Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tools/runqslower.py: Option for --pid or --tid #2635

Merged
merged 5 commits into from
Jan 3, 2020
Merged

tools/runqslower.py: Option for --pid or --tid #2635

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
2a3818b
tools/runqslower.py: Option for --pid or --tid
bodgergely Nov 28, 2019
1f865b7
Remove the 'and its children' comments.
bodgergely Jan 2, 2020
09f4fd2
tools/runqslower.py: Use add_mutually_exclusive_group()
bodgergely Jan 3, 2020
08d04cc
man runqslower: show TID option too
bodgergely Jan 3, 2020
43b1f5b
Remove redundant arg check.
bodgergely Jan 3, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
50 changes: 35 additions & 15 deletions tools/runqslower.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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] [min_us]
# USAGE: runqslower [-p PID] [-t TID] [min_us]
#
# REQUIRES: Linux 4.9+ (BPF_PROG_TYPE_PERF_EVENT support).
#
Expand Down Expand Up @@ -42,14 +42,17 @@
examples = """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 only
./runqslower -p 123 # trace pid 123 and its children threads
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
./runqslower -t 123 # trace tid 123 (use for threads only)
"""
parser = argparse.ArgumentParser(
description="Trace high run queue latency",
formatter_class=argparse.RawDescriptionHelpFormatter,
epilog=examples)
parser.add_argument("-p", "--pid", type=int, metavar="PID", dest="pid",
help="trace this PID only")
help="trace this PID and its children")
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
parser.add_argument("-t", "--tid", type=int, metavar="TID", dest="tid",
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
help="trace this TID only")
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
parser.add_argument("min_us", nargs="?", default='10000',
help="minimum run queue latecy to trace, in ms (default 10000)")
parser.add_argument("--ebpf", action="store_true",
Expand Down Expand Up @@ -80,7 +83,7 @@
// record enqueue timestamp
static int trace_enqueue(u32 tgid, u32 pid)
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
{
if (FILTER_PID || pid == 0)
if (FILTER_PID || FILTER_TGID || pid == 0)
return 0;
u64 ts = bpf_ktime_get_ns();
start.update(&pid, &ts);
Expand Down Expand Up @@ -109,13 +112,14 @@
if (prev->state == TASK_RUNNING) {
tgid = prev->tgid;
pid = prev->pid;
if (!(FILTER_PID || pid == 0)) {
u64 ts = bpf_ktime_get_ns();
start.update(&pid, &ts);
u64 ts = bpf_ktime_get_ns();
if (pid != 0) {
if (!(FILTER_PID) && !(FILTER_TGID)) {
start.update(&pid, &ts);
}
}
}

tgid = bpf_get_current_pid_tgid() >> 32;
pid = bpf_get_current_pid_tgid();

u64 *tsp, delta_us;
Expand Down Expand Up @@ -167,17 +171,21 @@
// 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 pid;
u32 tgid, pid;
long state;

// ivcsw: treat like an enqueue event and store timestamp
bpf_probe_read(&state, sizeof(long), (const void *)&prev->state);
if (state == TASK_RUNNING) {
bpf_probe_read(&tgid, sizeof(prev->tgid), &prev->tgid);
bpf_probe_read(&pid, sizeof(prev->pid), &prev->pid);
if (!(FILTER_PID || pid == 0)) {
u64 ts = bpf_ktime_get_ns();
start.update(&pid, &ts);
u64 ts = bpf_ktime_get_ns();
if (pid != 0) {
if (!(FILTER_PID) && !(FILTER_TGID)) {
start.update(&pid, &ts);
}
}

}

bpf_probe_read(&pid, sizeof(next->pid), &next->pid);
Expand Down Expand Up @@ -218,10 +226,22 @@
bpf_text = bpf_text.replace('FILTER_US', '0')
else:
bpf_text = bpf_text.replace('FILTER_US', 'delta_us <= %s' % str(min_us))
if args.pid:
bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % args.pid)

if args.tid and args.pid:
print("Can not specify both pid and tid!")
print(examples)
exit(-1)
bodgergely marked this conversation as resolved.
Show resolved Hide resolved

if args.tid:
bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % args.tid)
else:
bpf_text = bpf_text.replace('FILTER_PID', '0')

if args.pid:
bpf_text = bpf_text.replace('FILTER_TGID', 'tgid != %s' % args.pid)
else:
bpf_text = bpf_text.replace('FILTER_TGID', '0')

if debug or args.ebpf:
print(bpf_text)
if args.ebpf:
Expand All @@ -240,7 +260,7 @@ def print_event(cpu, data, size):
b.attach_kprobe(event="finish_task_switch", fn_name="trace_run")

print("Tracing run queue latency higher than %d us" % min_us)
print("%-8s %-16s %-6s %14s" % ("TIME", "COMM", "PID", "LAT(us)"))
print("%-8s %-16s %-6s %14s" % ("TIME", "COMM", "TID", "LAT(us)"))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This does not sound right. You cannot use "TID" all the time. If user specify '-p ', you want to show "PID".

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We might get threads showing up in case of '--pid' flag too. So using PID is also not correct in that case either.
Anyways my 2 cents are on just to simply stay with showing PID as a column value even for threads. Htop, top does the same. Showing PID/TID is bringing quite a lot possible confusion here.
Or what do you vote for?
If you prefer I can make it show PID if '--pid' and TID if '--tid'.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Think about this again. For kernel run queue, actually TID indeed makes sense. So, yes, we can just do TID here. If user filtered through pid, showing TID should be okay too, redundant PID information may not be needed. If user did not do any filterring, TID is the right choice too.

In summary, we can just use "TID" as you changed the above. Please a comment though. Please address other comments and resubmit. Thanks!

Copy link
Contributor Author

@bodgergely bodgergely Jan 3, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, just to make it clear: :)

  • In case --pid cmd line arg -> show PID in the report column
  • In case --tid cmd line arg specified -> show TID in the report column

Is the above what you think would make the most sense?


# read events
b["events"].open_perf_buffer(print_event, page_cnt=64)
Expand Down
19 changes: 14 additions & 5 deletions tools/runqslower_example.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,15 @@ runqslower shows high latency scheduling times between tasks being
ready to run and them running on CPU after that. For example:

# runqslower
Tracing run queue latency higher than 10000 us
TIME COMM PID LAT(us)

Note: Showing TID (thread id) in the report column. The smallest
execution unit becomes a TID when using the --pid flag as
in that case the tool reports not only the parent pid but
its children threads as well.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please do make sure when "-p" is specified, the above contents are presented.

Copy link
Contributor Author

@bodgergely bodgergely Jan 3, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you mean to emit (the below caveat for example) when running the tool with --pid the text:

Note: when using the --pid flag the tool reports both the parent pid and any of its children threads as well.


Tracing run queue latency higher than 10000 us.

TIME COMM TID LAT(us)
04:16:32 cc1 12924 12739
04:16:32 sh 13640 12118
04:16:32 make 13639 12730
Expand All @@ -32,7 +39,7 @@ These delays can be analyzed in depth with "perf sched" tool, see:
USAGE message:

# ./runqslower -h
usage: runqslower.py [-h] [-p PID] [min_us]
usage: runqslower.py [-h] [-p PID | -t TID] [min_us]

Trace high run queue latency

Expand All @@ -41,9 +48,11 @@ positional arguments:

optional arguments:
-h, --help show this help message and exit
-p PID, --pid PID trace this PID only
-p PID, --pid PID trace this PID and its children threads
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
-t TID, --tid TID trace this TID only
bodgergely marked this conversation as resolved.
Show resolved Hide resolved

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 only
./runqslower -p 123 # trace pid 123 and its children
bodgergely marked this conversation as resolved.
Show resolved Hide resolved
./runqslower -t 123 # trace tid (thread) 123