@@ -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;
+ s64 start_us = ktime_to_us(ktime_get());
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,
+ ktime_to_us(ktime_get()) - start_us);
}
/*
@@ -401,6 +401,27 @@ TRACE_EVENT(jbd2_wait_on_shadow,
__entry->wait_us)
);
+TRACE_EVENT(jbd2_wait_on_transaction_locked,
+
+ TP_PROTO(dev_t dev, unsigned long wait_us),
+
+ TP_ARGS(dev, wait_us),
+
+ TP_STRUCT__entry(
+ __field( dev_t, dev )
+ __field(unsigned long, wait_us )
+ ),
+
+ TP_fast_assign(
+ __entry->dev = dev;
+ __entry->wait_us = wait_us;
+ ),
+
+ TP_printk("dev %d,%d latency(us) %lu",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ __entry->wait_us)
+);
+
#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-1793 [009] .... 519.967867: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 73442 fsstress-1788 [002] .... 519.967877: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 75189 fsstress-1792 [012] .... 519.967882: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 148260 fsstress-1786 [011] .... 519.967885: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 143292 fsstress-1796 [004] .... 519.967889: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 147945 fsstress-1791 [015] .... 519.967892: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 148126 fsstress-1794 [009] .... 519.967938: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 148347 fsstress-1787 [003] .... 519.967990: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 148152 fsstress-1795 [004] .... 519.967999: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 141676 fsstress-1800 [000] .... 519.968001: jbd2_wait_on_transaction_locked: dev 254,17 latency(us) 148141 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(+)