Commit 46186905 authored by Matthias Tafelmeier's avatar Matthias Tafelmeier

softirqs: focus CPU as dissector

With having in mind that softirq processing is happeing in
ksoftirqd/<cpu> context, which is associated with a specific cpu over
the whole dynamic life time of a system, focussing on CPus as the
dissector appears more sensical.

Quite helpful is this alternative angle of view on the softirqs
processing especially for surveilling the effectiveness of net stack
tunings, as this is highly dynamic depending on the actual net stack
configuration, e.g. scaling or steering.
Signed-off-by: default avatarMatthias Tafelmeier <matthias.tafelmeier@gmx.net>
parent 9bcad326
......@@ -33,6 +33,8 @@ parser.add_argument("-N", "--nanoseconds", action="store_true",
help="output in nanoseconds")
parser.add_argument("-d", "--dist", action="store_true",
help="show distributions as histograms")
parser.add_argument("-C", "--bycpu", action="store_true",
help="break down softirqs to individual cpus")
parser.add_argument("interval", nargs="?", default=99999999,
help="output interval, in seconds")
parser.add_argument("count", nargs="?", default=99999999,
......@@ -48,58 +50,102 @@ else:
debug = 0
# define BPF program
bpf_text = """
#include <uapi/linux/ptrace.h>
typedef struct irq_key {
u64 ip;
u64 slot;
} irq_key_t;
BPF_HASH(start, u32);
BPF_HASH(iptr, u32);
BPF_HISTOGRAM(dist, irq_key_t);
// time IRQ
int trace_start(struct pt_regs *ctx)
{
u32 pid = bpf_get_current_pid_tgid();
u64 ip = PT_REGS_IP(ctx), ts = bpf_ktime_get_ns();
start.update(&pid, &ts);
iptr.update(&pid, &ip);
return 0;
}
int trace_completion(struct pt_regs *ctx)
{
u64 *tsp, delta, ip, *ipp;
u32 pid = bpf_get_current_pid_tgid();
// fetch timestamp and calculate delta
tsp = start.lookup(&pid);
ipp = iptr.lookup(&pid);
if (tsp == 0 || ipp == 0) {
return 0; // missed start
bpf_text = ""
if args.bycpu:
bpf_text = """
#include <uapi/linux/ptrace.h>
typedef struct irq_cpu_key {
s64 cpu;
u64 slot;
} irq_key_t;
BPF_HASH(start, u32);
BPF_HISTOGRAM(dist, irq_key_t);
// time IRQ
int trace_start_cpu(struct pt_regs *ctx)
{
int curr_cpu = bpf_get_smp_processor_id();
u64 ts = bpf_ktime_get_ns();
start.update(&curr_cpu, &ts);
return 0;
}
delta = bpf_ktime_get_ns() - *tsp;
ip = *ipp;
// store as sum or histogram
STORE
int trace_completion_cpu(struct pt_regs *ctx)
{
u64 *tsp, delta;
int curr_cpu = bpf_get_smp_processor_id();
start.delete(&pid);
iptr.delete(&pid);
return 0;
}
"""
// fetch timestamp and calculate delta
tsp = start.lookup(&curr_cpu);
COMMON
// store as sum or histogram
irq_key_t key = {.cpu = curr_cpu,
STORE
start.delete(&curr_cpu);
return 0;
}
"""
else:
bpf_text = """
#include <uapi/linux/ptrace.h>
typedef struct irq_key {
u64 ip;
u64 slot;
} irq_key_t;
BPF_HASH(start, u32);
BPF_HASH(iptr, u32);
BPF_HISTOGRAM(dist, irq_key_t);
// time IRQ
int trace_start(struct pt_regs *ctx)
{
u32 pid = bpf_get_current_pid_tgid();
u64 ip = PT_REGS_IP(ctx), ts = bpf_ktime_get_ns();
start.update(&pid, &ts);
iptr.update(&pid, &ip);
return 0;
}
int trace_completion(struct pt_regs *ctx)
{
u64 *tsp, delta, ip, *ipp;
u32 pid = bpf_get_current_pid_tgid();
// fetch timestamp and calculate delta
tsp = start.lookup(&pid);
ipp = iptr.lookup(&pid);
COMMON
// store as sum or histogram
irq_key_t key = {
STORE
start.delete(&pid);
iptr.delete(&pid);
return 0;
}
"""
# code substitutions
bpf_text = bpf_text.replace('COMMON',
"""if (tsp == 0) {
return 0; // missed start
}
delta = bpf_ktime_get_ns() - *tsp;
""")
if args.dist:
bpf_text = bpf_text.replace('STORE',
'irq_key_t key = {.ip = ip, .slot = bpf_log2l(delta)};' +
'.slot = bpf_log2l(delta)};' +
'dist.increment(key);')
else:
bpf_text = bpf_text.replace('STORE',
'irq_key_t key = {.ip = ip, .slot = 0 /* ignore */};' +
' .ip = ip, .slot = 0 /* ignore */};' +
'u64 zero = 0, *vp = dist.lookup_or_init(&key, &zero);' +
'(*vp) += delta;')
if debug:
......@@ -115,8 +161,12 @@ for softirqfunc in ("blk_iopoll_softirq", "blk_done_softirq",
"rcu_process_callbacks", "run_rebalance_domains", "tasklet_action",
"tasklet_hi_action", "run_timer_softirq", "net_tx_action",
"net_rx_action"):
b.attach_kprobe(event=softirqfunc, fn_name="trace_start")
b.attach_kretprobe(event=softirqfunc, fn_name="trace_completion")
if args.bycpu:
b.attach_kprobe(event=softirqfunc, fn_name="trace_start_cpu")
b.attach_kretprobe(event=softirqfunc, fn_name="trace_completion_cpu")
else:
b.attach_kprobe(event=softirqfunc, fn_name="trace_start")
b.attach_kretprobe(event=softirqfunc, fn_name="trace_completion")
print("Tracing soft irq event time... Hit Ctrl-C to end.")
......@@ -134,11 +184,19 @@ while (1):
print("%-8s\n" % strftime("%H:%M:%S"), end="")
if args.dist:
dist.print_log2_hist(label, "softirq", section_print_fn=b.ksym)
if args.bycpu:
dist.print_log2_hist(label, "CPU")
else:
dist.print_log2_hist(label, "softirq", section_print_fn=b.ksym)
else:
print("%-26s %11s" % ("SOFTIRQ", "TOTAL_" + label))
for k, v in sorted(dist.items(), key=lambda dist: dist[1].value):
print("%-26s %11d" % (b.ksym(k.ip), v.value / factor))
if args.bycpu:
print("%-26s %11s %11s" % ("SOFTIRQ", "CPU", "TOTAL_" + label))
for k, v in sorted(dist.items(), key=lambda dist: dist[1].value):
print("%-26s %11d %11d" % (b.ksym(k.ip), k.cpu, v.value / factor))
else:
print("%-26s %11s" % ("SOFTIRQ", "TOTAL_" + label))
for k, v in sorted(dist.items(), key=lambda dist: dist[1].value):
print("%-26s %11d" % (b.ksym(k.ip), v.value / factor))
dist.clear()
countdown -= 1
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment