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>

3 files changed, 18 insertions, 3 deletions

diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index 3091d42992f0..750c70148eff 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 1a80e3146a59..4ba2e81e35ac 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 df9f29760efa..735609e2d636 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;
 }