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 <pizhenwei@bytedance.com>

diff --git a/man/man8/runqslower.8 b/man/man8/runqslower.8
index f8b5f008d2b3fda9984d4de3fc339fdb88bf855a..55ea5bd90921874309154ab22f5173072c7d26fa 100644 (file)
--- 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 6df98d9f1175dd6b00910754c178141c585d1141..ef2bf2816c888a870d66cf7a6cff2a650ce5ea1d 100755 (executable)
--- 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 e64f9451af2e931af81593898b1604e81373079f..0b4d4bcd109c3d837330fce9c6ae46f558a0096c 100644 (file)
--- 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