[PATCH] tracing: don't reference jiffies from writeback TP_printk()

[Chaosheng Qu]

From: Chaosheng Qu <quchaosheng000406@xxxxxxx>
Subject: [PATCH] tracing: don't reference jiffies from writeback TP_printk()
To: Steven Rostedt <rostedt@xxxxxxxxxxx>
Cc: Masami Hiramatsu <mhiramat@xxxxxxxxxx>,
    Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx>,
    "Matthew Wilcox (Oracle)" <willy@xxxxxxxxxxxxx>,
    Jan Kara <jack@xxxxxxx>,
    linux-trace-kernel@xxxxxxxxxxxxxxx,
    linux-kernel@xxxxxxxxxxxxxxx

writeback_sb_inodes_requeue and writeback_single_inode_start/() compute
the inode age with:

	(jiffies - __entry->dirtied_when) / HZ

inside TP_printk().  TP_printk() is not part of the recorded event: it
runs when the trace is read back, so the expression is evaluated at
formatter time, not at the time the event was recorded.  The formatted
output therefore reports the interval between recording and reading,
not the age of the inode when it was traced.

It is also evaluated outside of the kernel: tracefs renders the format
string once and userspace re-evaluates it.  A tool that has to resolve
every symbol in the expression (trace-cmd and the parser in LISA both
do) resolves the bare "jiffies" to its address, so the printed age
becomes ((unsigned long)&jiffies - dirtied_when) / HZ, which is
nonsense.  This was reported as a wrong "age" value in trace-cmd
output:

  https://bugzilla.kernel.org/show_bug.cgi?id=219839

Nothing in TP_printk() may depend on the state of the machine at read
time, which is the same rule that keeps ktime_get() and friends out of
it.  writeback_queue_io already does the right thing and stores the age
in TP_fast_assign(); make these two events do that as well.

The new __entry->age field is appended after the existing fields, so
no existing field changes offset and trace consumers that index the
event by offset keep working.  The "age=%lu" placeholder keeps its
position in the output text.

Link: https://bugzilla.kernel.org/show_bug.cgi?id=219839
Signed-off-by: Chaosheng Qu <quchaosheng000406@xxxxxxx>
---
 include/trace/events/writeback.h | 12 ++++++++----
 1 file changed, 8 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/writeback.h b/include/trace/events/writeback.h
index 13ee076..23d107c 100644
--- a/include/trace/events/writeback.h
+++ b/include/trace/events/writeback.h
@@ -745,6 +745,7 @@ TRACE_EVENT(writeback_sb_inodes_requeue,
 		__field(u64, cgroup_ino)
 		__field(unsigned long, state)
 		__field(unsigned long, dirtied_when)
+		__field(unsigned long, age)
 	),
 
 	TP_fast_assign(
@@ -753,6 +754,7 @@ TRACE_EVENT(writeback_sb_inodes_requeue,
 		__entry->ino		= inode->i_ino;
 		__entry->state		= inode_state_read_once(inode);
 		__entry->dirtied_when	= inode->dirtied_when;
+		__entry->age		= (jiffies - __entry->dirtied_when) / HZ;
 		__entry->cgroup_ino	= __trace_wb_assign_cgroup(inode_to_wb(inode));
 	),
 
@@ -761,7 +763,7 @@ TRACE_EVENT(writeback_sb_inodes_requeue,
 		  __entry->ino,
 		  show_inode_state(__entry->state),
 		  __entry->dirtied_when,
-		  (jiffies - __entry->dirtied_when) / HZ,
+		  __entry->age,
 		  __entry->cgroup_ino
 	)
 );
@@ -784,6 +786,7 @@ DECLARE_EVENT_CLASS(writeback_single_inode_template,
 		__field(unsigned long, writeback_index)
 		__field(unsigned long, wrote)
 		__field(long, nr_to_write)
+		__field(unsigned long, age)
 	),
 
 	TP_fast_assign(
@@ -795,6 +798,7 @@ DECLARE_EVENT_CLASS(writeback_single_inode_template,
 		__entry->writeback_index = inode->i_mapping->writeback_index;
 		__entry->nr_to_write	= nr_to_write;
 		__entry->wrote		= nr_to_write - wbc->nr_to_write;
+		__entry->age		= (jiffies - __entry->dirtied_when) / HZ;
 		__entry->cgroup_ino	= __trace_wbc_assign_cgroup(wbc);
 	),
 
@@ -804,7 +808,7 @@ DECLARE_EVENT_CLASS(writeback_single_inode_template,
 		  __entry->ino,
 		  show_inode_state(__entry->state),
 		  __entry->dirtied_when,
-		  (jiffies - __entry->dirtied_when) / HZ,
+		  __entry->age,
 		  __entry->writeback_index,
 		  __entry->nr_to_write,
 		  __entry->wrote,
-- 
2.43.0