From: Steven Rostedt <[email protected]>
While debugging something with the function_graph tracer, I found the
need to see the preempt count of the traces. Unfortunately, since
the function graph tracer has its own output formatting, it does not
honor the latency-format option.
This patch makes the function_graph tracer honor the latency-format
option, but still keeps control of the output. But now we have the
same details that the latency-format supplies.
# tracer: function_graph
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# ||||
# CPU|||| DURATION FUNCTION CALLS
# | |||| | | | | | |
3) d..1 1.333 us | idle_cpu();
3) d.h1 | tick_check_idle() {
3) d.h1 0.550 us | tick_check_oneshot_broadcast();
3) d.h1 | tick_nohz_stop_idle() {
3) d.h1 | ktime_get() {
3) d.h1 | ktime_get_ts() {
Signed-off-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace_functions_graph.c | 74 +++++++++++++++++++++++++++++++---
1 files changed, 68 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index b3749a2..ee791a9 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -364,6 +364,29 @@ print_graph_proc(struct trace_seq *s, pid_t pid)
}
+static enum print_line_t
+print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
+{
+ int hardirq, softirq;
+
+ hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
+ softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
+
+ if (!trace_seq_printf(s, " %c%c%c",
+ (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
+ (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
+ 'X' : '.',
+ (entry->flags & TRACE_FLAG_NEED_RESCHED) ?
+ 'N' : '.',
+ (hardirq && softirq) ? 'H' :
+ hardirq ? 'h' : softirq ? 's' : '.'))
+ return 0;
+
+ if (entry->preempt_count)
+ return trace_seq_printf(s, "%x", entry->preempt_count);
+ return trace_seq_puts(s, ".");
+}
+
/* If the pid changed since the last trace, output this event */
static enum print_line_t
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
@@ -521,6 +544,7 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
}
+
/* Proc */
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
ret = print_graph_proc(s, pid);
@@ -758,6 +782,13 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
+ /* Latency format */
+ if (trace_flags & TRACE_ITER_LATENCY_FMT) {
+ ret = print_graph_lat_fmt(s, ent);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+
return 0;
}
@@ -952,28 +983,59 @@ print_graph_function(struct trace_iterator *iter)
return TRACE_TYPE_HANDLED;
}
+static void print_lat_header(struct seq_file *s)
+{
+ static const char spaces[] = " " /* 16 spaces */
+ " " /* 4 spaces */
+ " "; /* 17 spaces */
+ int size = 0;
+
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
+ size += 16;
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
+ size += 4;
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
+ size += 17;
+
+ seq_printf(s, "#%.*s _-----=> irqs-off \n", size, spaces);
+ 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);
+}
+
static void print_graph_headers(struct seq_file *s)
{
+ int lat = trace_flags & TRACE_ITER_LATENCY_FMT;
+
+ if (lat)
+ print_lat_header(s);
+
/* 1st line */
- seq_printf(s, "# ");
+ seq_printf(s, "#");
if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
seq_printf(s, " TIME ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
- seq_printf(s, "CPU");
+ seq_printf(s, " CPU");
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
- seq_printf(s, " TASK/PID ");
+ seq_printf(s, " TASK/PID ");
+ if (lat)
+ seq_printf(s, "||||");
if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " DURATION ");
seq_printf(s, " FUNCTION CALLS\n");
/* 2nd line */
- seq_printf(s, "# ");
+ seq_printf(s, "#");
if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
seq_printf(s, " | ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
- seq_printf(s, "| ");
+ seq_printf(s, " | ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
- seq_printf(s, " | | ");
+ seq_printf(s, " | | ");
+ if (lat)
+ seq_printf(s, "||||");
if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " | | ");
seq_printf(s, " | | | |\n");
--
1.6.3.3
--
On Fri, Sep 11, 2009 at 09:54:55AM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <[email protected]>
>
> While debugging something with the function_graph tracer, I found the
> need to see the preempt count of the traces. Unfortunately, since
> the function graph tracer has its own output formatting, it does not
> honor the latency-format option.
>
> This patch makes the function_graph tracer honor the latency-format
> option, but still keeps control of the output. But now we have the
> same details that the latency-format supplies.
>
> # tracer: function_graph
> #
> # _-----=> irqs-off
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| /
> # ||||
> # CPU|||| DURATION FUNCTION CALLS
> # | |||| | | | | | |
> 3) d..1 1.333 us | idle_cpu();
> 3) d.h1 | tick_check_idle() {
> 3) d.h1 0.550 us | tick_check_oneshot_broadcast();
> 3) d.h1 | tick_nohz_stop_idle() {
> 3) d.h1 | ktime_get() {
> 3) d.h1 | ktime_get_ts() {
>
> Signed-off-by: Steven Rostedt <[email protected]>
Great!! Thanks a lot!
That was in my todo list :-)
Oh, BTW, what would you think about addding the current->lock_depth
in the latency format? That may help debug the bkl...
On Fri, 2009-09-11 at 16:55 +0200, Frederic Weisbecker wrote:
> Oh, BTW, what would you think about addding the current->lock_depth
> in the latency format? That may help debug the bkl...
Hmm, that would require adding another field for all traces. I don't
want to increase the size of an entry unneeded. BTW, this is for all
entries (even events).
Ug! I just noticed that tgid was added to struct trace_entry, with the
only user as the user stack entry. This should be in the user stack
field not something that goes into every event!
I guess I need to fix that too.
Well, maybe replacing tgid with lock_depth may not be a bad idea after
all.
-- Steve
On Fri, Sep 11, 2009 at 11:11:56AM -0400, Steven Rostedt wrote:
> On Fri, 2009-09-11 at 16:55 +0200, Frederic Weisbecker wrote:
>
> > Oh, BTW, what would you think about addding the current->lock_depth
> > in the latency format? That may help debug the bkl...
>
> Hmm, that would require adding another field for all traces. I don't
> want to increase the size of an entry unneeded. BTW, this is for all
> entries (even events).
Right...
> Ug! I just noticed that tgid was added to struct trace_entry, with the
> only user as the user stack entry. This should be in the user stack
> field not something that goes into every event!
>
> I guess I need to fix that too.
>
> Well, maybe replacing tgid with lock_depth may not be a bad idea after
> all.
Yeah, would be nice. This would be an interesting general purpose
field.
On 2009-09-11 18:18, Frederic Weisbecker wrote:
> On Fri, Sep 11, 2009 at 11:11:56AM -0400, Steven Rostedt wrote:
>
>> On Fri, 2009-09-11 at 16:55 +0200, Frederic Weisbecker wrote:
>>
>>
>>> Oh, BTW, what would you think about addding the current->lock_depth
>>> in the latency format? That may help debug the bkl...
>>>
>> Hmm, that would require adding another field for all traces. I don't
>> want to increase the size of an entry unneeded. BTW, this is for all
>> entries (even events).
>>
>
>
> Right...
>
>
>
>> Ug! I just noticed that tgid was added to struct trace_entry, with the
>> only user as the user stack entry. This should be in the user stack
>> field not something that goes into every event!
>>
>> I guess I need to fix that too.
>>
Indeed tgid should be part of struct userstack_entry, and set in
ftrace_trace_userstack.
Do you want to me to write up a patch for that, or have you already
fixed it?
Best regards,
--Edwin
On Fri, Sep 11, 2009 at 06:38:10PM +0300, T?r?k Edwin wrote:
> On 2009-09-11 18:18, Frederic Weisbecker wrote:
> > On Fri, Sep 11, 2009 at 11:11:56AM -0400, Steven Rostedt wrote:
> >
> >> On Fri, 2009-09-11 at 16:55 +0200, Frederic Weisbecker wrote:
> >>
> >>
> >>> Oh, BTW, what would you think about addding the current->lock_depth
> >>> in the latency format? That may help debug the bkl...
> >>>
> >> Hmm, that would require adding another field for all traces. I don't
> >> want to increase the size of an entry unneeded. BTW, this is for all
> >> entries (even events).
> >>
> >
> >
> > Right...
> >
> >
> >
> >> Ug! I just noticed that tgid was added to struct trace_entry, with the
> >> only user as the user stack entry. This should be in the user stack
> >> field not something that goes into every event!
> >>
> >> I guess I need to fix that too.
> >>
>
> Indeed tgid should be part of struct userstack_entry, and set in
> ftrace_trace_userstack.
> Do you want to me to write up a patch for that, or have you already
> fixed it?
>
> Best regards,
> --Edwin
No, please do.
Thanks!
On Fri, 2009-09-11 at 18:38 +0300, T?r?k Edwin wrote:
> On 2009-09-11 18:18, Frederic Weisbecker wrote:
> > On Fri, Sep 11, 2009 at 11:11:56AM -0400, Steven Rostedt wrote:
>
> >> Ug! I just noticed that tgid was added to struct trace_entry, with the
> >> only user as the user stack entry. This should be in the user stack
> >> field not something that goes into every event!
> >>
> >> I guess I need to fix that too.
> >>
>
> Indeed tgid should be part of struct userstack_entry, and set in
> ftrace_trace_userstack.
> Do you want to me to write up a patch for that, or have you already
> fixed it?
I've just fixed it, thanks!
-- Steve
On 2009-09-11 18:50, Steven Rostedt wrote:
> On Fri, 2009-09-11 at 18:38 +0300, T?r?k Edwin wrote:
>
>> On 2009-09-11 18:18, Frederic Weisbecker wrote:
>>
>>> On Fri, Sep 11, 2009 at 11:11:56AM -0400, Steven Rostedt wrote:
>>>
>>
>>
>>>> Ug! I just noticed that tgid was added to struct trace_entry, with the
>>>> only user as the user stack entry. This should be in the user stack
>>>> field not something that goes into every event!
>>>>
>>>> I guess I need to fix that too.
>>>>
>>>>
>> Indeed tgid should be part of struct userstack_entry, and set in
>> ftrace_trace_userstack.
>> Do you want to me to write up a patch for that, or have you already
>> fixed it?
>>
>
> I've just fixed it, thanks!
Ok.
BTW any plans on integrating an in-kernel unwinder like systemtap has?
Even if I build libc with framepointers, a userspace stacktrace on
x86-64 can't go beyond most pthreads routines, like __read_nocancel
(they're written in asm maybe?).
Best regards,
--Edwin
On Fri, Sep 11, 2009 at 07:08:00PM +0300, T?r?k Edwin wrote:
>
> BTW any plans on integrating an in-kernel unwinder like systemtap has?
>
> Even if I build libc with framepointers, a userspace stacktrace on
> x86-64 can't go beyond most pthreads routines, like __read_nocancel
> (they're written in asm maybe?).
>
fyi SH has an in-kernel DWARF unwinder. It was my intention to shake out
most of the bugs (of which there have been a few) by having it in the SH
tree and then submit it for generic inclusion.
So by carefully placing .cfi_* directives in assembly, you can get
stacktraces for assembly routines in the kernel.
The branch containing the latest code is here,
http://git.kernel.org/?p=linux/kernel/git/lethal/sh-2.6.git;a=shortlog;h=sh/dwarf-unwinder