On Mon 26-10-26 14:17:18, Chaosheng Qu 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]>
Looks good. Feel free to add: Reviewed-by: Jan Kara <[email protected]> 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 <[email protected]> SUSE Labs, CR
