On Mon, 9 Oct 2023 23:37:14 +0800
Jinyu Tang <tangji...@tinylab.org> wrote:
> When we want to know what happened in kernel when our app
> has more latency than we hope, but the larger latency of
> our app may be lower than other process in the syetem.
> We feel sad after waiting a long time but only get other
> process sched_wakeup trace.
>
> This Patch can let us only trace target process sched-wakeup
> time, other process sched-wakeup will be dropped and won't
> change tracing_max_latency.
>
> The patch is tested by the following commands:
>
> $ mount -t tracefs none /sys/kernel/tracing
> $ echo wakeup_rt > /sys/kernel/tracing/current_tracer
> # some other stress-ng options are also tested
> $ stress-ng --cpu 4 &
> $ cyclictest --mlockall --smp --priority=99 &
> $ cyclictest_pid=$!
> # child thread of cyclictest main process
> $ thread_pid=$((cyclictest_pid + 1))
>
> $ echo ${thread_pid} > /sys/kernel/tracing/set_wakeup_pid
>
> $ echo 1 > /sys/kernel/tracing/tracing_on
> $ echo 0 > /sys/kernel/tracing/tracing_max_latency
> $ wait ${cyclictest_pid}
> $ echo 0 > /sys/kernel/tracing/tracing_on
> $ cat /sys/kernel/tracing/trace
>
> The maximum latency and backtrace recorded in the trace file will be only
> generated by the target process.
> Then we can eliminate interference from other programs, making it easier
> to identify the cause of latency.
>
> Tested-by: Jiexun Wang <wangjie...@tinylab.org>
> Signed-off-by: Jinyu Tang <tangji...@tinylab.org>
> ---
Honestly, the wakeup tracers are obsolete. I haven't used them in years. I
use synthetic events instead:
# cd /sys/kernel/tracing
# echo 'wakeup_lat pid_t pid; u64 delay;' > synthetic_events
# echo 'hist:keys=pid:ts=common_timestamp.usecs' if pid==$thread_pid >
events/sched/sched_waking/trigger
# echo
'hist:keys=next_pid:delta=common_timestamp.usecs-$ts:onmax($delta).trace(wakeup_lat,next_pid,$delta)'
> events/sched/sched_switch/trigger
# echo 1 > events/synthetic/wakeup_lat/enable
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 3/3 #P:8
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [000] d..4. 350799.423428: wakeup_lat: pid=59921
delay=1281
<idle>-0 [000] d..4. 350800.423441: wakeup_lat: pid=59921
delay=1317
<idle>-0 [000] d..4. 350801.423445: wakeup_lat: pid=59921
delay=1331
I could also make it record stack traces, disable tracing, and all sorts of
other nifty things.
-- Steve
