tracing: add lock depth to entries
This patch adds the lock depth of the big kernel lock to the generic
entry header. This way we can see the depth of the lock and help
in removing the BKL.
Example:
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| /_--=> lock-depth
# |||||/ delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
<idle>-0 2.N..3 5902255250us+: lock_acquire: read rcu_read_lock
<idle>-0 2.N..3 5902255253us+: lock_release: rcu_read_lock
<idle>-0 2dN..3 5902255257us+: lock_acquire: xtime_lock
<idle>-0 2dN..4 5902255259us : lock_acquire: clocksource_lock
<idle>-0 2dN..4 5902255261us+: lock_release: clocksource_lock
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 1a37da2..3b91828 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -886,6 +886,7 @@
entry->preempt_count = pc & 0xff;
entry->pid = (tsk) ? tsk->pid : 0;
+ entry->lock_depth = (tsk) ? tsk->lock_depth : 0;
entry->flags =
#ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT
(irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
@@ -1530,10 +1531,10 @@
seq_puts(m, "# | / _----=> need-resched \n");
seq_puts(m, "# || / _---=> hardirq/softirq \n");
seq_puts(m, "# ||| / _--=> preempt-depth \n");
- seq_puts(m, "# |||| / \n");
- seq_puts(m, "# ||||| delay \n");
- seq_puts(m, "# cmd pid ||||| time | caller \n");
- seq_puts(m, "# \\ / ||||| \\ | / \n");
+ seq_puts(m, "# |||| /_--=> lock-depth \n");
+ seq_puts(m, "# |||||/ delay \n");
+ seq_puts(m, "# cmd pid |||||| time | caller \n");
+ seq_puts(m, "# \\ / |||||| \\ | / \n");
}
static void print_func_help_header(struct seq_file *m)
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 28d9202..975f324 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -86,6 +86,7 @@
__common_field(unsigned char, flags);
__common_field(unsigned char, preempt_count);
__common_field(int, pid);
+ __common_field(int, lock_depth);
return ret;
}
@@ -571,11 +572,13 @@
"\tfield:%s %s;\toffset:%zu;\tsize:%zu;\n"
"\tfield:%s %s;\toffset:%zu;\tsize:%zu;\n"
"\tfield:%s %s;\toffset:%zu;\tsize:%zu;\n"
+ "\tfield:%s %s;\toffset:%zu;\tsize:%zu;\n"
"\n",
FIELD(unsigned short, type),
FIELD(unsigned char, flags),
FIELD(unsigned char, preempt_count),
- FIELD(int, pid));
+ FIELD(int, pid),
+ FIELD(int, lock_depth));
}
static ssize_t
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index ee791a9..48af493 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -368,6 +368,7 @@
print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
{
int hardirq, softirq;
+ int ret;
hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
@@ -382,6 +383,13 @@
hardirq ? 'h' : softirq ? 's' : '.'))
return 0;
+ if (entry->lock_depth < 0)
+ ret = trace_seq_putc(s, '.');
+ else
+ ret = trace_seq_printf(s, "%d", entry->lock_depth);
+ if (!ret)
+ return 0;
+
if (entry->preempt_count)
return trace_seq_printf(s, "%x", entry->preempt_count);
return trace_seq_puts(s, ".");
@@ -1001,8 +1009,8 @@
seq_printf(s, "#%.*s / _----=> need-resched \n", size, spaces);
seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
seq_printf(s, "#%.*s|| / _--=> preempt-depth \n", size, spaces);
- seq_printf(s, "#%.*s||| / \n", size, spaces);
- seq_printf(s, "#%.*s|||| \n", size, spaces);
+ seq_printf(s, "#%.*s||| / _-=> lock-depth \n", size, spaces);
+ seq_printf(s, "#%.*s|||| / \n", size, spaces);
}
static void print_graph_headers(struct seq_file *s)
@@ -1021,7 +1029,7 @@
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " TASK/PID ");
if (lat)
- seq_printf(s, "||||");
+ seq_printf(s, "|||||");
if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " DURATION ");
seq_printf(s, " FUNCTION CALLS\n");
@@ -1035,7 +1043,7 @@
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " | | ");
if (lat)
- seq_printf(s, "||||");
+ seq_printf(s, "|||||");
if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " | | ");
seq_printf(s, " | | | |\n");
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index be34a6a..29a370a 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -465,6 +465,7 @@
{
int hardirq, softirq;
char comm[TASK_COMM_LEN];
+ int ret;
trace_find_cmdline(entry->pid, comm);
hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
@@ -481,9 +482,16 @@
hardirq ? 'h' : softirq ? 's' : '.'))
return 0;
+ if (entry->lock_depth < 0)
+ ret = trace_seq_putc(s, '.');
+ else
+ ret = trace_seq_printf(s, "%d", entry->lock_depth);
+ if (!ret)
+ return 0;
+
if (entry->preempt_count)
return trace_seq_printf(s, "%x", entry->preempt_count);
- return trace_seq_puts(s, ".");
+ return trace_seq_putc(s, '.');
}
static unsigned long preempt_mark_thresh = 100;
