Patchwork [01/12] jbd2: track request delay statistics

login
register
mail settings
Submitter Theodore Ts'o
Date Feb. 9, 2013, 9:53 p.m.
Message ID <1360446832-12724-2-git-send-email-tytso@mit.edu>
Download mbox | patch
Permalink /patch/219458/
State Accepted
Headers show

Comments

Theodore Ts'o - Feb. 9, 2013, 9:53 p.m.
Track the delay between when we first request that the commit begin
and when it actually begins, so we can see how much of a gap exists.
In theory, this should just be the remaining scheduling quantuum of
the thread which requested the commit (assuming it was not a
synchronous operation which triggered the commit request) plus
scheduling overhead; however, it's possible that real time processes
might get in the way of letting the kjournald thread from executing.

Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
---
 fs/jbd2/commit.c            |  8 ++++++++
 fs/jbd2/journal.c           | 12 +++++++++---
 fs/jbd2/transaction.c       |  1 +
 include/linux/jbd2.h        |  7 +++++++
 include/trace/events/jbd2.h |  8 ++++++--
 5 files changed, 31 insertions(+), 5 deletions(-)
Jan Kara - Feb. 11, 2013, 3:57 p.m.
On Sat 09-02-13 16:53:41, Ted Tso wrote:
> Track the delay between when we first request that the commit begin
> and when it actually begins, so we can see how much of a gap exists.
> In theory, this should just be the remaining scheduling quantuum of
> the thread which requested the commit (assuming it was not a
> synchronous operation which triggered the commit request) plus
> scheduling overhead; however, it's possible that real time processes
> might get in the way of letting the kjournald thread from executing.
  Looks good. I just wonder whether jiffies really have enough precision to
get you meaningful numbers. Did you try that?

								Honza
> 
> Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
> ---
>  fs/jbd2/commit.c            |  8 ++++++++
>  fs/jbd2/journal.c           | 12 +++++++++---
>  fs/jbd2/transaction.c       |  1 +
>  include/linux/jbd2.h        |  7 +++++++
>  include/trace/events/jbd2.h |  8 ++++++--
>  5 files changed, 31 insertions(+), 5 deletions(-)
> 
> diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
> index 3091d42..750c701 100644
> --- a/fs/jbd2/commit.c
> +++ b/fs/jbd2/commit.c
> @@ -435,7 +435,12 @@ void jbd2_journal_commit_transaction(journal_t *journal)
>  
>  	trace_jbd2_commit_locking(journal, commit_transaction);
>  	stats.run.rs_wait = commit_transaction->t_max_wait;
> +	stats.run.rs_request_delay = 0;
>  	stats.run.rs_locked = jiffies;
> +	if (commit_transaction->t_requested)
> +		stats.run.rs_request_delay =
> +			jbd2_time_diff(commit_transaction->t_requested,
> +				       stats.run.rs_locked);
>  	stats.run.rs_running = jbd2_time_diff(commit_transaction->t_start,
>  					      stats.run.rs_locked);
>  
> @@ -1116,7 +1121,10 @@ restart_loop:
>  	 */
>  	spin_lock(&journal->j_history_lock);
>  	journal->j_stats.ts_tid++;
> +	if (commit_transaction->t_requested)
> +		journal->j_stats.ts_requested++;
>  	journal->j_stats.run.rs_wait += stats.run.rs_wait;
> +	journal->j_stats.run.rs_request_delay += stats.run.rs_request_delay;
>  	journal->j_stats.run.rs_running += stats.run.rs_running;
>  	journal->j_stats.run.rs_locked += stats.run.rs_locked;
>  	journal->j_stats.run.rs_flushing += stats.run.rs_flushing;
> diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
> index 1a80e31..4ba2e81 100644
> --- a/fs/jbd2/journal.c
> +++ b/fs/jbd2/journal.c
> @@ -533,6 +533,7 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
>  		jbd_debug(1, "JBD2: requesting commit %d/%d\n",
>  			  journal->j_commit_request,
>  			  journal->j_commit_sequence);
> +		journal->j_running_transaction->t_requested = jiffies;
>  		wake_up(&journal->j_wait_commit);
>  		return 1;
>  	} else if (!tid_geq(journal->j_commit_request, target))
> @@ -898,13 +899,18 @@ static int jbd2_seq_info_show(struct seq_file *seq, void *v)
>  
>  	if (v != SEQ_START_TOKEN)
>  		return 0;
> -	seq_printf(seq, "%lu transaction, each up to %u blocks\n",
> -			s->stats->ts_tid,
> -			s->journal->j_max_transaction_buffers);
> +	seq_printf(seq, "%lu transactions (%lu requested), "
> +		   "each up to %u blocks\n",
> +		   s->stats->ts_tid, s->stats->ts_requested,
> +		   s->journal->j_max_transaction_buffers);
>  	if (s->stats->ts_tid == 0)
>  		return 0;
>  	seq_printf(seq, "average: \n  %ums waiting for transaction\n",
>  	    jiffies_to_msecs(s->stats->run.rs_wait / s->stats->ts_tid));
> +	seq_printf(seq, "  %ums request delay\n",
> +	    (s->stats->ts_requested == 0) ? 0 :
> +	    jiffies_to_msecs(s->stats->run.rs_request_delay /
> +			     s->stats->ts_requested));
>  	seq_printf(seq, "  %ums running transaction\n",
>  	    jiffies_to_msecs(s->stats->run.rs_running / s->stats->ts_tid));
>  	seq_printf(seq, "  %ums transaction was being locked\n",
> diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
> index df9f297..735609e 100644
> --- a/fs/jbd2/transaction.c
> +++ b/fs/jbd2/transaction.c
> @@ -100,6 +100,7 @@ jbd2_get_transaction(journal_t *journal, transaction_t *transaction)
>  	journal->j_running_transaction = transaction;
>  	transaction->t_max_wait = 0;
>  	transaction->t_start = jiffies;
> +	transaction->t_requested = 0;
>  
>  	return transaction;
>  }
> diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h
> index e30b663..e0aafc4 100644
> --- a/include/linux/jbd2.h
> +++ b/include/linux/jbd2.h
> @@ -581,6 +581,11 @@ struct transaction_s
>  	unsigned long		t_start;
>  
>  	/*
> +	 * When commit was requested
> +	 */
> +	unsigned long		t_requested;
> +
> +	/*
>  	 * Checkpointing stats [j_checkpoint_sem]
>  	 */
>  	struct transaction_chp_stats_s t_chp_stats;
> @@ -637,6 +642,7 @@ struct transaction_s
>  
>  struct transaction_run_stats_s {
>  	unsigned long		rs_wait;
> +	unsigned long		rs_request_delay;
>  	unsigned long		rs_running;
>  	unsigned long		rs_locked;
>  	unsigned long		rs_flushing;
> @@ -649,6 +655,7 @@ struct transaction_run_stats_s {
>  
>  struct transaction_stats_s {
>  	unsigned long		ts_tid;
> +	unsigned long		ts_requested;
>  	struct transaction_run_stats_s run;
>  };
>  
> diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h
> index 127993d..5419f57 100644
> --- a/include/trace/events/jbd2.h
> +++ b/include/trace/events/jbd2.h
> @@ -142,6 +142,7 @@ TRACE_EVENT(jbd2_run_stats,
>  		__field(		dev_t,	dev		)
>  		__field(	unsigned long,	tid		)
>  		__field(	unsigned long,	wait		)
> +		__field(	unsigned long,	request_delay	)
>  		__field(	unsigned long,	running		)
>  		__field(	unsigned long,	locked		)
>  		__field(	unsigned long,	flushing	)
> @@ -155,6 +156,7 @@ TRACE_EVENT(jbd2_run_stats,
>  		__entry->dev		= dev;
>  		__entry->tid		= tid;
>  		__entry->wait		= stats->rs_wait;
> +		__entry->request_delay	= stats->rs_request_delay;
>  		__entry->running	= stats->rs_running;
>  		__entry->locked		= stats->rs_locked;
>  		__entry->flushing	= stats->rs_flushing;
> @@ -164,10 +166,12 @@ TRACE_EVENT(jbd2_run_stats,
>  		__entry->blocks_logged	= stats->rs_blocks_logged;
>  	),
>  
> -	TP_printk("dev %d,%d tid %lu wait %u running %u locked %u flushing %u "
> -		  "logging %u handle_count %u blocks %u blocks_logged %u",
> +	TP_printk("dev %d,%d tid %lu wait %u request_delay %u running %u "
> +		  "locked %u flushing %u logging %u handle_count %u "
> +		  "blocks %u blocks_logged %u",
>  		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
>  		  jiffies_to_msecs(__entry->wait),
> +		  jiffies_to_msecs(__entry->request_delay),
>  		  jiffies_to_msecs(__entry->running),
>  		  jiffies_to_msecs(__entry->locked),
>  		  jiffies_to_msecs(__entry->flushing),
> -- 
> 1.7.12.rc0.22.gcdd159b
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Patch

diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index 3091d42..750c701 100644
--- a/fs/jbd2/commit.c
+++ b/fs/jbd2/commit.c
@@ -435,7 +435,12 @@  void jbd2_journal_commit_transaction(journal_t *journal)
 
 	trace_jbd2_commit_locking(journal, commit_transaction);
 	stats.run.rs_wait = commit_transaction->t_max_wait;
+	stats.run.rs_request_delay = 0;
 	stats.run.rs_locked = jiffies;
+	if (commit_transaction->t_requested)
+		stats.run.rs_request_delay =
+			jbd2_time_diff(commit_transaction->t_requested,
+				       stats.run.rs_locked);
 	stats.run.rs_running = jbd2_time_diff(commit_transaction->t_start,
 					      stats.run.rs_locked);
 
@@ -1116,7 +1121,10 @@  restart_loop:
 	 */
 	spin_lock(&journal->j_history_lock);
 	journal->j_stats.ts_tid++;
+	if (commit_transaction->t_requested)
+		journal->j_stats.ts_requested++;
 	journal->j_stats.run.rs_wait += stats.run.rs_wait;
+	journal->j_stats.run.rs_request_delay += stats.run.rs_request_delay;
 	journal->j_stats.run.rs_running += stats.run.rs_running;
 	journal->j_stats.run.rs_locked += stats.run.rs_locked;
 	journal->j_stats.run.rs_flushing += stats.run.rs_flushing;
diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index 1a80e31..4ba2e81 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -533,6 +533,7 @@  int __jbd2_log_start_commit(journal_t *journal, tid_t target)
 		jbd_debug(1, "JBD2: requesting commit %d/%d\n",
 			  journal->j_commit_request,
 			  journal->j_commit_sequence);
+		journal->j_running_transaction->t_requested = jiffies;
 		wake_up(&journal->j_wait_commit);
 		return 1;
 	} else if (!tid_geq(journal->j_commit_request, target))
@@ -898,13 +899,18 @@  static int jbd2_seq_info_show(struct seq_file *seq, void *v)
 
 	if (v != SEQ_START_TOKEN)
 		return 0;
-	seq_printf(seq, "%lu transaction, each up to %u blocks\n",
-			s->stats->ts_tid,
-			s->journal->j_max_transaction_buffers);
+	seq_printf(seq, "%lu transactions (%lu requested), "
+		   "each up to %u blocks\n",
+		   s->stats->ts_tid, s->stats->ts_requested,
+		   s->journal->j_max_transaction_buffers);
 	if (s->stats->ts_tid == 0)
 		return 0;
 	seq_printf(seq, "average: \n  %ums waiting for transaction\n",
 	    jiffies_to_msecs(s->stats->run.rs_wait / s->stats->ts_tid));
+	seq_printf(seq, "  %ums request delay\n",
+	    (s->stats->ts_requested == 0) ? 0 :
+	    jiffies_to_msecs(s->stats->run.rs_request_delay /
+			     s->stats->ts_requested));
 	seq_printf(seq, "  %ums running transaction\n",
 	    jiffies_to_msecs(s->stats->run.rs_running / s->stats->ts_tid));
 	seq_printf(seq, "  %ums transaction was being locked\n",
diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index df9f297..735609e 100644
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -100,6 +100,7 @@  jbd2_get_transaction(journal_t *journal, transaction_t *transaction)
 	journal->j_running_transaction = transaction;
 	transaction->t_max_wait = 0;
 	transaction->t_start = jiffies;
+	transaction->t_requested = 0;
 
 	return transaction;
 }
diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h
index e30b663..e0aafc4 100644
--- a/include/linux/jbd2.h
+++ b/include/linux/jbd2.h
@@ -581,6 +581,11 @@  struct transaction_s
 	unsigned long		t_start;
 
 	/*
+	 * When commit was requested
+	 */
+	unsigned long		t_requested;
+
+	/*
 	 * Checkpointing stats [j_checkpoint_sem]
 	 */
 	struct transaction_chp_stats_s t_chp_stats;
@@ -637,6 +642,7 @@  struct transaction_s
 
 struct transaction_run_stats_s {
 	unsigned long		rs_wait;
+	unsigned long		rs_request_delay;
 	unsigned long		rs_running;
 	unsigned long		rs_locked;
 	unsigned long		rs_flushing;
@@ -649,6 +655,7 @@  struct transaction_run_stats_s {
 
 struct transaction_stats_s {
 	unsigned long		ts_tid;
+	unsigned long		ts_requested;
 	struct transaction_run_stats_s run;
 };
 
diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h
index 127993d..5419f57 100644
--- a/include/trace/events/jbd2.h
+++ b/include/trace/events/jbd2.h
@@ -142,6 +142,7 @@  TRACE_EVENT(jbd2_run_stats,
 		__field(		dev_t,	dev		)
 		__field(	unsigned long,	tid		)
 		__field(	unsigned long,	wait		)
+		__field(	unsigned long,	request_delay	)
 		__field(	unsigned long,	running		)
 		__field(	unsigned long,	locked		)
 		__field(	unsigned long,	flushing	)
@@ -155,6 +156,7 @@  TRACE_EVENT(jbd2_run_stats,
 		__entry->dev		= dev;
 		__entry->tid		= tid;
 		__entry->wait		= stats->rs_wait;
+		__entry->request_delay	= stats->rs_request_delay;
 		__entry->running	= stats->rs_running;
 		__entry->locked		= stats->rs_locked;
 		__entry->flushing	= stats->rs_flushing;
@@ -164,10 +166,12 @@  TRACE_EVENT(jbd2_run_stats,
 		__entry->blocks_logged	= stats->rs_blocks_logged;
 	),
 
-	TP_printk("dev %d,%d tid %lu wait %u running %u locked %u flushing %u "
-		  "logging %u handle_count %u blocks %u blocks_logged %u",
+	TP_printk("dev %d,%d tid %lu wait %u request_delay %u running %u "
+		  "locked %u flushing %u logging %u handle_count %u "
+		  "blocks %u blocks_logged %u",
 		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
 		  jiffies_to_msecs(__entry->wait),
+		  jiffies_to_msecs(__entry->request_delay),
 		  jiffies_to_msecs(__entry->running),
 		  jiffies_to_msecs(__entry->locked),
 		  jiffies_to_msecs(__entry->flushing),