Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::3:3 as permitted sender) client-ip=2620:137:e000::3:3;
Date:   Mon, 9 Oct 2023 12:25:00 -0400
From:   Steven Rostedt <rostedt@goodmis.org>
To:     Jinyu Tang <tangjinyu@tinylab.org>
Cc:     mhiramat@kernel.org, bristot@kernel.org, ttjjyystupid@163.com,
        falcon@tinylab.org, wangjiexun@tinylab.org,
        linux-trace-kernel@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: [PATCH v1] Ftrace: make sched_wakeup can focus on the target
 process
Message-ID: <20231009122500.69854f94@gandalf.local.home>
In-Reply-To: <20231009153714.10743-1-tangjinyu@tinylab.org>
References: <20231009153714.10743-1-tangjinyu@tinylab.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Precedence: bulk

On Mon,  9 Oct 2023 23:37:14 +0800
Jinyu Tang <tangjinyu@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 <wangjiexun@tinylab.org>
> Signed-off-by: Jinyu Tang <tangjinyu@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