On Wed, 16 Apr 2025 19:47:14 +0200
Borislav Petkov <[email protected]> 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
