Received-SPF: pass (google.com: best guess record for domain of linux-ext4-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Xiaoguang Wang <xiaoguang.wang@linux.alibaba.com>
To:     linux-ext4@vger.kernel.org
Cc:     Xiaoguang Wang <xiaoguang.wang@linux.alibaba.com>
Subject: [PATCH 2/3] jbd2: add new tracepoint jbd2_wait_on_transaction_locked
Date:   Tue, 24 Sep 2019 13:13:49 +0800
Message-Id: <20190924051350.1740-2-xiaoguang.wang@linux.alibaba.com>
In-Reply-To: <20190924051350.1740-1-xiaoguang.wang@linux.alibaba.com>
References: <20190924051350.1740-1-xiaoguang.wang@linux.alibaba.com>
Sender: linux-ext4-owner@vger.kernel.org
Precedence: bulk

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(+)

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