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@xxxxxxxxxxxxxxxxx>
---
fs/jbd2/transaction.c | 3 +++
include/trace/events/jbd2.h | 21 +++++++++++++++++++++
2 files changed, 24 insertions(+)
diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index 5d7a96e10133..6757911a4a17 100644
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -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);
}
/*
diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h
index e42072c74ce9..f2eebd839bf2 100644
--- a/include/trace/events/jbd2.h
+++ b/include/trace/events/jbd2.h
@@ -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 */
--
2.17.2
