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

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

[Chaosheng Qu]

From: Chaosheng Qu <quchaosheng000406@163.com>
Subject: [PATCH] tracing: don't reference jiffies from writeback TP_printk()
To: Steven Rostedt <rostedt@goodmis.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>,
    Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
    "Matthew Wilcox (Oracle)" <willy@infradead.org>,
    Jan Kara <jack@suse.cz>,
    linux-trace-kernel@vger.kernel.org,
    linux-kernel@vger.kernel.org

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@163.com>
---
 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

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

[Jan Kara]

On Mon 26-10-26 14:17:18, Chaosheng Qu wrote:
> From: Chaosheng Qu <quchaosheng000406@163.com>
> Subject: [PATCH] tracing: don't reference jiffies from writeback TP_printk()
> To: Steven Rostedt <rostedt@goodmis.org>
> Cc: Masami Hiramatsu <mhiramat@kernel.org>,
>     Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
>     "Matthew Wilcox (Oracle)" <willy@infradead.org>,
>     Jan Kara <jack@suse.cz>,
>     linux-trace-kernel@vger.kernel.org,
>     linux-kernel@vger.kernel.org
> 
> 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@163.com>

Looks good. Feel free to add:

Reviewed-by: Jan Kara <jack@suse.cz>

								Honza

> ---
>  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
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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@163.com> wrote:

> From: Chaosheng Qu <quchaosheng000406@163.com>
> Subject: [PATCH] tracing: don't reference jiffies from writeback TP_printk()
> To: Steven Rostedt <rostedt@goodmis.org>
> Cc: Masami Hiramatsu <mhiramat@kernel.org>,
>     Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
>     "Matthew Wilcox (Oracle)" <willy@infradead.org>,
>     Jan Kara <jack@suse.cz>,
>     linux-trace-kernel@vger.kernel.org,
>     linux-kernel@vger.kernel.org
> 
> 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@163.com>
> ---
>  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