@@ -148,6 +148,7 @@ static void wait_transaction_locked(journal_t *journal)
DEFINE_WAIT(wait);
int need_to_start;
tid_t tid = journal->j_running_transaction->t_tid;
+ unsigned long start = jiffies;
prepare_to_wait(&journal->j_wait_transaction_locked, &wait,
TASK_UNINTERRUPTIBLE);
@@ -158,6 +159,8 @@ static void wait_transaction_locked(journal_t *journal)
jbd2_might_wait_for_commit(journal);
schedule();
finish_wait(&journal->j_wait_transaction_locked, &wait);
+ trace_jbd2_wait_on_transaction_locked(journal->j_fs_dev->bd_dev,
+ jiffies_to_msecs(jiffies - start));
}
/*
@@ -401,6 +401,27 @@ TRACE_EVENT(jbd2_sleep_on_shadow,
__entry->stall_ms)
);
+TRACE_EVENT(jbd2_wait_on_transaction_locked,
+
+ TP_PROTO(dev_t dev, unsigned long stall_ms),
+
+ TP_ARGS(dev, stall_ms),
+
+ TP_STRUCT__entry(
+ __field( dev_t, dev )
+ __field(unsigned long, stall_ms )
+ ),
+
+ TP_fast_assign(
+ __entry->dev = dev;
+ __entry->stall_ms = stall_ms;
+ ),
+
+ TP_printk("dev %d,%d wait %lu",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ __entry->stall_ms)
+);
+
#endif /* _TRACE_JBD2_H */
/* This part must be outside protection */
Sometimes process will be stalled in wait_transaction_locked() for a while, also add a new tracepoint to track this delay. Trace info likes below: fsstress-1672 [009] .... 184.663043: jbd2_wait_on_transaction_locked: dev 254,17 wait 0 fsstress-1674 [002] .... 184.771556: jbd2_wait_on_transaction_locked: dev 254,17 wait 42 fsstress-1676 [005] .... 184.771562: jbd2_wait_on_transaction_locked: dev 254,17 wait 100 fsstress-1677 [003] .... 184.771567: jbd2_wait_on_transaction_locked: dev 254,17 wait 102 kworker/13:1-160 [013] .... 184.771619: jbd2_wait_on_transaction_locked: dev 254,17 wait 102 fsstress-1673 [003] .... 184.771675: jbd2_wait_on_transaction_locked: dev 254,17 wait 95 Signed-off-by: Xiaoguang Wang <xiaoguang.wang@linux.alibaba.com> --- fs/jbd2/transaction.c | 3 +++ include/trace/events/jbd2.h | 21 +++++++++++++++++++++ 2 files changed, 24 insertions(+)