On Mon, 26 Oct 2026 14:17:18 +0800 Chaosheng Qu <[email protected]> wrote:
> From: Chaosheng Qu <[email protected]> > Subject: [PATCH] tracing: don't reference jiffies from writeback TP_printk() > To: Steven Rostedt <[email protected]> > Cc: Masami Hiramatsu <[email protected]>, > Mathieu Desnoyers <[email protected]>, > "Matthew Wilcox (Oracle)" <[email protected]>, > Jan Kara <[email protected]>, > [email protected], > [email protected] > > 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 <[email protected]> > --- > 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
