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>

1 files changed, 6 insertions, 2 deletions

diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h
index 127993dbf322..5419f57beb1f 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),