Re: [PATCH 1/3] ring-buffer: Add uname to match criteria for persistent ring buffer

[Steven Rostedt <rostedt@goodmis.org>]

On Tue, 17 Dec 2024 09:46:30 -0800
Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Tue, 17 Dec 2024 at 09:34, Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > Add uname into the meta data and if the uname in the meta data from the
> > previous boot does not match the uname of the current boot, then clear the
> > buffer and re-initialize it.  
> 
> This seems broken.

BTW, this isn't the fix for the trace_check_vprintf(). That is here:

  https://lore.kernel.org/linux-trace-kernel/20241217024118.587584221@goodmis.org/

Where the I completely remove that function.

> 
> The problem is not that the previous boot data is wrong.
> 
> The problem is that you printed it *out* wrong by trying to interpret
> pointers in it.
> 
> Now you basically hide that, and make it harder to see any data from a
> bad kernel (since you presumably need to boot into a good kernel to do
> analysis).
> 
> The real fix seems to have been your 3/3, which still prints out the
> data, but stops trying to interpret the pointers in it.
> 
> Except you should also remove the last_text_delta / last_data_delta
> stuff. That's all about exactly that "trying to interpret bogus
> pointers". Instead you seem to have actually just *added* a case of
> that in your 3/3.

I'm not sure what you mean. If the kernels are the same, then the pointers
should also be the same, as KASLR just shifts them. This no longer uses
module code. It only traces core kernel code which should always have the
same offsets.

With the last_text_delta (and last_data_delta is always the same, but I
added it in the case that ever changes), the shifts have always been
accurate. For example, for RCU event strings.

With the pointer update to print_fields() I get:

           <...>-912     [001] d..1.   304.817710: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
           <...>-912     [001] d..1.   304.817713: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
          <idle>-0       [002] dN.1.   304.817769: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
          <idle>-0       [002] dN.1.   304.817772: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
           <...>-19      [002] d..1.   304.817805: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
           <...>-19      [002] d..1.   304.817806: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
          <idle>-0       [006] dN.1.   304.817819: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
          <idle>-0       [006] dN.1.   304.817821: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
           <...>-902     [006] d.h1.   304.817901: rcu_utilization: s=(0xffffffff9c488fdd:Start scheduler-tick)
           <...>-902     [006] d.h1.   304.817903: rcu_utilization: s=(0xffffffff9c426d45:End scheduler-tick)
          <idle>-0       [007] dN.1.   304.817913: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
          <idle>-0       [007] dN.1.   304.817915: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
           <...>-18      [007] d..1.   304.817931: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
           <...>-18      [007] d..1.   304.817931: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)
           <...>-902     [006] ..s1.   304.817941: rcu_utilization: s=(0xffffffff9c470f20:Start RCU core)
           <...>-902     [006] ..s1.   304.817958: rcu_utilization: s=(0xffffffff9c419bb8:End RCU core)
          <idle>-0       [002] dN.1.   304.818003: rcu_utilization: s=(0xffffffff9c4026b5:Start context switch)
          <idle>-0       [002] dN.1.   304.818003: rcu_utilization: s=(0xffffffff9c4ca779:End context switch)

Without that calculation, all I get is garbage and completely useless:

           <...>-903     [000] d..1.    24.712788: rcu_utilization: s=(0xffffffff970026af)
           <...>-903     [000] d..1.    24.712791: rcu_utilization: s=(0xffffffff970ca75b)
          <idle>-0       [004] dN.1.    24.712796: rcu_utilization: s=(0xffffffff970026af)
          <idle>-0       [004] dN.1.    24.712799: rcu_utilization: s=(0xffffffff970ca75b)
           <...>-19      [004] d..1.    24.712825: rcu_utilization: s=(0xffffffff970026af)
           <...>-19      [004] d..1.    24.712825: rcu_utilization: s=(0xffffffff970ca75b)
           <...>-18      [004] d..1.    24.712838: rcu_utilization: s=(0xffffffff970026af)
           <...>-18      [004] d..1.    24.712839: rcu_utilization: s=(0xffffffff970ca75b)
          <idle>-0       [005] dN.1.    24.712881: rcu_utilization: s=(0xffffffff970026af)
          <idle>-0       [005] dN.1.    24.712883: rcu_utilization: s=(0xffffffff970ca75b)
           <...>-893     [005] d.h1.    24.712911: rcu_utilization: s=(0xffffffff97088feb)
           <...>-893     [005] d.h1.    24.712912: rcu_utilization: s=(0xffffffff97026d3f)
           <...>-893     [005] ..s1.    24.712942: rcu_utilization: s=(0xffffffff97070f2e)
           <...>-893     [005] ..s1.    24.712944: rcu_utilization: s=(0xffffffff97019bb2)
           <...>-893     [005] dN.1.    24.713412: rcu_utilization: s=(0xffffffff970026af)
           <...>-893     [005] dN.1.    24.713412: rcu_utilization: s=(0xffffffff970ca75b)

The delta calculations are done by saving an address of a symbol into the
meta data, and when the meta data is considered a match, it calculates the
delta between what was saved in the meta data to the same symbol in the
current kernel.

This works across several reboots too. That is, I can save the boot mapped
data, reboot several times, and still see the correct data in the ring
buffer, as the delta is calculated at each boot. It's only saved when
tracing starts and the ring buffer is re-initialized.

So what exactly are you saying is broken?

-- Steve