Skip to content

Commit 867f4a0

Browse files
chenyuezhouchenyuezhou
authored
tools: add softirqslower (#5356)
Summary ======= Adds softirqslower tool to trace softirq execution performance issues by measuring: SoftIRQ Runtime: Handler execution duration HardIRQ-to-SoftIRQ Latency: Delay between wakeup (trigger) and execution start Motivation ======== Diagnosing network latency/stalls requires observing: Slow softirq executions (e.g., >10ms NET_RX processing) Scheduling delays where softirqs get preempted after wakeup Signed-off-by: chenyuezhou <[email protected]>
1 parent e12cf0f commit 867f4a0

File tree

6 files changed

+401
-0
lines changed

6 files changed

+401
-0
lines changed

‎README.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -136,6 +136,7 @@ pair of .c and .py files, and some are directories of files.
136136
- tools/[mysqld_qslower](tools/mysqld_qslower.py): Trace MySQL server queries slower than a threshold. [Examples](tools/mysqld_qslower_example.txt).
137137
- tools/[ppchcalls](tools/ppchcalls.py): Summarize ppc hcall counts and latencies. [Examples](tools/ppchcalls_example.txt).
138138
- tools/[softirqs](tools/softirqs.py): Measure soft IRQ (soft interrupt) event time. [Examples](tools/softirqs_example.txt).
139+
- tools/[softirqslower](tools/softirqslower.py): Trace slow soft IRQ (interrupt). [Examples](tools/softirqslower_example.txt).
139140
- tools/[syscount](tools/syscount.py): Summarize syscall counts and latencies. [Examples](tools/syscount_example.txt).
140141

141142
##### CPU and Scheduler Tools

‎man/man8/softirqslower.8‎

Lines changed: 133 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,133 @@
1+
.TH SOFTIRQSLOWER 8 "2025-07-08" "BCC Tools" "Linux Performance Analysis"
2+
.SH NAME
3+
softirqslower \- Trace softirq handlers with latency exceeding a threshold
4+
.SH SYNOPSIS
5+
.B softirqslower.py
6+
.RI [min_us]
7+
.br
8+
.B softirqslower.py
9+
.RB [ \-c
10+
.IR CPU ]
11+
.RI [min_us]
12+
.SH DESCRIPTION
13+
The
14+
.B softirqslower
15+
tool traces softirq events that exceed a specified latency threshold. This tool helps diagnose
16+
interrupt handling bottlenecks by measuring two critical latency dimensions:
17+
18+
.IP \(bu 2
19+
\fBirq(hard) to softirq\fR: Time delay between hardware interrupt completion and softirq execution start
20+
.IP \(bu 2
21+
\fBsoftirq runtime\fR: Actual execution duration of softirq handlers
22+
.PP
23+
Developed as part of the BCC (BPF Compiler Collection) tools, it's particularly useful for network
24+
stack optimization, scheduler tuning, and real-time systems analysis.
25+
26+
.SH OPTIONS
27+
.TP
28+
.B min_us
29+
Minimum latency threshold to trace (in microseconds). Default: 10,000 μs (10 ms)
30+
.TP
31+
.BR \-c ", " \-\-cpu " " \fICPU
32+
Trace only events on the specified CPU core
33+
34+
.SH OUTPUT FORMAT
35+
The tool outputs events in the following table format:
36+
.PP
37+
TIME STAGE SOFTIRQ LAT(us) CPU COMM
38+
.PP
39+
With fields defined as:
40+
.TP
41+
.B TIME
42+
Event timestamp (HH:MM:SS format)
43+
.TP
44+
.B STAGE
45+
Latency measurement type:
46+
.RS
47+
.TP 12
48+
.B irq(hard) to softirq
49+
Time from hardware interrupt completion to softirq dispatch
50+
.TP
51+
.B softirq runtime
52+
SoftIRQ handler execution duration
53+
.RE
54+
.TP
55+
.B SOFTIRQ
56+
SoftIRQ category (case-sensitive). Common values:
57+
.RS
58+
.TP 12
59+
.B NET_RX
60+
Network reception processing
61+
.TP
62+
.B NET_TX
63+
Network transmission processing
64+
.TP
65+
.B TIMER
66+
Timer callbacks
67+
.TP
68+
.B SCHED
69+
Scheduler operations
70+
.TP
71+
.B RCU
72+
Read-Copy-Update synchronization
73+
.TP
74+
.B TASKLET
75+
Deferred task execution
76+
.TP
77+
.B HRTIMER
78+
High-resolution timers
79+
.TP
80+
.B BLOCK
81+
Block device operations
82+
.RE
83+
.TP
84+
.B LAT(us)
85+
Measured latency in microseconds
86+
.TP
87+
.B CPU
88+
CPU core where softirq was handled (0-based numbering)
89+
.TP
90+
.B COMM
91+
Process context handling the softirq:
92+
.RS
93+
.TP 12
94+
.B swapper/N
95+
Idle thread for CPU N
96+
.TP
97+
.B ksoftirqd/N
98+
Softirq daemon for CPU N
99+
.TP
100+
.B <process>
101+
User-space process
102+
.RE
103+
104+
.SH EXAMPLES
105+
.TP
106+
Trace softirqs exceeding 10μs latency:
107+
.B softirqslower 10
108+
.TP
109+
Monitor only CPU core 1:
110+
.B softirqslower \-c 1
111+
.TP
112+
Trace network-related softirq delays (>50μs):
113+
.B softirqslower 50 | grep -E 'net_rx|net_tx'
114+
.TP
115+
Capture RCU delays longer than 100μs to file:
116+
.B softirqslower 100 | grep "rcu" > rcu_latency.log
117+
118+
.SH SIGNALS
119+
.B Ctrl+C
120+
Stop tracing and exit gracefully
121+
122+
.SH AUTHOR
123+
Chenyue Zhou
124+
125+
.SH SEE ALSO
126+
.BR runqslower (8),
127+
.BR hardirqs (8),
128+
.BR softirqs (8),
129+
.BR trace (8),
130+
.BR funclatency (8),
131+
132+
.SH REPORTING BUGS
133+
BCC Tools Issue Tracker: https://github.com/iovisor/bcc/issues

‎snap/snapcraft.yaml‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -274,6 +274,8 @@ apps:
274274
command: bcc-wrapper sofdsnoop
275275
softirqs:
276276
command: bcc-wrapper softirqs
277+
softirqslower:
278+
command: bcc-wrapper softirqslower
277279
solisten:
278280
command: bcc-wrapper solisten
279281
sslsniff:

‎tests/python/test_tools_smoke.py‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -317,6 +317,10 @@ def test_softirqs(self):
317317
self.run_with_duration("softirqs.py 1 1")
318318
pass
319319

320+
@skipUnless(kernel_version_ge(4,7), "requires kernel >= 4.7")
321+
def test_softirqslower(self):
322+
self.run_with_int("softirqslower.py")
323+
320324
@skipUnless(kernel_version_ge(4,4), "requires kernel >= 4.4")
321325
def test_solisten(self):
322326
self.run_with_int("solisten.py")

‎tools/softirqslower.py‎

Lines changed: 203 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,203 @@
1+
#!/usr/bin/env python
2+
# @lint-avoid-python-3-compatibility-imports
3+
#
4+
# softirqlat Trace slow soft IRQ (interrupt).
5+
# For Linux, uses BCC, eBPF.
6+
#
7+
# USAGE: softirqslower [-h] [-c CPU] [min_us]
8+
#
9+
# Copyright (c) 2025 Chenyue Zhou.
10+
# Licensed under the Apache License, Version 2.0 (the "License")
11+
#
12+
# 08-Jul-2025 Chenyue Zhou Created this.
13+
14+
from __future__ import print_function
15+
from bcc import BPF
16+
from time import sleep, strftime
17+
import argparse
18+
import sys
19+
20+
# arguments
21+
examples = """examples:
22+
./softirqslower # trace softirq latency higher than 10000 us (default)
23+
./softirqslower 100000 # trace softirq latency higher than 100000 us
24+
./softirqslower -c 1 # trace softirq latency on CPU 1 only
25+
"""
26+
27+
parser = argparse.ArgumentParser(
28+
description="Trace slow soft IRQ (interrupt).",
29+
formatter_class=argparse.RawDescriptionHelpFormatter,
30+
epilog=examples)
31+
parser.add_argument("min_us", nargs="?", default="10000",
32+
help="minimum softirq latency to trace, in us (default 10000)")
33+
parser.add_argument("-c", "--cpu", type=int, help="trace this CPU only")
34+
parser.add_argument("--ebpf", action="store_true", help=argparse.SUPPRESS)
35+
args = parser.parse_args()
36+
37+
bpf_text = """
38+
#include <uapi/linux/ptrace.h>
39+
#include <linux/sched.h>
40+
#include <linux/interrupt.h>
41+
42+
enum {
43+
SOFTIRQ_RAISE,
44+
SOFTIRQ_ENTRY,
45+
SOFTIRQ_EXIT,
46+
SOFTIRQ_MAX_STAGE,
47+
};
48+
49+
struct counter {
50+
u64 ts;
51+
u8 not_first;
52+
};
53+
54+
struct data {
55+
u32 reserved;
56+
u32 stage;
57+
u32 vec;
58+
u32 cpu;
59+
u64 delta_ns;
60+
char task[TASK_COMM_LEN];
61+
};
62+
63+
BPF_PERCPU_ARRAY(raise, struct counter, NR_SOFTIRQS);
64+
BPF_PERCPU_ARRAY(entry, struct counter, NR_SOFTIRQS);
65+
BPF_PERF_OUTPUT(softirq_events);
66+
67+
static __always_inline void event_collect(void *ctx, u32 stage, u32 vec,
68+
u32 cpu, u64 delta_ns)
69+
{
70+
struct data dt = {
71+
.stage = stage,
72+
.vec = vec,
73+
.cpu = cpu,
74+
.delta_ns = delta_ns,
75+
};
76+
bpf_get_current_comm(&dt.task, sizeof(dt.task));
77+
softirq_events.perf_submit(ctx, &dt, sizeof(dt));
78+
}
79+
80+
RAW_TRACEPOINT_PROBE(softirq_raise)
81+
{
82+
u32 cpu = bpf_get_smp_processor_id();
83+
u32 vec = (u32)(ctx->args[0]);
84+
85+
FILTER_CPU
86+
87+
struct counter *data = raise.lookup(&vec);
88+
if (!data)
89+
return 0;
90+
91+
if (data->ts) {
92+
// TODO record event
93+
return 0;
94+
}
95+
96+
data->not_first = 1;
97+
data->ts = bpf_ktime_get_ns();
98+
99+
return 0;
100+
}
101+
102+
RAW_TRACEPOINT_PROBE(softirq_entry)
103+
{
104+
u32 cpu = bpf_get_smp_processor_id();
105+
u32 vec = (u32)(ctx->args[0]);
106+
107+
FILTER_CPU
108+
109+
struct counter *data = raise.lookup(&vec);
110+
if (!data)
111+
return 0;
112+
113+
if ((data->not_first) && !(data->ts)) {
114+
// TODO record miss event
115+
return 0;
116+
}
117+
118+
u64 cur_ts = bpf_ktime_get_ns();
119+
u64 delta_ns = cur_ts - data->ts;
120+
data->ts = 0;
121+
122+
if (DELTA_FILTER) {
123+
event_collect(ctx, SOFTIRQ_ENTRY, vec, cpu, delta_ns);
124+
}
125+
data = entry.lookup(&vec);
126+
if (!data)
127+
return 0;
128+
129+
data->not_first = 1;
130+
data->ts = cur_ts;
131+
132+
return 0;
133+
}
134+
135+
RAW_TRACEPOINT_PROBE(softirq_exit)
136+
{
137+
u32 cpu = bpf_get_smp_processor_id();
138+
u32 vec = (u32)(ctx->args[0]);
139+
140+
FILTER_CPU
141+
142+
struct counter *data = entry.lookup(&vec);
143+
if (!data)
144+
return 0;
145+
146+
if ((data->not_first) && !(data->ts)) {
147+
// TODO record miss event
148+
return 0;
149+
}
150+
151+
u64 cur_ts = bpf_ktime_get_ns();
152+
u64 delta_ns = cur_ts - data->ts;
153+
data->ts = 0;
154+
155+
if (DELTA_FILTER) {
156+
event_collect(ctx, SOFTIRQ_EXIT, vec, cpu, delta_ns);
157+
}
158+
159+
return 0;
160+
}
161+
"""
162+
163+
def vec_to_name(vec):
164+
return ["hi", "timer", "net_tx", "net_rx", "block", "irq_poll", "tasklet",
165+
"sched", "hrtimer", "rcu"][vec]
166+
167+
def stage_to_name(stage):
168+
return ["raise softirq", "irq(hard) to softirq", "softirq runtime"][stage]
169+
170+
def print_event(cpu, data, size):
171+
event = b["softirq_events"].event(data)
172+
print("%-8s %-20s %-8s %-14d %-6d %-6s" % (strftime("%H:%M:%S"),
173+
stage_to_name(event.stage), vec_to_name(event.vec),
174+
event.delta_ns / 1000, event.cpu, event.task.decode("utf-8",
175+
"replace")))
176+
177+
if __name__ == "__main__":
178+
if args.cpu is not None:
179+
bpf_text = bpf_text.replace("FILTER_CPU",
180+
'if (cpu != %d) { return 0; }' % int(args.cpu))
181+
else:
182+
bpf_text = bpf_text.replace("FILTER_CPU", "")
183+
184+
bpf_text = bpf_text.replace("DELTA_FILTER", "delta_ns >= %d" % \
185+
(int(args.min_us) * 1000))
186+
187+
if args.ebpf:
188+
print(bpf_text)
189+
exit()
190+
191+
b = BPF(text=bpf_text)
192+
b["softirq_events"].open_perf_buffer(print_event, page_cnt=64)
193+
194+
print("Tracing softirq latency higher than %d us... Hit Ctrl-C to end." % \
195+
int(args.min_us))
196+
197+
print("%-8s %-20s %-8s %-14s %-6s %-6s" % ("TIME", "STAGE", "SOFTIRQ",
198+
"LAT(us)", "CPU", "COMM"))
199+
while (1):
200+
try:
201+
b.perf_buffer_poll()
202+
except KeyboardInterrupt:
203+
exit()

0 commit comments

Comments
 (0)