Skip to content

Commit

Permalink
Add softirq-latency example
Browse files Browse the repository at this point in the history 
Example for NET_RX:

    $ curl -s http://metrics-interface:3141/metrics | fgrep NET_RX_SOFTIRQ
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1e-06"} 7.285406e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="2e-06"} 7.795892e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="4e-06"} 8.007842e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="8e-06"} 8.151191e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1.6e-05"} 8.230504e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="3.2e-05"} 8.251142e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="6.4e-05"} 8.259189e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000128"} 8.261051e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000256"} 8.261677e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000512"} 8.262088e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.001024"} 8.262267e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.002048"} 8.262433e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.004096"} 8.262572e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.008192"} 8.262683e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.016384"} 8.262707e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.032768"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.065536"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.131072"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.262144"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.524288"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1.048576"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="2.097152"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="+Inf"} 8.262708e+06
    ebpf_exporter_softirq_entry_latency_seconds_sum{kind="NET_RX_SOFTIRQ"} 16.282414
    ebpf_exporter_softirq_entry_latency_seconds_count{kind="NET_RX_SOFTIRQ"} 8.262708e+06
    ebpf_exporter_softirq_raised_total{kind="NET_RX_SOFTIRQ"} 8.275197e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1e-06"} 226218
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="2e-06"} 1.643431e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="4e-06"} 4.141819e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="8e-06"} 5.646346e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1.6e-05"} 6.952278e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="3.2e-05"} 8.055987e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="6.4e-05"} 8.239492e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000128"} 8.262601e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000256"} 8.266388e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.000512"} 8.267436e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.001024"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.002048"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.004096"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.008192"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.016384"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.032768"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.065536"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.131072"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.262144"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="0.524288"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="1.048576"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="2.097152"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_bucket{kind="NET_RX_SOFTIRQ",le="+Inf"} 8.267449e+06
    ebpf_exporter_softirq_service_latency_seconds_sum{kind="NET_RX_SOFTIRQ"} 130.717583
    ebpf_exporter_softirq_service_latency_seconds_count{kind="NET_RX_SOFTIRQ"} 8.267449e+06
    ebpf_exporter_softirq_serviced_total{kind="NET_RX_SOFTIRQ"} 8.26212e+06
  • Loading branch information
@bobrik
bobrik committed Oct 17, 2023
1 parent d50fbad commit 9aaefcd
Show file tree
Hide file tree
Showing 3 changed files with 250 additions and 0 deletions.
19 changes: 19 additions & 0 deletions examples/maps.bpf.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,3 +13,22 @@ static int increment_map(void *map, void *key, u64 increment)

return *count;
}

// Arrays are always preallocated, so this only fails if the key is missing
#define read_array_ptr(map, key, into) \
into = bpf_map_lookup_elem(map, key); \
if (!into) { \
return 0; \
}

#define increment_exp2_histogram(map, key, increment, max_bucket) \
key.bucket = log2l(increment); \
\
if (key.bucket > max_bucket) { \
key.bucket = max_bucket; \
} \
\
increment_map(map, &key, 1); \
\
key.bucket = max_bucket + 1; \
increment_map(map, &key, increment);
136 changes: 136 additions & 0 deletions examples/softirq-latency.bpf.c
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,136 @@
#include <vmlinux.h>
#include <bpf/bpf_tracing.h>
#include "bits.bpf.h"
#include "maps.bpf.h"

// Loosely based on https://github.com/xdp-project/xdp-project/blob/master/areas/latency/softirq_net_latency.bt

// 20 buckets for latency, max range is 0.5s .. 1.0s
#define MAX_LATENCY_SLOT 21

struct softirq_latency_key_t {
u32 kind;
u64 bucket;
};

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_ARRAY);
__uint(max_entries, NR_SOFTIRQS);
__type(key, u32);
__type(value, u64);
} softirq_raised_total SEC(".maps");

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_ARRAY);
__uint(max_entries, NR_SOFTIRQS);
__type(key, u32);
__type(value, u64);
} softirq_serviced_total SEC(".maps");

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_ARRAY);
__uint(max_entries, NR_SOFTIRQS);
__type(key, u32);
__type(value, u64);
} softirq_raise_timestamp SEC(".maps");

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_ARRAY);
__uint(max_entries, NR_SOFTIRQS);
__type(key, u32);
__type(value, u64);
} softirq_entry_timestamp SEC(".maps");

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_HASH);
__uint(max_entries, (MAX_LATENCY_SLOT + 1) * NR_SOFTIRQS);
__type(key, struct softirq_latency_key_t);
__type(value, u64);
} softirq_entry_latency_seconds SEC(".maps");

struct {
__uint(type, BPF_MAP_TYPE_PERCPU_HASH);
__uint(max_entries, (MAX_LATENCY_SLOT + 1) * NR_SOFTIRQS);
__type(key, struct softirq_latency_key_t);
__type(value, u64);
} softirq_service_latency_seconds SEC(".maps");

SEC("tp_btf/softirq_raise")
int BPF_PROG(softirq_raise, unsigned int vec_nr)
{
u64 *existing_ts_ptr, *raised_total_ptr, ts = bpf_ktime_get_ns();

read_array_ptr(&softirq_raised_total, &vec_nr, raised_total_ptr);
*raised_total_ptr += 1;

read_array_ptr(&softirq_raise_timestamp, &vec_nr, existing_ts_ptr);

// Set the timestamp only if it is not set, so that we always measure the oldest non-entered raise
if (!*existing_ts_ptr) {
*existing_ts_ptr = ts;
}

return 0;
}

SEC("tp_btf/softirq_entry")
int BPF_PROG(softirq_entry, unsigned int vec_nr)
{
u64 delta_us, *raise_ts_ptr, *existing_entry_ts_ptr, *serviced_total_ptr, ts = bpf_ktime_get_ns();
struct softirq_latency_key_t key = {};

read_array_ptr(&softirq_serviced_total, &vec_nr, serviced_total_ptr);
*serviced_total_ptr += 1;

read_array_ptr(&softirq_raise_timestamp, &vec_nr, raise_ts_ptr);

// Interrupt was re-rased after ts was obtained, resulting in negative duration
if (*raise_ts_ptr > ts) {
return 0;
}

// Interrupt entry started with no corresponding raise, resulting in large duration
if (!*raise_ts_ptr) {
return 0;
}

delta_us = (ts - *raise_ts_ptr) / 1000;

key.kind = vec_nr;

increment_exp2_histogram(&softirq_entry_latency_seconds, key, delta_us, MAX_LATENCY_SLOT);

// Allow raise timestamp to be set again
*raise_ts_ptr = 0;

read_array_ptr(&softirq_entry_timestamp, &vec_nr, existing_entry_ts_ptr);

// There is some time from function start to here, so overall service time includes it
*existing_entry_ts_ptr = ts;

return 0;
}

SEC("tp_btf/softirq_exit")
int BPF_PROG(softirq_exit, unsigned int vec_nr)
{
u64 delta_us, *entry_ts_ptr, ts = bpf_ktime_get_ns();
struct softirq_latency_key_t key = {};

read_array_ptr(&softirq_entry_timestamp, &vec_nr, entry_ts_ptr);

// Interrupt exited with no corresponding entry, resulting in large duration
if (!*entry_ts_ptr) {
return 0;
}

delta_us = (ts - *entry_ts_ptr) / 1000;

key.kind = vec_nr;

increment_exp2_histogram(&softirq_service_latency_seconds, key, delta_us, MAX_LATENCY_SLOT);

return 0;
}

char LICENSE[] SEC("license") = "GPL";
95 changes: 95 additions & 0 deletions examples/softirq-latency.yaml
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,95 @@
metrics:
histograms:
- name: softirq_entry_latency_seconds
help: Latency histogram for how long it takes from softirq raise to entry
bucket_type: exp2
bucket_min: 0
bucket_max: 21
bucket_multiplier: 0.000001 # nano to seconds
labels:
- name: kind
size: 8
decoders:
- name: uint
- name: static_map
static_map:
0: HI_SOFTIRQ
1: TIMER_SOFTIRQ
2: NET_TX_SOFTIRQ
3: NET_RX_SOFTIRQ
4: BLOCK_SOFTIRQ
5: IRQ_POLL_SOFTIRQ
6: TASKLET_SOFTIRQ
7: SCHED_SOFTIRQ
8: HRTIMER_SOFTIRQ
9: RCU_SOFTIRQ
- name: bucket
size: 8
decoders:
- name: uint
- name: softirq_service_latency_seconds
help: Latency histogram for how long it takes from softirq entry to exit
bucket_type: exp2
bucket_min: 0
bucket_max: 21
bucket_multiplier: 0.000001 # nano to seconds
labels:
- name: kind
size: 8
decoders:
- name: uint
- name: static_map
static_map:
0: HI_SOFTIRQ
1: TIMER_SOFTIRQ
2: NET_TX_SOFTIRQ
3: NET_RX_SOFTIRQ
4: BLOCK_SOFTIRQ
5: IRQ_POLL_SOFTIRQ
6: TASKLET_SOFTIRQ
7: SCHED_SOFTIRQ
8: HRTIMER_SOFTIRQ
9: RCU_SOFTIRQ
- name: bucket
size: 8
decoders:
- name: uint
counters:
- name: softirq_raised_total
help: Total number of times softirq were raised
labels:
- name: kind
size: 4
decoders:
- name: uint
- name: static_map
static_map:
0: HI_SOFTIRQ
1: TIMER_SOFTIRQ
2: NET_TX_SOFTIRQ
3: NET_RX_SOFTIRQ
4: BLOCK_SOFTIRQ
5: IRQ_POLL_SOFTIRQ
6: TASKLET_SOFTIRQ
7: SCHED_SOFTIRQ
8: HRTIMER_SOFTIRQ
9: RCU_SOFTIRQ
- name: softirq_serviced_total
help: Total number of times softirq were serviced
labels:
- name: kind
size: 4
decoders:
- name: uint
- name: static_map
static_map:
0: HI_SOFTIRQ
1: TIMER_SOFTIRQ
2: NET_TX_SOFTIRQ
3: NET_RX_SOFTIRQ
4: BLOCK_SOFTIRQ
5: IRQ_POLL_SOFTIRQ
6: TASKLET_SOFTIRQ
7: SCHED_SOFTIRQ
8: HRTIMER_SOFTIRQ
9: RCU_SOFTIRQ

0 comments on commit 9aaefcd

Please sign in to comment.