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/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 @@
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_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_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 @@
__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 @@
__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 @@
__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),