From e38b053220daf060300d24c8b3976e707f418e5c Mon Sep 17 00:00:00 2001 From: Costa Shulyupin Date: Thu, 4 Apr 2024 22:12:17 +0300 Subject: [PATCH] new tool wakesnoop wakesnoop attaches to scheduler tracepoints sched_waking and sched_wakeup, and measures delay of wakeup. --- sched/wakesnoop.bt | 43 +++++++++++++++++++++++++++++++++++++ sched/wakesnoop_example.txt | 16 ++++++++++++++ 2 files changed, 59 insertions(+) create mode 100755 sched/wakesnoop.bt create mode 100644 sched/wakesnoop_example.txt diff --git a/sched/wakesnoop.bt b/sched/wakesnoop.bt new file mode 100755 index 0000000..62da974 --- /dev/null +++ b/sched/wakesnoop.bt @@ -0,0 +1,43 @@ +#!/usr/bin/env bpftrace +/* + * latsnoop.bt Scheduler latency tracing tool. + * + * USAGE: + * ./latsnoop.bt [wakeup delay threshold, us] [cpu mask] [pid] + * + * Copyright 2024 Red Hat, Inc. + * Licensed under the Apache License, Version 2.0 (the "License"). + * + * 4-Apr-2024 Costa Shulyupin Initial release + */ + +BEGIN +{ + printf("Tracing scheduler delay and in microseconds. Ctrl-C to end.\n"); + printf("%-15s %9s %3s %7s %s\n", "TIME", "DELAY(us)", "CPU", "PID", "COMM"); +} + + +tracepoint:sched:sched_waking, +/!$3 || args.pid == $3/ +{ + @waking[args.pid] = nsecs; +} + +tracepoint:sched:sched_wakeup +/(!$3 || args.pid == $3) && @waking[args.pid] / +{ + $delay = (nsecs - @waking[args.pid]) / 1000; + @sched_wakeup_delay_max = max($delay); + if ($delay > $1 && (!$2 || 1 << args.target_cpu & $2)) { + printf("%s %9u %3u %7d %s\n", + strftime("%H:%M:%S.%f", @waking[args.pid]), $delay, args.target_cpu, + args.pid, args.comm); + } + delete(@waking[args.pid]); +} + +END +{ + clear(@waking); +} diff --git a/sched/wakesnoop_example.txt b/sched/wakesnoop_example.txt new file mode 100644 index 0000000..3f64342 --- /dev/null +++ b/sched/wakesnoop_example.txt @@ -0,0 +1,16 @@ +Demonstration of wakesnoop. + +wakesnoop attaches to scheduler tracepoints sched_waking and sched_wakeup +and measures delay of wakeup. + +# ./sched/wakesnoop.bt 100 +Attaching 4 probes... +Tracing scheduler delay and in microseconds. Ctrl-C to end. +TIME DELAY(us) CPU PID COMM +21:49:23.425949 123 7 6124 pulseaudio +21:49:23.534792 116 8 32155 VizCompositorTh +21:49:24.213697 145 5 6124 pulseaudio +21:49:24.315695 113 5 6124 pulseaudio +21:49:24.603702 107 5 6124 pulseaudio +21:49:24.652704 107 5 444683 kworker/u25:3 +