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

Looks good. Feel free to add:

Reviewed-by: Jan Kara <jack@xxxxxxx>

								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@xxxxxxxx>
SUSE Labs, CR