[PATCH 0/3] [GIT PULL] tracing: various updates

[PATCH 0/3] [GIT PULL] tracing: various updates

[Steven Rostedt]

Ingo,

Note, this is bassed off of my last pull request of tip/tracing/core.

Please pull the latest tip/tracing/core2 tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/core2


Steven Rostedt (3):
      x86/tracing: comment need for atomic nop
      tracing/profile: add ref count for registering profile events
      tracing: add latency format to function_graph tracer

----
 arch/x86/include/asm/nops.h          |    2 +
 include/trace/ftrace.h               |   22 +++++++++-
 kernel/trace/trace_functions_graph.c |   74 +++++++++++++++++++++++++++++++---
 3 files changed, 90 insertions(+), 8 deletions(-)
-- 

[PATCH 1/3] x86/tracing: comment need for atomic nop

[Steven Rostedt]

[-- Attachment #1: 0001-x86-tracing-comment-need-for-atomic-nop.patch --]
[-- Type: text/plain, Size: 1101 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The dynamic function tracer relys on the macro P6_NOP5 always being
an atomic NOP. If for some reason it is changed to be two operations
(like a nop2 nop3) it can faults within the kernel when the function
tracer modifies the code.

This patch adds a comment to note that the P6_NOPs are expected to
be atomic. This will hopefully prevent anyone from changing that.

Reported-by: Mathieu Desnoyer <mathieu.desnoyers@polymtl.ca>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 arch/x86/include/asm/nops.h |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/arch/x86/include/asm/nops.h b/arch/x86/include/asm/nops.h
index ad2668e..6d8723a 100644
--- a/arch/x86/include/asm/nops.h
+++ b/arch/x86/include/asm/nops.h
@@ -65,6 +65,8 @@
    6: osp nopl 0x00(%eax,%eax,1)
    7: nopl 0x00000000(%eax)
    8: nopl 0x00000000(%eax,%eax,1)
+   Note: All the above are assumed to be a single instruction.
+	There is kernel code that depends on this.
 */
 #define P6_NOP1	GENERIC_NOP1
 #define P6_NOP2	".byte 0x66,0x90\n"
-- 
1.6.3.3

-- 

[PATCH 2/3] tracing/profile: add ref count for registering profile events

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-profile-add-ref-count-for-registering-profil.patch --]
[-- Type: text/plain, Size: 2314 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Li Zefan discovered that doing the following:

 # insmod trace-events-sample.ko
 # perf record -f -a -e sample:foo_bar sleep 3 &
 # sleep 1
 # rmmod trace_events_sample
 # insmod trace-events-sample.ko

Would cause an OOPS. This was because the registering of the profiler
registers inside the module and does not unregister when unloaded.

This patch adds an increment of the module refcount when a profile
registers a tracepoint, to prevent a module from being unloaded
while being profiled.

Reported-by: Li Zefan <lizf@cn.fujitsu.com>
LKML-Reference: <4A9214E3.2070807@cn.fujitsu.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/ftrace.h |   22 ++++++++++++++++++++--
 1 files changed, 20 insertions(+), 2 deletions(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 308bafd..59e09f9 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -400,6 +400,20 @@ static inline int ftrace_get_offsets_##call(				\
  *
  */
 
+#ifdef MODULE
+# define event_trace_up_ref()					\
+	do {							\
+		if (!try_module_get(THIS_MODULE)) {		\
+			atomic_dec(&event_call->profile_count);	\
+			return -ENOENT;				\
+		}						\
+	} while (0)
+# define event_trace_down_ref() module_put(THIS_MODULE)
+#else
+# define event_trace_up_ref() do { } while (0)
+# define event_trace_down_ref() do { } while (0)
+#endif
+
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
 									\
@@ -409,16 +423,20 @@ static int ftrace_profile_enable_##call(struct ftrace_event_call *event_call) \
 {									\
 	int ret = 0;							\
 									\
-	if (!atomic_inc_return(&event_call->profile_count))		\
+	if (!atomic_inc_return(&event_call->profile_count)) {		\
+		event_trace_up_ref();					\
 		ret = register_trace_##call(ftrace_profile_##call);	\
+	}								\
 									\
 	return ret;							\
 }									\
 									\
 static void ftrace_profile_disable_##call(struct ftrace_event_call *event_call)\
 {									\
-	if (atomic_add_negative(-1, &event_call->profile_count))	\
+	if (atomic_add_negative(-1, &event_call->profile_count)) {	\
 		unregister_trace_##call(ftrace_profile_##call);		\
+		event_trace_down_ref();					\
+	}								\
 }
 
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
-- 
1.6.3.3

-- 

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Peter Zijlstra]

On Fri, 2009-09-11 at 09:54 -0400, Steven Rostedt wrote:

> +#ifdef MODULE
> +# define event_trace_up_ref()					\
> +	do {							\
> +		if (!try_module_get(THIS_MODULE)) {		\
> +			atomic_dec(&event_call->profile_count);	\
> +			return -ENOENT;				\
> +		}						\
> +	} while (0)
> +# define event_trace_down_ref() module_put(THIS_MODULE)
> +#else
> +# define event_trace_up_ref() do { } while (0)
> +# define event_trace_down_ref() do { } while (0)
> +#endif

That's like truely gruesomely ugly.

At the very least write it like:

int event_trace_up_ref(struct ftrace_event_call *call)
{
	if (!try_module_get(THIS_MODULE)) {
		atomic_dev(&call->profile_count);
		return -ENOENT;
	}
	return 0;
}

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Peter Zijlstra]

On Fri, 2009-09-11 at 16:04 +0200, Peter Zijlstra wrote:
> On Fri, 2009-09-11 at 09:54 -0400, Steven Rostedt wrote:
> 
> > +#ifdef MODULE
> > +# define event_trace_up_ref()					\
> > +	do {							\
> > +		if (!try_module_get(THIS_MODULE)) {		\
> > +			atomic_dec(&event_call->profile_count);	\
> > +			return -ENOENT;				\
> > +		}						\
> > +	} while (0)
> > +# define event_trace_down_ref() module_put(THIS_MODULE)
> > +#else
> > +# define event_trace_up_ref() do { } while (0)
> > +# define event_trace_down_ref() do { } while (0)
> > +#endif
> 
> That's like truely gruesomely ugly.
> 
> At the very least write it like:
> 
> int event_trace_up_ref(struct ftrace_event_call *call)
> {
> 	if (!try_module_get(THIS_MODULE)) {
> 		atomic_dev(&call->profile_count);
> 		return -ENOENT;
> 	}
> 	return 0;
> }

Or we can go with Li's original patch, that was less ugly.

I still think tracepoints/markers should sort this out, because we now
have a sematic difference between the two wrt modules.

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Steven Rostedt]

On Fri, 2009-09-11 at 16:09 +0200, Peter Zijlstra wrote:
> On Fri, 2009-09-11 at 16:04 +0200, Peter Zijlstra wrote:
> > On Fri, 2009-09-11 at 09:54 -0400, Steven Rostedt wrote:
> > 
> > > +#ifdef MODULE
> > > +# define event_trace_up_ref()					\
> > > +	do {							\
> > > +		if (!try_module_get(THIS_MODULE)) {		\
> > > +			atomic_dec(&event_call->profile_count);	\
> > > +			return -ENOENT;				\
> > > +		}						\
> > > +	} while (0)
> > > +# define event_trace_down_ref() module_put(THIS_MODULE)
> > > +#else
> > > +# define event_trace_up_ref() do { } while (0)
> > > +# define event_trace_down_ref() do { } while (0)
> > > +#endif
> > 
> > That's like truely gruesomely ugly.
> > 
> > At the very least write it like:
> > 
> > int event_trace_up_ref(struct ftrace_event_call *call)
> > {
> > 	if (!try_module_get(THIS_MODULE)) {
> > 		atomic_dev(&call->profile_count);
> > 		return -ENOENT;
> > 	}
> > 	return 0;
> > }
> 
> Or we can go with Li's original patch, that was less ugly.

I can go back to Li's original patch, but the talk on that was
"fragile". If you no longer feel that way, then I'll use his instead.

For now, I'll pull out this patch altogether, and resubmit the pull
request without it. I'd like the other changes to not be held up by
this.

> 
> I still think tracepoints/markers should sort this out, because we now
> have a sematic difference between the two wrt modules.

I originally tried to do it in the tracepoint logic, but that broke a
lot of assumptions about tracepoints that Mathieu pointed out. This is
not a normal use of tracepoints. It is expected that if you register a
probe in a module, you will unregister it before exiting.

I can't remember all the details, but at the end, it seemed that the fix
belonged at the ftrace level.

-- Steve

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Peter Zijlstra]

On Fri, 2009-09-11 at 10:33 -0400, Steven Rostedt wrote:
> > Or we can go with Li's original patch, that was less ugly.
> 
> I can go back to Li's original patch, but the talk on that was
> "fragile". If you no longer feel that way, then I'll use his instead.
> 
> For now, I'll pull out this patch altogether, and resubmit the pull
> request without it. I'd like the other changes to not be held up by
> this.

Right, I still think its at the wrong level,. see below.

> > 
> > I still think tracepoints/markers should sort this out, because we now
> > have a sematic difference between the two wrt modules.
> 
> I originally tried to do it in the tracepoint logic, but that broke a
> lot of assumptions about tracepoints that Mathieu pointed out. This is
> not a normal use of tracepoints. It is expected that if you register a
> probe in a module, you will unregister it before exiting.
> 
> I can't remember all the details, but at the end, it seemed that the fix
> belonged at the ftrace level.

Right, Mathieu thinks its sane to be able to attach to
tracepoints/markers before they exist, so you can put them in module
init code. I disagree.

ftrace doesn't mirror this behaviour, that is the source of the problem.
If it did the ftrace structures wouldn't go away on unload and there
wouldn't be no crash.

But if you want to maintain this disparity between the two frameworks
then yes Li's patch, or yours (they're identical) seems the way to solve
it.

Still think its daft though.

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Steven Rostedt]

On Fri, 2009-09-11 at 16:37 +0200, Peter Zijlstra wrote:

> > I originally tried to do it in the tracepoint logic, but that broke a
> > lot of assumptions about tracepoints that Mathieu pointed out. This is
> > not a normal use of tracepoints. It is expected that if you register a
> > probe in a module, you will unregister it before exiting.
> > 
> > I can't remember all the details, but at the end, it seemed that the fix
> > belonged at the ftrace level.
> 
> Right, Mathieu thinks its sane to be able to attach to
> tracepoints/markers before they exist, so you can put them in module
> init code. I disagree.
> 
> ftrace doesn't mirror this behaviour, that is the source of the problem.
> If it did the ftrace structures wouldn't go away on unload and there
> wouldn't be no crash.
> 
> But if you want to maintain this disparity between the two frameworks
> then yes Li's patch, or yours (they're identical) seems the way to solve
> it.

I'll take Li's patch then. He wrote it first.

> 
> Still think its daft though.
> 

Well, it needs to be fixed, and I don't want to put up with a flamewar
about changing the way tracepoints currently work. I'll take Li's patch
and send out another pull request.

-- Steve

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Mathieu Desnoyers]

* Peter Zijlstra (peterz@infradead.org) wrote:
> On Fri, 2009-09-11 at 10:33 -0400, Steven Rostedt wrote:
> > > Or we can go with Li's original patch, that was less ugly.
> > 
> > I can go back to Li's original patch, but the talk on that was
> > "fragile". If you no longer feel that way, then I'll use his instead.
> > 
> > For now, I'll pull out this patch altogether, and resubmit the pull
> > request without it. I'd like the other changes to not be held up by
> > this.
> 
> Right, I still think its at the wrong level,. see below.
> 
> > > 
> > > I still think tracepoints/markers should sort this out, because we now
> > > have a sematic difference between the two wrt modules.
> > 
> > I originally tried to do it in the tracepoint logic, but that broke a
> > lot of assumptions about tracepoints that Mathieu pointed out. This is
> > not a normal use of tracepoints. It is expected that if you register a
> > probe in a module, you will unregister it before exiting.
> > 
> > I can't remember all the details, but at the end, it seemed that the fix
> > belonged at the ftrace level.
> 
> Right, Mathieu thinks its sane to be able to attach to
> tracepoints/markers before they exist, so you can put them in module
> init code. I disagree.

I know we disagree on this topic, but AFAIK you did not propose any
solution to solve the problem of tracepoints in module init code. This
leaves a tracepoint user who need to trace module init with no way to do
it, because he will run in the chicken and egg problem of having to load
the module to make the tracepoint appear, but needing to trace module
load. A similar problem applies to kernel boot tracing for tracepoints
in init code of the kernel image.

Maybe you have a solution for this in mind ? Or is it simply to reduce
tracepoint instrumentation coverage to exclude init functions ? You not
caring about this use case does not mean no one care about it.

> 
> ftrace doesn't mirror this behaviour, that is the source of the problem.
> If it did the ftrace structures wouldn't go away on unload and there
> wouldn't be no crash.

Ftrace and lttng need to perform refcounting the probe module
independently of this specific behavior, because they offer an interface
located outside of tracepoint or probe module to manage the
tracepoints/probes connected. Ftrace does it in ftrace, LTTng does it
within the markers. It therefore make sense to keep a global registry of
loaded probes, and to refcount the probe module before connecting a
probe to a tracepoint. I think the solution Li proposed is good.

Thanks,

Mathieu

> 
> But if you want to maintain this disparity between the two frameworks
> then yes Li's patch, or yours (they're identical) seems the way to solve
> it.
> 
> Still think its daft though.
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Steven Rostedt]

On Fri, 2009-09-11 at 16:09 +0200, Peter Zijlstra wrote:
> On Fri, 2009-09-11 at 16:04 +0200, Peter Zijlstra wrote:
> > On Fri, 2009-09-11 at 09:54 -0400, Steven Rostedt wrote:
> > 
> > > +#ifdef MODULE
> > > +# define event_trace_up_ref()					\
> > > +	do {							\
> > > +		if (!try_module_get(THIS_MODULE)) {		\
> > > +			atomic_dec(&event_call->profile_count);	\
> > > +			return -ENOENT;				\
> > > +		}						\
> > > +	} while (0)
> > > +# define event_trace_down_ref() module_put(THIS_MODULE)
> > > +#else
> > > +# define event_trace_up_ref() do { } while (0)
> > > +# define event_trace_down_ref() do { } while (0)
> > > +#endif
> > 
> > That's like truely gruesomely ugly.
> > 
> > At the very least write it like:
> > 
> > int event_trace_up_ref(struct ftrace_event_call *call)
> > {
> > 	if (!try_module_get(THIS_MODULE)) {
> > 		atomic_dev(&call->profile_count);
> > 		return -ENOENT;
> > 	}
> > 	return 0;
> > }
> 
> Or we can go with Li's original patch, that was less ugly.

Here's another version of the patch (less ugly). I forgot that the
try_module_get should handle code compiled with !CONFIG_MODULE.
This should be less ugly.

-- Steve

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 308bafd..6d5edd1 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -409,16 +409,23 @@ static int ftrace_profile_enable_##call(struct ftrace_event_call *event_call) \
 {									\
 	int ret = 0;							\
 									\
-	if (!atomic_inc_return(&event_call->profile_count))		\
+	if (!atomic_inc_return(&event_call->profile_count)) {		\
+		if (!try_module_get(THIS_MODULE))			\
+			goto out_fail;					\
 		ret = register_trace_##call(ftrace_profile_##call);	\
+	}								\
 									\
 	return ret;							\
+ out_fail:								\
+	atomic_dec(&event_call->profile_count);				\
 }									\
 									\
 static void ftrace_profile_disable_##call(struct ftrace_event_call *event_call)\
 {									\
-	if (atomic_add_negative(-1, &event_call->profile_count))	\
+	if (atomic_add_negative(-1, &event_call->profile_count)) {	\
 		unregister_trace_##call(ftrace_profile_##call);		\
+		module_put(THIS_MODULE)					\
+	}								\
 }
 
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)

Re: [PATCH 2/3] tracing/profile: add ref count for registering profile events

[Steven Rostedt]

On Fri, 2009-09-11 at 16:04 +0200, Peter Zijlstra wrote:
> On Fri, 2009-09-11 at 09:54 -0400, Steven Rostedt wrote:
> 
> > +#ifdef MODULE
> > +# define event_trace_up_ref()					\
> > +	do {							\
> > +		if (!try_module_get(THIS_MODULE)) {		\
> > +			atomic_dec(&event_call->profile_count);	\
> > +			return -ENOENT;				\
> > +		}						\
> > +	} while (0)
> > +# define event_trace_down_ref() module_put(THIS_MODULE)
> > +#else
> > +# define event_trace_up_ref() do { } while (0)
> > +# define event_trace_down_ref() do { } while (0)
> > +#endif
> 
> That's like truely gruesomely ugly.
> 
> At the very least write it like:
> 
> int event_trace_up_ref(struct ftrace_event_call *call)
> {
> 	if (!try_module_get(THIS_MODULE)) {
> 		atomic_dev(&call->profile_count);
> 		return -ENOENT;
> 	}
> 	return 0;
> }

OK, I'll replace the MACROS with static inline, rebase and resend.

Ingo, don't pull that yet.

-- Steve

[PATCH 3/3] tracing: add latency format to function_graph tracer

[Steven Rostedt]

[-- Attachment #1: 0003-tracing-add-latency-format-to-function_graph-tracer.patch --]
[-- Type: text/plain, Size: 5195 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

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 <rostedt@goodmis.org>
---
 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

-- 

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Frederic Weisbecker]

On Fri, Sep 11, 2009 at 09:54:55AM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> 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 <rostedt@goodmis.org>


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...

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Steven Rostedt]

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

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Frederic Weisbecker]

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.

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Török Edwin]

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

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Frederic Weisbecker]

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!

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Steven Rostedt]

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

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Török Edwin]

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

Re: [PATCH 3/3] tracing: add latency format to function_graph tracer

[Matt Fleming]

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