Re: possible trace_printk() bug in v5.19-rc1

[Chuck Lever III <chuck.lever@oracle.com>]

> On Jun 24, 2022, at 7:08 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Mon, 20 Jun 2022 00:57:23 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>>> Yes, I'm sure. I just checked out v5.18 and built it with the
>>> same CONFIG. trace_printk() on that kernel generates function
>>> names as expected.  
>> 
>> I moved my development work to another system, and bisected. The
>> result:
>> 
>> 91fb02f31505 ("module: Move kallsyms support into a separate file")
> 
> Hmm, right below that it says:
> 
>   "No functional change."
> 
> I'm guessing it may not be as reliably reproducible.

So far I've seen this misbehavior 100% of the time on two different
systems running 5.19-rc. But, I agree, it's not known how broadly
reproducible this is on the cohort of systems now running 5.19-rc.


> And is this an issue with trace-cmd output or reading the trace file?

The trace_printk() call site in nfsd_file_slab_free() shows up like
this via "trace-cmd show -p":

     ksoftirqd/2-28      [002] ..s..    61.849252: nfsd_file_slab_free: nf=0000000007b6d60b
     ksoftirqd/2-28      [002] ..s..    61.849257: nfsd_file_slab_free: nf=000000004bf47e99
          <idle>-0       [005] ..s1.    61.853212: nfsd_file_slab_free: nf=0000000029187f87
          <idle>-0       [005] ..s1.    61.853223: nfsd_file_slab_free: nf=000000003cd1db63

So, it looks like the misbehavior appears only with "trace-cmd report".

[root@manet ~]# cat /etc/redhat-release 
Fedora release 35 (Thirty Five)
[root@manet ~]# trace-cmd version

trace-cmd version 2.9.2 (not-a-git-repo)

usage:
  trace-cmd [COMMAND] ...

  commands:
     record - record a trace into a trace.dat file
     set - set a ftrace configuration parameter

 ...

     check-events - parse trace event formats
     dump - read out the meta data from a trace file

[root@manet ~]# 

--
Chuck Lever