tracing/ftrace: Introduce the big kernel lock tracer

Introduce the Big Kernel Lock tracer.
This new tracer lets one to observe the latencies caused by the lock_kernel() function.
It captures the time when the task request the spinlock, the time when the spinlock is hold and the time it is released. This way we can measure the latency for a task that wait for this spinlock and the latency caused by the time this lock is hold.

I will surely add some improvements like:

_ Adding a stack trace to know which function locked or unlocked the kernel. _ Adding a script to get some statistics about this: which functions hold it often, which hold it for a long time and some other things....

Signed-off-by Frederic Weisbecker <[email protected]>

Cc Steven Rostedt <[email protected]>

---
 include/trace/bkl.h      |   29 ++++++++
 kernel/trace/Kconfig     |   11 +++
 kernel/trace/Makefile    |    1 +
 kernel/trace/trace.h     |   18 +++++
 kernel/trace/trace_bkl.c |  170 ++++++++++++++++++++++++++++++++++++++++++++++
 lib/kernel_lock.c        |   22 ++++++-
 6 files changed, 249 insertions(+), 2 deletions(-)

include/trace/bkl.h new file +29 -0

new file mode 100644
index 0000000..bed2f1b
@@ -0,0 +1,29 @@
+#ifndef _TRACE_BKL_H
+#define _TRACE_BKL_H
+
+
+/* Entry which log the time when the task tried first to acquire the bkl
+ * and the time when it acquired it.
+ * That will let us know the latency to acquire the kernel lock.
+ */
+struct bkl_trace_acquire {
+       unsigned long long acquire_req_time;
+       unsigned long long acquire_time;
+};
+
+/* This will log the time when the task released the bkl.
+ * So we will know the whole duration of its kernel lock.
+ */
+struct bkl_trace_release {
+       unsigned long long release_time;
+};
+
+#ifdef CONFIG_BKL_TRACER
+extern void trace_bkl_acquire(struct bkl_trace_acquire *trace);
+extern void trace_bkl_release(struct bkl_trace_release *trace);
+#else
+static void trace_bkl_acquire(struct bkl_trace_acquire *trace) { }
+static void trace_bkl_release(struct bkl_trace_release *trace) { }
+#endif
+
+#endif

kernel/trace/Kconfig +11 -0

index 396aea1..fde7700 100644
@@ -144,6 +144,17 @@ config STACK_TRACER
         This tracer records the max stack of the kernel, and displays
         it in debugfs/tracing/stack_trace
 
+config BKL_TRACER
+       bool "Trace Big Kernel Lock latencies"
+       depends on HAVE_FTRACE
+       depends on DEBUG_KERNEL
+       select FTRACE
+       select STACKTRACE
+       help
+         This tracer records the latencies issued by the Big Kernel Lock.
+         It traces the time when a task request the bkl, the time when it
+         acquires it and the time when it releases it.
+
 config DYNAMIC_FTRACE
       bool "enable/disable ftrace tracepoints dynamically"
       depends on FTRACE

kernel/trace/Makefile +1 -0

index a85dfba..2ba8904 100644
@@ -24,5 +24,6 @@ obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
 obj-$(CONFIG_BOOT_TRACER) += trace_boot.o
+obj-$(CONFIG_BKL_TRACER) += trace_bkl.o
 
 libftrace-y := ftrace.o

kernel/trace/trace.h +18 -0

index 707620c..b1df671 100644
@@ -8,6 +8,7 @@
 #include <linux/ring_buffer.h>
 #include <linux/mmiotrace.h>
 #include <linux/ftrace.h>
+#include <trace/bkl.h>
 
 enum trace_type {
       __TRACE_FIRST_TYPE = 0,

@@ -22,6 +23,8 @@ enum trace_type {
       TRACE_MMIO_RW,
       TRACE_MMIO_MAP,
       TRACE_BOOT,
+       TRACE_BKL_ACQ,
+       TRACE_BKL_REL,
 
       __TRACE_LAST_TYPE
 };

@@ -119,6 +122,17 @@ struct trace_boot {
       struct boot_trace       initcall;
 };
 
+/* Trace bkl entries */
+struct trace_bkl_acq {
+       struct trace_entry              ent;
+       struct bkl_trace_acquire        bkl_acq;
+};
+
+struct trace_bkl_rel {
+       struct trace_entry              ent;
+       struct bkl_trace_release        bkl_rel;
+};
+
 /*
 * trace_flag_type is an enumeration that holds different
 * states when a trace occurs. These are:

@@ -219,6 +233,10 @@ extern void __ftrace_bad_type(void);
               IF_ASSIGN(var, ent, struct trace_mmiotrace_map,         \
                         TRACE_MMIO_MAP);                              \
               IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT);     \
+               IF_ASSIGN(var, ent, struct trace_bkl_acq,               \
+                         TRACE_BKL_ACQ);                               \
+               IF_ASSIGN(var, ent, struct trace_bkl_rel,               \
+                         TRACE_BKL_REL);                               \
               __ftrace_bad_type();                                    \
       } while (0)
 

kernel/trace/trace_bkl.c new file +170 -0

new file mode 100644
index 0000000..169ee01
@@ -0,0 +1,170 @@
+/*
+ * Ring buffer based Big Kernel Lock tracer
+ * for purpose of measuring the latencies issued
+ * by the BKL.
+ *
+ * Copyright (C) 2008 Frederic Weisbecker <[email protected]>
+ */
+
+#include <trace/bkl.h>
+#include "trace.h"
+#include <linux/ftrace.h>
+
+
+static struct trace_array *bkl_trace;
+static bool bkl_tracer_enabled;
+
+
+static void bkl_trace_init(struct trace_array *tr)
+{
+       int cpu;
+       bkl_trace = tr;
+
+       for_each_cpu_mask(cpu, cpu_possible_map)
+               tracing_reset(tr, cpu);
+
+       if (tr->ctrl)
+               bkl_tracer_enabled = 1;
+}
+
+static void reset_bkl_trace(struct trace_array *tr)
+{
+       bkl_tracer_enabled = 0;
+}
+
+static void bkl_trace_ctrl_update(struct trace_array *tr)
+{
+       if (tr->ctrl)
+               bkl_tracer_enabled = 1;
+       else
+               bkl_tracer_enabled = 0;
+}
+
+static enum print_line_t bkl_acq_print_line(struct trace_iterator *iter)
+{
+       int ret;
+       struct trace_entry *entry = iter->ent;
+       struct trace_bkl_acq *field = (struct trace_bkl_acq *) entry;
+       struct bkl_trace_acquire *bta = &field->bkl_acq;
+       struct trace_seq *s = &iter->seq;
+       unsigned long sec, nsec_rem;
+       unsigned long long wait_for_spin;
+
+       wait_for_spin = bta->acquire_time - bta->acquire_req_time;
+       nsec_rem = do_div(bta->acquire_req_time, 1000000000);
+       sec = (unsigned long) bta->acquire_req_time;
+       ret = trace_seq_printf(s, "Kernel lock requested at %5lu.%09lu ",
+                                 sec, nsec_rem);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       nsec_rem = do_div(bta->acquire_time, 1000000000);
+       sec = (unsigned long) bta->acquire_time;
+       ret = trace_seq_printf(s, "acquired at %5lu.%09lu "
+                                 "(waited %llu nsecs)\n",
+                                 sec, nsec_rem,
+                                 wait_for_spin);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+       return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t bkl_rel_print_line(struct trace_iterator *iter)
+{
+       int ret;
+       struct trace_entry *entry = iter->ent;
+       struct trace_bkl_rel *field = (struct trace_bkl_rel *) entry;
+       struct bkl_trace_release *btr = &field->bkl_rel;
+       struct trace_seq *s = &iter->seq;
+       unsigned long sec, nsec_rem;
+
+       nsec_rem = do_div(btr->release_time, 1000000000);
+       sec = (unsigned long) btr->release_time;
+       ret = trace_seq_printf(s, "Kernel lock released at  %5lu.%09lu\n",
+                                 sec, nsec_rem);
+       return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t bkl_trace_print_line(struct trace_iterator *iter)
+{
+       struct trace_entry *entry = iter->ent;
+
+       if (entry->type == TRACE_BKL_ACQ)
+               return bkl_acq_print_line(iter);
+       if (entry->type == TRACE_BKL_REL)
+               return bkl_rel_print_line(iter);
+
+       return TRACE_TYPE_UNHANDLED;
+}
+
+static struct tracer bkl_tracer __read_mostly =
+{
+       .name           = "bkl",
+       .init           = bkl_trace_init,
+       .reset          = reset_bkl_trace,
+       .ctrl_update    = bkl_trace_ctrl_update,
+       .print_line     = bkl_trace_print_line,
+};
+
+__init static int init_bkl_tracer(void)
+{
+       return register_tracer(&bkl_tracer);
+}
+device_initcall(init_bkl_tracer);
+
+/*
+ * These functions don't need us to disable
+ * the preemption since it has been done by lock_kernel()
+ */
+
+void trace_bkl_acquire(struct bkl_trace_acquire *trace)
+{
+       struct ring_buffer_event *event;
+       struct trace_bkl_acq *entry;
+       struct trace_array_cpu *data;
+       unsigned long irq_flags;
+       struct trace_array *tr = bkl_trace;
+
+       if (!bkl_tracer_enabled)
+               return;
+
+       data = tr->data[smp_processor_id()];
+
+       event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
+                                        &irq_flags);
+       if (!event)
+               return;
+       entry   = ring_buffer_event_data(event);
+       tracing_generic_entry_update(&entry->ent, 0, 0);
+       entry->ent.type = TRACE_BKL_ACQ;
+       entry->bkl_acq = *trace;
+       ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
+
+       trace_wake_up();
+}
+
+void trace_bkl_release(struct bkl_trace_release *trace)
+{
+       struct ring_buffer_event *event;
+       struct trace_bkl_rel *entry;
+       struct trace_array_cpu *data;
+       unsigned long irq_flags;
+       struct trace_array *tr = bkl_trace;
+
+       if (!bkl_tracer_enabled)
+               return;
+
+       data = tr->data[smp_processor_id()];
+
+       event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
+                                        &irq_flags);
+       if (!event)
+               return;
+       entry   = ring_buffer_event_data(event);
+       tracing_generic_entry_update(&entry->ent, 0, 0);
+       entry->ent.type = TRACE_BKL_REL;
+       entry->bkl_rel = *trace;
+       ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
+
+       trace_wake_up();
+}

lib/kernel_lock.c +14 -2

index 01a3c22..9987834 100644
@@ -9,6 +9,7 @@
 #include <linux/module.h>
 #include <linux/kallsyms.h>
 #include <linux/semaphore.h>
+#include <trace/bkl.h>
 
 /*
 * The 'big kernel lock'

@@ -116,16 +117,33 @@ static inline void __unlock_kernel(void)
 void __lockfunc lock_kernel(void)
 {
       int depth = current->lock_depth+1;
-       if (likely(!depth))
+       if (likely(!depth)) {
+#ifdef CONFIG_BKL_TRACER
+               struct bkl_trace_acquire trace;
+               preempt_disable();
+               trace.acquire_req_time = cpu_clock(raw_smp_processor_id());
+               preempt_enable();
               __lock_kernel();
+               trace.acquire_time = cpu_clock(raw_smp_processor_id());
+               trace_bkl_acquire(&trace);
+#else
+               __lock_kernel();
+#endif
+       }
       current->lock_depth = depth;
 }
 
 void __lockfunc unlock_kernel(void)
 {
       BUG_ON(current->lock_depth < 0);
-       if (likely(--current->lock_depth < 0))
+       if (likely(--current->lock_depth < 0)) {

Are these last 15 days patches submitted to tip put in a wait queue because of the merge window? I hope that the reason for no comment on them is not because they stand in a total irrelevance...

Correct, we froze down for the merge window. Thawing it now :)

Quoted 8 lines

Introduce the Big Kernel Lock tracer.
This new tracer lets one to observe the latencies caused by the lock_kernel() function.
It captures the time when the task request the spinlock, the time when the spinlock is hold and the time it is released. This way we can measure the latency for a task that wait for this spinlock and the latency caused by the time this lock is hold.

For comparison, this is how this sort of analysis may be done with systemtap, just for fun collecting locking latency on a per-locker/unlocker (stack traceback) basis. We don't have the stack traceback extended right into userspace yet, but will before too long.

% cat bkl.stp
probe kernel.function("lock_kernel") {
locker=backtrace()
locktime=gettimeofday_us()
}

probe kernel.function("lock_kernel").return {
unlocktime=gettimeofday_us()
delay = unlocktime-locktime
lockhistory[locker,unlocker] <<< delay
}

probe kernel.function("unlock_kernel") {
unlocker=backtrace()
}

global locker, unlocker, locktime, lockhistory

probe end,timer.s(30) { // interrupt any time; automatic ending in 30s
foreach ([l,u] in lockhistory+) { // in increasing order of @count()

println("locker:") print_stack (l) println("unlocker:") print_stack (u)

println(@hist_log (lockhistory[l,u]))

if (@max (lockhistory[l,u]) > 100)
println("--- holy cow, that can take a long time ---")
}
exit()
}

% sudo stap bkl.stp
[...]
locker:
0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel] 0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel] 0xffffffff811b067b : write_chan+0x273/0x338 [kernel] 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel] 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel] 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel] 0x00000ffffffff810
unlocker:
0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel] 0xffffffff811b064e : write_chan+0x246/0x338 [kernel] 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel] 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel] 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel] 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel] 0x00000fffffffff7f
value |-------------------------------------------------- count

   0 |                                                     3
   1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    570
   2 |@@@@@@@@@@@@@                                      159
   4 |                                                     9
   8 |@                                                   16
  16 |                                                     3
  32 |@@                                                  35
  64 |                                                     5
 128 |                                                     0
 256 |                                                     0

locker:
0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel] 0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel] 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel] 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel] 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel] 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel] 0x00000fffffffff7f
unlocker:
0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel] 0xffffffff811b064e : write_chan+0x246/0x338 [kernel] 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel] 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel] 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel] 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel] 0x00000fffffffff7f
value |-------------------------------------------------- count

   0 |                                                     0
   1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      454
   2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  497
   4 |@@                                                  21
   8 |@                                                   15
  16 |                                                     1
  32 |@@@                                                 33
  64 |                                                     2
 128 |                                                     0
 256 |                                                     0

NB: Observed lock times in the 1-2 us range indicate no contention, as that's on the order of magnitude of the (un)lock_kernel kprobe overheads.

Quoted 2 lines

[...] For comparison, this is how this sort of analysis may be done with systemtap [...]

That's a great and powerful tool.

But just one sorrow:
I just think that's a pity that we have to use/learn a new scripting language to use it.

I would rather prefer to use an API that provides functions/objects for most common scripting languages.

Hi -

Quoted 8 lines · Fr?d?ric Weisbecker

Quoted 2 lines

[...] For comparison, this is how this sort of analysis may be done with systemtap [...]

That's a great and powerful tool.

But just one sorrow:
I just think that's a pity that we have to use/learn a new scripting language to use it.

I understand.

Quoted 2 lines

I would rather prefer to use an API that provides functions/objects for most common scripting languages.

That is an interesting idea. One possible problem is that the final complete script "program" needs to be translated to something that can run quickly and safely inside the kernel. Full python or perl runtime
+ libraries would have been almost certainly unbearable.

[...]

Quoted 7 lines

Quoted 2 lines

I would rather prefer to use an API that provides functions/objects for most common scripting languages.

That is an interesting idea. One possible problem is that the final complete script "program" needs to be translated to something that can run quickly and safely inside the kernel. Full python or perl runtime
+ libraries would have been almost certainly unbearable.

Why can't the userspace application convert the script to something easy that the kernel can handle?

But have the user application interface be very simple, and perhaps even use perl or python.

That's what we do with the systemtap script, where kernel "handling" consists of "running the machine code".

Quoted 2 lines

But have the user application interface be very simple, and perhaps even use perl or python.

perl and python are pretty big procedural languages, and are not easily compiled down to compact & quickly executed machine code. (I take it no one is suggesting including a perl or python VM in the kernel.) Plus, debugger-flavoured event-handling programming style would not look nearly as compact in perl/python as in systemtap, which is small and domain-specific.

- FChE

[...]
Actually what I thought is a style like this (Python like):

probe = Systemtap.probeFunc("lock_kernel")
probe.captureUtime("utime"))
probe.captureBacktrace("trace")
probe.trace()

For an obvious set of batch work like that, that could be possible, perhaps even easy to implement an Api...
When the object calls trace(), the userspace Systemtap analyse the list of work to do and then translate into commands in kernel space.

And the script could wait for events and then do its own processing with the captured events (do some operations on delays, on output....).

for event in probe.getEvent(): #blocking
print event["utime"]
trace = event["trace"] #Systemtap.trace object with specific
fields and a default string repr
print trace

It would be interpreted by Python itself [...]

2008/10/24 Frank Ch. Eigler <[email protected]>:

Quoted 11 lines

That's what we do with the systemtap script, where kernel "handling" consists of "running the machine code".

Quoted 2 lines

But have the user application interface be very simple, and perhaps even use perl or python.

perl and python are pretty big procedural languages, and are not easily compiled down to compact & quickly executed machine code. (I take it no one is suggesting including a perl or python VM in the kernel.) Plus, debugger-flavoured event-handling programming style would not look nearly as compact in perl/python as in systemtap,

which

Quoted 4 lines

is small and domain-specific.

- FChE

Actually what I thought is a style like this (Python like):

probe = Systemtap.probeFunc("lock_kernel")
probe.captureUtime("utime"))
probe.captureBacktrace("trace")
probe.trace()

For an obvious set of batch work like that, that could be possible, perhaps even easy
to implement an Api...
When the object calls trace(), the userspace Systemtap analyse the list
of work to do and then translate into commands in kernel space.

And the script could wait for events and then do its own processing with the captured events
(do some operations on delays, on output....).

for event in probe.getEvent(): #blocking
print event["utime"]
trace = event["trace"] #Systemtap.trace object with specific fields and a default string repr
print trace

It would be interpreted by Python itself, and you just have to capture commands and works
sent through Api. Then, when the kernel has something to give, you just have to place it in the
appripriate object and transmit it to the script which is waiting. Processing and output with the data are done by the python script. So actually, the python script only needs to ask you what data to capture. It's its own responsability to
do wathever it wants with.

What do you think?