Re: [PATCH] x86/tracing: introduce enter/exit tracepoint pairs for page faults

[Steven Rostedt <rostedt@goodmis.org>]

On Wed, 16 Apr 2025 19:47:14 +0200
Borislav Petkov <bp@alien8.de> wrote:

> On Mon, Apr 14, 2025 at 06:20:50PM -0400, Steven Rostedt wrote:
> > It's useful for me ;-)  
> 
> That's why I CCed you.
> 
> I suspected you'd have "your mustard to share". :-P

:-)

> 
> >  # cd /sys/kernel/tracing
> >  # echo 's:user_faults u64 delta;' >> dynamic_events
> >  # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs' >> events/exceptions/page_fault_user_enter/trigger
> >  # echo 'hist:keys=common_pid:delta=common_timestamp.usecs-$ts0:onmatch(exceptions.page_fault_user_enter).trace(user_faults,$delta)' >> events/exceptions/page_fault_user_exit/trigger
> > 
> >  # cd /work/git/trace-cmd.git
> >  # echo 'hist:keys=delta.log2:sort=delta if COMM == "cc1"' > /sys/kernel/tracing/events/synthetic/user_faults/trigger  
> 
> OMG, this tracing thing has turned into a language almost. I hope you're
> documenting those fancy use cases...

The above was created by:

 # trace-cmd sqlhist -e -n user_faults SELECT TIMESTAMP_DELTA_USECS as delta FROM page_fault_user_enter as start JOIN \
     page_fault_user_exit as end ON start.common_pid = end.common_pid

It also shows the kernel commands, which I took and sanitized a bit.

;-)

> 
> >  # make
> > [..]
> > 
> >  # cat /sys/kernel/tracing/events/synthetic/user_faults/hist
> > # event histogram
> > #
> > # trigger info: hist:keys=delta.log2:vals=hitcount:sort=delta.log2:size=2048 if COMM == "cc1" [active]
> > #
> > 
> > { delta: ~ 2^0  } hitcount:          1
> > { delta: ~ 2^1  } hitcount:        334
> > { delta: ~ 2^2  } hitcount:       4090
> > { delta: ~ 2^3  } hitcount:      86037
> > { delta: ~ 2^4  } hitcount:     108790
> > { delta: ~ 2^5  } hitcount:      27387
> > { delta: ~ 2^6  } hitcount:       6015
> > { delta: ~ 2^7  } hitcount:        481
> > { delta: ~ 2^8  } hitcount:        134
> > { delta: ~ 2^9  } hitcount:         74
> > { delta: ~ 2^10 } hitcount:         54
> > { delta: ~ 2^11 } hitcount:          6
> > 
> > Totals:
> >     Hits: 233403
> >     Entries: 12
> >     Dropped: 0
> > 
> > 
> > The above shows a histogram in microseconds where the buckets increase in a
> > power of two. The biggest bucket is between 2^4 (16) and 2^5 (32) microseconds
> > with 108790 hits.
> > 
> > The longest bucket of 2^11 (2ms) to 2^12 (4ms) had 6 hits.
> > 
> > And when sframes is supported, it will be able to show the user space stack
> > trace of where the longest page faults occur.  
> 
> Ok, so AFAIU, this gives you how long user page faults take and apparently for
> someone this is important info.

This was just a simple example. I rather see where in the kernel it happens.
I can still use the synthetic events and user stack trace to find where the
big faults occur.

> 
> Now if only that info were in the commit message along with the usage scenario
> so that people can *actually* do what you guys are bragging about...

I plan on adding things like this to Documentation/trace/debugging.rst

I need to get time out to add a bunch of helpful tricks there.

-- Steve