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

[Steven Rostedt]

On Mon, 26 Oct 2026 14:17:18 +0800
Chaosheng Qu <quchaosheng000406@xxxxxxx> wrote:

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

Actually can we just record jiffies here?

>  	),
>  
>  	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;

Divisions are expensive and this is executed during the trace where we
try to keep the trace side effects as small as possible.


>  		__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,

By saving jiffies, this would be:

		  (__entry->jiffies - __entry->dirtied_when) / HZ

Where it would be processed at the time of read (aka "slow path").

As jiffies would be saved in the event, user space would also be able
to calculate this.

-- Steve


>  		  __entry->cgroup_ino