[PATCH] tracing: record jiffies in writeback events instead of computing age

[Chaosheng Qu]

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.

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.

v1 stored the age itself in TP_fast_assign().  Steve pointed out that
the division then runs on the trace path, which is where the side
effects have to stay small, and that recording the jiffies snapshot
instead lets userspace compute whatever it wants from the raw value.
Do that: save jiffies in TP_fast_assign() and keep the subtraction and
the division in TP_printk(), where they run on the slow path.  This
follows the same shape as xprtrdma_req's connect/reconnect fields.

The new __entry->jiffies 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, and the value it prints is unchanged.

Suggested-by: Steven Rostedt <rostedt@xxxxxxxxxxx>
Link: https://bugzilla.kernel.org/show_bug.cgi?id=219839
Reviewed-by: Jan Kara <jack@xxxxxxx>
Signed-off-by: Chaosheng Qu <quchaosheng000406@xxxxxxx>
---
 include/trace/events/writeback.h | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/writeback.h b/include/trace/events/writeback.h
index 13ee076cc..b7dfc9f7b 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, jiffies)
 	),
 
 	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->jiffies	= jiffies;
 		__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->jiffies - __entry->dirtied_when) / HZ,
 		  __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, jiffies)
 	),
 
 	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->jiffies	= jiffies;
 		__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->jiffies - __entry->dirtied_when) / HZ,
 		  __entry->writeback_index,
 		  __entry->nr_to_write,
 		  __entry->wrote,
-- 
2.43.0