jbd2: track request delay statistics

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>

diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index 3091d42992f0d934eb4355022efaa5c83ad1be0d..750c70148effad6151023e70e08a0e17f185d4e8 100644 (file)
--- 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 1a80e3146a59f0cba8435783b207a7aa16b96bae..4ba2e81e35ac8da784f7172612519a01bb6cb8af 100644 (file)
--- 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 df9f29760efa99931bef9fdd9609e7580d8852cd..735609e2d63697437d9624836e3c7fc2d348641c 100644 (file)
--- 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 e30b66346942a90a4c79cdc5a0362b3899db0521..e0aafc46064f17e0aca7e5da46aa147f2e149755 100644 (file)
--- a/include/linux/jbd2.h
+++ b/include/linux/jbd2.h
@@ -580,6 +580,11 @@ struct transaction_s
         */
        unsigned long           t_start;
 
+       /*
+        * When commit was requested
+        */
+       unsigned long           t_requested;
+
        /*
         * Checkpointing stats [j_checkpoint_sem]
         */
@@ -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 127993dbf322efa40bc68222551ff181132122b4..5419f57beb1f4e3b7465f111e40f1e6c0fe77c18 100644 (file)
--- 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),