From: zhenwei pi Date: Thu, 12 Aug 2021 10:04:17 +0000 (+0800) Subject: tools/runqslower: add '-P' optional X-Git-Tag: v0.22.0~27 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=508d9694ba7ea503cce821175ffca5a7740b832b;p=platform%2Fupstream%2Fbcc.git tools/runqslower: add '-P' optional During a task hits schedule delay, in the high probability, the previous task takes a long time to run. It's possible to dump the previous task comm and TID by '-P' or '--previous' option. Signed-off-by: zhenwei pi --- diff --git a/man/man8/runqslower.8 b/man/man8/runqslower.8 index f8b5f008..55ea5bd9 100644 --- a/man/man8/runqslower.8 +++ b/man/man8/runqslower.8 @@ -2,7 +2,7 @@ .SH NAME runqslower \- Trace long process scheduling delays. .SH SYNOPSIS -.B runqslower [\-p PID] [\-t TID] [min_us] +.B runqslower [\-p PID] [\-t TID] [-P] [min_us] .SH DESCRIPTION This measures the time a task spends waiting on a run queue (or equivalent scheduler data structure) for a turn on-CPU, and shows occurrences of time @@ -43,6 +43,9 @@ Only show this TID (filtered in kernel for efficiency). .TP min_us Minimum scheduling delay in microseconds to output. +.TP +\-P +Also show previous task comm and TID. .SH EXAMPLES .TP Show scheduling delays longer than 10ms: diff --git a/tools/runqslower.py b/tools/runqslower.py index 6df98d9f..ef2bf281 100755 --- a/tools/runqslower.py +++ b/tools/runqslower.py @@ -7,7 +7,7 @@ # This script traces high scheduling delays between tasks being # ready to run and them running on CPU after that. # -# USAGE: runqslower [-p PID] [-t TID] [min_us] +# USAGE: runqslower [-p PID] [-t TID] [-P] [min_us] # # REQUIRES: Linux 4.9+ (BPF_PROG_TYPE_PERF_EVENT support). # @@ -44,6 +44,7 @@ examples = """examples: ./runqslower 1000 # trace run queue latency higher than 1000 us ./runqslower -p 123 # trace pid 123 ./runqslower -t 123 # trace tid 123 (use for threads only) + ./runqslower -P # also show previous task comm and TID """ parser = argparse.ArgumentParser( description="Trace high run queue latency", @@ -59,6 +60,8 @@ thread_group.add_argument("-p", "--pid", metavar="PID", dest="pid", help="trace this PID only", type=int) thread_group.add_argument("-t", "--tid", metavar="TID", dest="tid", help="trace this TID only", type=int) +thread_group.add_argument("-P", "--previous", action="store_true", + help="also show previous task name and TID") args = parser.parse_args() min_us = int(args.min_us) @@ -77,7 +80,9 @@ struct rq; struct data_t { u32 pid; + u32 prev_pid; char task[TASK_COMM_LEN]; + char prev_task[TASK_COMM_LEN]; u64 delta_us; }; @@ -109,16 +114,16 @@ int trace_ttwu_do_wakeup(struct pt_regs *ctx, struct rq *rq, struct task_struct // calculate latency int trace_run(struct pt_regs *ctx, struct task_struct *prev) { - u32 pid, tgid; + u32 pid, tgid, prev_pid; // ivcsw: treat like an enqueue event and store timestamp + prev_pid = prev->pid; if (prev->state == TASK_RUNNING) { tgid = prev->tgid; - pid = prev->pid; u64 ts = bpf_ktime_get_ns(); - if (pid != 0) { + if (prev_pid != 0) { if (!(FILTER_PID) && !(FILTER_TGID)) { - start.update(&pid, &ts); + start.update(&prev_pid, &ts); } } } @@ -139,8 +144,10 @@ int trace_run(struct pt_regs *ctx, struct task_struct *prev) struct data_t data = {}; data.pid = pid; + data.prev_pid = prev_pid; data.delta_us = delta_us; bpf_get_current_comm(&data.task, sizeof(data.task)); + bpf_probe_read_kernel_str(&data.prev_task, sizeof(data.prev_task), prev->comm); // output events.perf_submit(ctx, &data, sizeof(data)); @@ -174,18 +181,18 @@ RAW_TRACEPOINT_PROBE(sched_switch) // TP_PROTO(bool preempt, struct task_struct *prev, struct task_struct *next) struct task_struct *prev = (struct task_struct *)ctx->args[1]; struct task_struct *next= (struct task_struct *)ctx->args[2]; - u32 tgid, pid; + u32 tgid, pid, prev_pid; long state; // ivcsw: treat like an enqueue event and store timestamp bpf_probe_read_kernel(&state, sizeof(long), (const void *)&prev->state); + bpf_probe_read_kernel(&prev_pid, sizeof(prev->pid), &prev->pid); if (state == TASK_RUNNING) { bpf_probe_read_kernel(&tgid, sizeof(prev->tgid), &prev->tgid); - bpf_probe_read_kernel(&pid, sizeof(prev->pid), &prev->pid); u64 ts = bpf_ktime_get_ns(); - if (pid != 0) { + if (prev_pid != 0) { if (!(FILTER_PID) && !(FILTER_TGID)) { - start.update(&pid, &ts); + start.update(&prev_pid, &ts); } } @@ -207,8 +214,10 @@ RAW_TRACEPOINT_PROBE(sched_switch) struct data_t data = {}; data.pid = pid; + data.prev_pid = prev_pid; data.delta_us = delta_us; bpf_probe_read_kernel_str(&data.task, sizeof(data.task), next->comm); + bpf_probe_read_kernel_str(&data.prev_task, sizeof(data.prev_task), prev->comm); // output events.perf_submit(ctx, &data, sizeof(data)); @@ -248,7 +257,10 @@ if debug or args.ebpf: # process event def print_event(cpu, data, size): event = b["events"].event(data) - print("%-8s %-16s %-6s %14s" % (strftime("%H:%M:%S"), event.task, event.pid, event.delta_us)) + if args.previous: + print("%-8s %-16s %-6s %14s %-16s %-6s" % (strftime("%H:%M:%S"), event.task, event.pid, event.delta_us, event.prev_task, event.prev_pid)) + else: + print("%-8s %-16s %-6s %14s" % (strftime("%H:%M:%S"), event.task, event.pid, event.delta_us)) # load BPF program b = BPF(text=bpf_text) @@ -259,7 +271,10 @@ if not is_support_raw_tp: fn_name="trace_run") print("Tracing run queue latency higher than %d us" % min_us) -print("%-8s %-16s %-6s %14s" % ("TIME", "COMM", "TID", "LAT(us)")) +if args.previous: + print("%-8s %-16s %-6s %14s %-16s %-6s" % ("TIME", "COMM", "TID", "LAT(us)", "PREV COMM", "PREV TID")) +else: + print("%-8s %-16s %-6s %14s" % ("TIME", "COMM", "TID", "LAT(us)")) # read events b["events"].open_perf_buffer(print_event, page_cnt=64) diff --git a/tools/runqslower_example.txt b/tools/runqslower_example.txt index e64f9451..0b4d4bcd 100644 --- a/tools/runqslower_example.txt +++ b/tools/runqslower_example.txt @@ -44,15 +44,17 @@ usage: runqslower.py [-h] [-p PID | -t TID] [min_us] Trace high run queue latency positional arguments: - min_us minimum run queue latecy to trace, in us (default 10000) + min_us minimum run queue latency to trace, in us (default 10000) optional arguments: -h, --help show this help message and exit - -p PID, --pid PID trace this PID + -p PID, --pid PID trace this PID only -t TID, --tid TID trace this TID only + -P, --previous also show previous task name and TID examples: ./runqslower # trace run queue latency higher than 10000 us (default) ./runqslower 1000 # trace run queue latency higher than 1000 us ./runqslower -p 123 # trace pid 123 - ./runqslower -t 123 # trace tid (thread) 123 + ./runqslower -t 123 # trace tid 123 (use for threads only) + ./runqslower -P # also show previous task comm and TID