mirror of
https://github.com/eunomia-bpf/bpf-developer-tutorial.git
synced 2026-02-11 06:05:19 +08:00
147 lines
5.9 KiB
Markdown
147 lines
5.9 KiB
Markdown
| layout | title | date | category | author | tags | summary |
|
|
| ------ | ---------- | ---------------- | -------- | -------- | --------------- | ----------------------------------------------- |
|
|
| post | runqslower | 2022-11-11-20:50 | bpftools | yunwei37 | bpftool syscall | runqslower Trace long process scheduling delays |
|
|
|
|
## origin
|
|
|
|
origin from:
|
|
|
|
https://github.com/iovisor/bcc/blob/master/libbpf-tools/runqslower.bpf.c
|
|
|
|
result:
|
|
|
|
```
|
|
$ sudo ecli/build/bin/Release/ecli run examples/bpftools/runqslower/package.json
|
|
|
|
running and waiting for the ebpf events from perf event...
|
|
time task prev_task delta_us pid prev_pid
|
|
20:11:59 gnome-shell swapper/0 32 2202 0
|
|
20:11:59 ecli swapper/3 23 3437 0
|
|
20:11:59 rcu_sched swapper/1 1 14 0
|
|
20:11:59 gnome-terminal- swapper/1 13 2714 0
|
|
20:11:59 ecli swapper/3 2 3437 0
|
|
20:11:59 kworker/3:3 swapper/3 3 215 0
|
|
20:11:59 containerd swapper/1 8 1088 0
|
|
20:11:59 ecli swapper/2 5 3437 0
|
|
20:11:59 HangDetector swapper/3 6 854 0
|
|
20:11:59 ecli swapper/2 60 3437 0
|
|
20:11:59 rcu_sched swapper/1 26 14 0
|
|
20:11:59 kworker/0:1 swapper/0 26 3414 0
|
|
20:11:59 ecli swapper/2 6 3437 0
|
|
```
|
|
|
|
## Compile and Run
|
|
|
|
Compile:
|
|
|
|
```
|
|
docker run -it -v `pwd`/:/src/ yunwei37/ebpm:latest
|
|
```
|
|
|
|
Run:
|
|
|
|
```
|
|
sudo ./ecli run examples/bpftools/runqslower/package.json
|
|
```
|
|
|
|
## details in bcc
|
|
|
|
Demonstrations of runqslower, the Linux eBPF/bcc version.
|
|
|
|
runqslower traces high scheduling delays between tasks being ready to run and them running on CPU after that. Example output:
|
|
|
|
```
|
|
# ./runqslower
|
|
Tracing run queue latency higher than 10000 us
|
|
TIME COMM TID LAT(us)
|
|
13:11:43 b'kworker/0:2' 8680 10250
|
|
13:12:18 b'irq/16-vmwgfx' 422 10838
|
|
13:12:18 b'systemd-oomd' 753 11012
|
|
13:12:18 b'containerd' 8272 11254
|
|
13:12:18 b'HangDetector' 764 12042
|
|
^C
|
|
``
|
|
This measures the time a task spends waiting on a run queue for a turn on-CPU, and shows this time as a individual events. This time should be small, but a task may need to wait its turn due to CPU load.
|
|
|
|
This measures two types of run queue latency:
|
|
1. The time from a task being enqueued on a run queue to its context switch and execution. This traces ttwu_do_wakeup(), wake_up_new_task() -> finish_task_switch() with either raw tracepoints (if supported) or kprobes and instruments the run queue latency after a voluntary context switch.
|
|
2. The time from when a task was involuntary context switched and still in the runnable state, to when it next executed. This is instrumented from finish_task_switch() alone.
|
|
|
|
The overhead of this tool may become significant for some workloads: see the OVERHEAD section.
|
|
|
|
This works by tracing various kernel scheduler functions using dynamic tracing, and will need updating to match any changes to these functions.
|
|
|
|
Since this uses BPF, only the root user can use this tool.
|
|
|
|
```console
|
|
Usage: runqslower [-h] [-p PID | -t TID | -P] [min_us]
|
|
```
|
|
|
|
The min_us option sets the latency of the run queue to track:
|
|
|
|
```
|
|
# ./runqslower 100
|
|
Tracing run queue latency higher than 100 us
|
|
TIME COMM TID LAT(us)
|
|
20:48:26 b'gnome-shell' 3005 201
|
|
20:48:26 b'gnome-shell' 3005 202
|
|
20:48:26 b'gnome-shell' 3005 254
|
|
20:48:26 b'gnome-shell' 3005 208
|
|
20:48:26 b'gnome-shell' 3005 132
|
|
20:48:26 b'gnome-shell' 3005 213
|
|
20:48:26 b'gnome-shell' 3005 205
|
|
20:48:26 b'python3' 5224 127
|
|
20:48:26 b'gnome-shell' 3005 214
|
|
20:48:26 b'gnome-shell' 3005 126
|
|
20:48:26 b'gnome-shell' 3005 285
|
|
20:48:26 b'Xorg' 2869 296
|
|
20:48:26 b'gnome-shell' 3005 119
|
|
20:48:26 b'gnome-shell' 3005 206
|
|
```
|
|
|
|
The -p PID option only traces this PID:
|
|
|
|
```
|
|
# ./runqslower -p 3005
|
|
Tracing run queue latency higher than 10000 us
|
|
TIME COMM TID LAT(us)
|
|
20:46:22 b'gnome-shell' 3005 16024
|
|
20:46:45 b'gnome-shell' 3005 11494
|
|
20:46:45 b'gnome-shell' 3005 21430
|
|
20:46:45 b'gnome-shell' 3005 14948
|
|
20:47:16 b'gnome-shell' 3005 10164
|
|
20:47:16 b'gnome-shell' 3005 18070
|
|
20:47:17 b'gnome-shell' 3005 13272
|
|
20:47:18 b'gnome-shell' 3005 10451
|
|
20:47:18 b'gnome-shell' 3005 15010
|
|
20:47:18 b'gnome-shell' 3005 19449
|
|
20:47:22 b'gnome-shell' 3005 19327
|
|
20:47:23 b'gnome-shell' 3005 13178
|
|
20:47:23 b'gnome-shell' 3005 13483
|
|
20:47:23 b'gnome-shell' 3005 15562
|
|
20:47:23 b'gnome-shell' 3005 13655
|
|
20:47:23 b'gnome-shell' 3005 19571
|
|
```
|
|
|
|
The -P option also shows previous task name and TID:
|
|
|
|
```
|
|
# ./runqslower -P
|
|
Tracing run queue latency higher than 10000 us
|
|
TIME COMM TID LAT(us) PREV COMM PREV TID
|
|
20:42:48 b'sysbench' 5159 10562 b'sysbench' 5152
|
|
20:42:48 b'sysbench' 5159 10367 b'sysbench' 5152
|
|
20:42:49 b'sysbench' 5158 11818 b'sysbench' 5159
|
|
20:42:49 b'sysbench' 5160 16913 b'sysbench' 5153
|
|
20:42:49 b'sysbench' 5157 13742 b'sysbench' 5160
|
|
20:42:49 b'sysbench' 5152 13746 b'sysbench' 5160
|
|
20:42:49 b'sysbench' 5153 13731 b'sysbench' 5160
|
|
20:42:49 b'sysbench' 5158 14688 b'sysbench' 5161
|
|
20:42:50 b'sysbench' 5155 10468 b'sysbench' 5152
|
|
20:42:50 b'sysbench' 5156 17695 b'sysbench' 5158
|
|
20:42:50 b'sysbench' 5155 11251 b'sysbench' 5152
|
|
20:42:50 b'sysbench' 5154 13283 b'sysbench' 5152
|
|
20:42:50 b'sysbench' 5158 22278 b'sysbench' 5157
|
|
```
|
|
|
|
For more details, see docs/special_filtering.md |