Re: [PATCH] tracing: Fix printing ptrs in preempt/irq enable/disable events

[Joel Fernandes]

On Thu, Dec 19, 2019 at 06:45:25PM +0000, Valentin Schneider wrote:
> On 07/12/2019 00:00, Antonio Borneo wrote:
> > At login:
> > trace-cmd record -e preemptirq:irq_enable sleep 1
> > trace-cmd report trace.dat | head
> > and I incorrectly get only the offsets to _stext:
> > cpus=1
> >            sleep-197   [000]   280.378022: irq_enable:           caller=0x1afaS parent=0xc00091S
> >            sleep-197   [000]   280.378026: irq_enable:           caller=0x54d34S parent=0x78e00000S
> >            sleep-197   [000]   280.378029: irq_enable:           caller=0x1afaS parent=0xc00a84S
> >            sleep-197   [000]   280.378032: irq_enable:           caller=0x263dS parent=0x78e00000S
> > ...
> > 
> > With this patch I get the expected/right result:
> > cpus=1
> >            sleep-210   [000]   525.177583: irq_enable:           caller=trace_hardirqs_on_thunk parent=entry_SYSCALL_64_after_hwframe
> >            sleep-210   [000]   525.177587: irq_enable:           caller=__do_page_fault parent=(nil)S
> >            sleep-210   [000]   525.177590: irq_enable:           caller=trace_hardirqs_on_thunk parent=swapgs_restore_regs_and_return_to_usermode
> >            sleep-210   [000]   525.177593: irq_enable:           caller=do_syscall_64 parent=(nil)S
> > ...
> 
> FWIW Ambroise (in Cc) and I were staring at some irq enable/disable traces,
> and encountered exactly this on a Pixel3 running a mainline kernel. With
> Antonio's patch we got the expected result, so you can have:
> 
> Tested-by: Valentin Schneider <valentin.schneider@xxxxxxx>

In BCC, we use the binary trace record of this tracepoint and don't interpret
the text output.  There we lookup _stext value (I believe from kallsyms) and
then apply the offset to that and do another look up for the final symbol.

Would it be possible for Ambroise to work more on this patch so that the
trace record size is not doubled?

> >> I am not comfortable with this patch at the moment, mainly because it will
> >> increase the size of this rather high frequency event. But I'm not saying
> >> there isn't an issue on 32-bit. Let's discuss more.
> >>
> > 
> > Sure, the pressure on the trace buffer will increase on a 64 bit system, but in general it also has more memory than an embedded 32 bit system.
> > The key point is, instead, can we feel safe with a 32 bit offset in a 64 bit system? Is there any guarantee a module is loaded within 32 bits offset from _stext?
> > 
> 
> You're better placed than I to know if and when this is the case, but I
> wouldn't use this in a production environment. To me this is more of a
> debugging tool (and a really good one at that), so I am less concerned
> about the memory overhead.

The issue is with poor trace buffer utilization, you could overflow the trace
buffer more easily, and lose trace data. The reason I came up with the stext
delta approach was precisely to address this and it worked when I was using
this tracepoint. Let me find some time this evening to work more on
Ambroise's patch.

thanks,

 - Joel