Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints

[Daniel Wagner]

It is possible to avoid the hackery from patch 4 completely.
If the tracepoint is placed in stop_critical_timing(),
lockdep doesn't complain anymore.

I have changed this patch so that I don't do need to any additional
work to get the latency calculated. Instead just use the values
from check_critical_timing().

That means the tracepoints will only be hit if the tracer
preemptirqsoff & co is enabled. Instead having several
different tracepoints just add the a new field which describes where
the latency is coming from. Furthermore, this approach also avoids
adding additional overhead when the tracers are compiled in but
not used.

# cat /sys/kernel/debug/tracing/events/latency/latency/format 
name: latency
ID: 333
format:
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
        field:int common_pid;   offset:4;       size:4; signed:1;

        field:int source;       offset:8;       size:4; signed:1;
        field:cycles_t latency; offset:16;      size:8; signed:0;

print fmt: "source=%s latency=%llu", __print_symbolic(REC->source, {1, "critical section" }, {2, "irq"}, {3, "preempt"}), REC->latency


So in short you could do following to get a histogram:

# echo preemptirqsoff > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /sys/kernel/debug/tracing/tracing_on
# echo 'hist:key=latency.bucket:val=hitcount:sort=latency '	\
	'if source == 1' > 					\
	/sys/kernel/debug/tracing/events/latency/latency/trigger

# cat /sys/kernel/debug/tracing/events/latency/latency/hist | head -20
# trigger info: hist:keys=latency.bucket:vals=:sort=latency.bucket:size=2048 if source == 1 [active]

latency:       1792 hitcount:          7
latency:       2048 hitcount:         23
latency:       2304 hitcount:         37
latency:       2560 hitcount:         57
latency:       2816 hitcount:         33
latency:       3072 hitcount:         40
latency:       3328 hitcount:         16
latency:       3584 hitcount:         40
latency:       3840 hitcount:        133
latency:       4096 hitcount:        150
latency:       4352 hitcount:        196
latency:       4608 hitcount:        338
latency:       4864 hitcount:        159
latency:       5120 hitcount:         92
latency:       5376 hitcount:         58
latency:       5632 hitcount:         26
latency:       5888 hitcount:         25
latency:       6144 hitcount:         24


I do some more testing to see if I missed something.

cheers,
daniel