[PATCH 1/2] ftrace: Add task_comm support for trace_event

[PATCH 1/2] ftrace: Add task_comm support for trace_event

[Zhaolei]

If we use trace_event alone(without function trace, .etc),
it can't output enough task command information.

Before patch:
 # echo 1 > debugfs/tracing/events/sched/sched_switch/enable
 # cat debugfs/tracing/trace
 # tracer: nop
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
            <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
            <...>-2287  [000] 526276.725231: sched_switch: task sshd:2287 [120] ==> bash:2289 [120]
            <...>-2289  [000] 526276.725452: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
            <...>-2287  [000] 526276.727181: sched_switch: task sshd:2287 [120] ==> swapper:0 [140]
           <idle>-0     [000] 526277.032734: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
            <...>-5     [000] 526277.032782: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
 ...

After patch:
 # tracer: nop
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-2269  [000] 527347.989229: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
             sshd-2267  [000] 527347.990960: sched_switch: task sshd:2267 [120] ==> bash:2269 [120]
             bash-2269  [000] 527347.991143: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
             sshd-2267  [000] 527347.992959: sched_switch: task sshd:2267 [120] ==> swapper:0 [140]
           <idle>-0     [000] 527348.531989: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
         events/0-5     [000] 527348.532115: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
 ...

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
---
 kernel/trace/trace_events.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 0eec0c5..df35e5e 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -85,6 +85,7 @@ static void ftrace_clear_events(void)
 
 		if (call->enabled) {
 			call->enabled = 0;
+			tracing_stop_cmdline_record();
 			call->unregfunc();
 		}
 	}
@@ -99,12 +100,14 @@ static void ftrace_event_enable_disable(struct ftrace_event_call *call,
 	case 0:
 		if (call->enabled) {
 			call->enabled = 0;
+			tracing_stop_cmdline_record();
 			call->unregfunc();
 		}
 		break;
 	case 1:
 		if (!call->enabled) {
 			call->enabled = 1;
+			tracing_start_cmdline_record();
 			call->regfunc();
 		}
 		break;
@@ -1058,6 +1061,7 @@ static void trace_module_remove_events(struct module *mod)
 			found = true;
 			if (call->enabled) {
 				call->enabled = 0;
+				tracing_stop_cmdline_record();
 				call->unregfunc();
 			}
 			if (call->event)
@@ -1262,11 +1266,13 @@ static __init void event_trace_self_tests(void)
 		}
 
 		call->enabled = 1;
+		tracing_start_cmdline_record();
 		call->regfunc();
 
 		event_test_stuff();
 
 		call->unregfunc();
+		tracing_stop_cmdline_record();
 		call->enabled = 0;
 
 		pr_cont("OK\n");
-- 
1.5.5.3

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Steven Rostedt]

On Thu, 21 May 2009, Zhaolei wrote:

> If we use trace_event alone(without function trace, .etc),
> it can't output enough task command information.
> 
> Before patch:
>  # echo 1 > debugfs/tracing/events/sched/sched_switch/enable
>  # cat debugfs/tracing/trace
>  # tracer: nop
>  #
>  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
>  #              | |       |          |         |
>             <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
>             <...>-2287  [000] 526276.725231: sched_switch: task sshd:2287 [120] ==> bash:2289 [120]
>             <...>-2289  [000] 526276.725452: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
>             <...>-2287  [000] 526276.727181: sched_switch: task sshd:2287 [120] ==> swapper:0 [140]
>            <idle>-0     [000] 526277.032734: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
>             <...>-5     [000] 526277.032782: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
>  ...
> 
> After patch:
>  # tracer: nop
>  #
>  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
>  #              | |       |          |         |
>              bash-2269  [000] 527347.989229: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
>              sshd-2267  [000] 527347.990960: sched_switch: task sshd:2267 [120] ==> bash:2269 [120]
>              bash-2269  [000] 527347.991143: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
>              sshd-2267  [000] 527347.992959: sched_switch: task sshd:2267 [120] ==> swapper:0 [140]
>            <idle>-0     [000] 527348.531989: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
>          events/0-5     [000] 527348.532115: sched_switch: task events/0:5 [115] ==> swapper:0 [140]

Heh, this was on my todo list today. Thanks, I'll suck up this patch, if 
Ingo doesn't get to it first. If he does.

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

[PATCH 0/2] [GIT PULL] tracing/events: show task comms

[Steven Rostedt]

Ingo,

This is on top of the changes that I posted yesterday (ftrace-1), but
in its own branch.

Please pull the latest tip/tracing/ftrace-2 tree, which can be found at:

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


Zhaolei (2):
      ftrace: Add task_comm support for trace_event
      ftrace: clean up of using ftrace_event_enable_disable()

----
 kernel/trace/trace_events.c |   42 ++++++++++++++++--------------------------
 1 files changed, 16 insertions(+), 26 deletions(-)
-- 

[PATCH 1/2] ftrace: Add task_comm support for trace_event

[Steven Rostedt]

[-- Attachment #1: 0001-ftrace-Add-task_comm-support-for-trace_event.patch --]
[-- Type: text/plain, Size: 3200 bytes --]

From: Zhaolei <zhaolei@cn.fujitsu.com>

If we use trace_event alone(without function trace, .etc),
it can't output enough task command information.

Before patch:
 # echo 1 > debugfs/tracing/events/sched/sched_switch/enable
 # cat debugfs/tracing/trace
 # tracer: nop
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
            <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
            <...>-2287  [000] 526276.725231: sched_switch: task sshd:2287 [120] ==> bash:2289 [120]
            <...>-2289  [000] 526276.725452: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
            <...>-2287  [000] 526276.727181: sched_switch: task sshd:2287 [120] ==> swapper:0 [140]
           <idle>-0     [000] 526277.032734: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
            <...>-5     [000] 526277.032782: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
 ...

After patch:
 # tracer: nop
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-2269  [000] 527347.989229: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
             sshd-2267  [000] 527347.990960: sched_switch: task sshd:2267 [120] ==> bash:2269 [120]
             bash-2269  [000] 527347.991143: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
             sshd-2267  [000] 527347.992959: sched_switch: task sshd:2267 [120] ==> swapper:0 [140]
           <idle>-0     [000] 527348.531989: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
         events/0-5     [000] 527348.532115: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
 ...

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
LKML-Reference: <4A14FDFE.2080402@cn.fujitsu.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 9e91c4a..9b246eb 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -85,6 +85,7 @@ static void ftrace_clear_events(void)
 
 		if (call->enabled) {
 			call->enabled = 0;
+			tracing_stop_cmdline_record();
 			call->unregfunc();
 		}
 	}
@@ -99,12 +100,14 @@ static void ftrace_event_enable_disable(struct ftrace_event_call *call,
 	case 0:
 		if (call->enabled) {
 			call->enabled = 0;
+			tracing_stop_cmdline_record();
 			call->unregfunc();
 		}
 		break;
 	case 1:
 		if (!call->enabled) {
 			call->enabled = 1;
+			tracing_start_cmdline_record();
 			call->regfunc();
 		}
 		break;
@@ -1058,6 +1061,7 @@ static void trace_module_remove_events(struct module *mod)
 			found = true;
 			if (call->enabled) {
 				call->enabled = 0;
+				tracing_stop_cmdline_record();
 				call->unregfunc();
 			}
 			if (call->event)
@@ -1262,11 +1266,13 @@ static __init void event_trace_self_tests(void)
 		}
 
 		call->enabled = 1;
+		tracing_start_cmdline_record();
 		call->regfunc();
 
 		event_test_stuff();
 
 		call->unregfunc();
+		tracing_stop_cmdline_record();
 		call->enabled = 0;
 
 		pr_cont("OK\n");
-- 
1.6.2.4

-- 

[PATCH 2/2] ftrace: clean up of using ftrace_event_enable_disable()

[Steven Rostedt]

[-- Attachment #1: 0002-ftrace-clean-up-of-using-ftrace_event_enable_disabl.patch --]
[-- Type: text/plain, Size: 2457 bytes --]

From: Zhaolei <zhaolei@cn.fujitsu.com>

Always use tracing_stop_cmdline_record() to enable/disable a event.

Impact: cleanup, no functionality changed

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
LKML-Reference: <4A14FE45.6070308@cn.fujitsu.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c |   44 +++++++++++++-----------------------------
 1 files changed, 14 insertions(+), 30 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 9b246eb..6c81f9c 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -76,26 +76,9 @@ static void trace_destroy_fields(struct ftrace_event_call *call)
 
 #endif /* CONFIG_MODULES */
 
-static void ftrace_clear_events(void)
-{
-	struct ftrace_event_call *call;
-
-	mutex_lock(&event_mutex);
-	list_for_each_entry(call, &ftrace_events, list) {
-
-		if (call->enabled) {
-			call->enabled = 0;
-			tracing_stop_cmdline_record();
-			call->unregfunc();
-		}
-	}
-	mutex_unlock(&event_mutex);
-}
-
 static void ftrace_event_enable_disable(struct ftrace_event_call *call,
 					int enable)
 {
-
 	switch (enable) {
 	case 0:
 		if (call->enabled) {
@@ -114,6 +97,17 @@ static void ftrace_event_enable_disable(struct ftrace_event_call *call,
 	}
 }
 
+static void ftrace_clear_events(void)
+{
+	struct ftrace_event_call *call;
+
+	mutex_lock(&event_mutex);
+	list_for_each_entry(call, &ftrace_events, list) {
+		ftrace_event_enable_disable(call, 0);
+	}
+	mutex_unlock(&event_mutex);
+}
+
 /*
  * __ftrace_set_clr_event(NULL, NULL, NULL, set) will set/unset all events.
  */
@@ -1059,11 +1053,7 @@ static void trace_module_remove_events(struct module *mod)
 	list_for_each_entry_safe(call, p, &ftrace_events, list) {
 		if (call->mod == mod) {
 			found = true;
-			if (call->enabled) {
-				call->enabled = 0;
-				tracing_stop_cmdline_record();
-				call->unregfunc();
-			}
+			ftrace_event_enable_disable(call, 0);
 			if (call->event)
 				unregister_ftrace_event(call->event);
 			debugfs_remove_recursive(call->dir);
@@ -1265,15 +1255,9 @@ static __init void event_trace_self_tests(void)
 			continue;
 		}
 
-		call->enabled = 1;
-		tracing_start_cmdline_record();
-		call->regfunc();
-
+		ftrace_event_enable_disable(call, 1);
 		event_test_stuff();
-
-		call->unregfunc();
-		tracing_stop_cmdline_record();
-		call->enabled = 0;
+		ftrace_event_enable_disable(call, 0);
 
 		pr_cont("OK\n");
 	}
-- 
1.6.2.4

-- 

Re: [PATCH 0/2] [GIT PULL] tracing/events: show task comms

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> Ingo,
> 
> This is on top of the changes that I posted yesterday (ftrace-1), but
> in its own branch.
> 
> Please pull the latest tip/tracing/ftrace-2 tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace-2
> 
> 
> Zhaolei (2):
>       ftrace: Add task_comm support for trace_event
>       ftrace: clean up of using ftrace_event_enable_disable()
> 
> ----
>  kernel/trace/trace_events.c |   42 ++++++++++++++++--------------------------
>  1 files changed, 16 insertions(+), 26 deletions(-)

Pulled, thanks Steve!

	Ingo

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Thu, 21 May 2009, Zhaolei wrote:
> 
> > If we use trace_event alone(without function trace, .etc),
> > it can't output enough task command information.
> > 
> > Before patch:
> >  # echo 1 > debugfs/tracing/events/sched/sched_switch/enable
> >  # cat debugfs/tracing/trace
> >  # tracer: nop
> >  #
> >  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
> >  #              | |       |          |         |
> >             <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
> >             <...>-2287  [000] 526276.725231: sched_switch: task sshd:2287 [120] ==> bash:2289 [120]
> >             <...>-2289  [000] 526276.725452: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
> >             <...>-2287  [000] 526276.727181: sched_switch: task sshd:2287 [120] ==> swapper:0 [140]
> >            <idle>-0     [000] 526277.032734: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
> >             <...>-5     [000] 526277.032782: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
> >  ...
> > 
> > After patch:
> >  # tracer: nop
> >  #
> >  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
> >  #              | |       |          |         |
> >              bash-2269  [000] 527347.989229: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
> >              sshd-2267  [000] 527347.990960: sched_switch: task sshd:2267 [120] ==> bash:2269 [120]
> >              bash-2269  [000] 527347.991143: sched_switch: task bash:2269 [120] ==> sshd:2267 [120]
> >              sshd-2267  [000] 527347.992959: sched_switch: task sshd:2267 [120] ==> swapper:0 [140]
> >            <idle>-0     [000] 527348.531989: sched_switch: task swapper:0 [140] ==> events/0:5 [115]
> >          events/0-5     [000] 527348.532115: sched_switch: task events/0:5 [115] ==> swapper:0 [140]
> 
> Heh, this was on my todo list today. [...]

yeah, it annoyed me too for some time :)

> [...] Thanks, I'll suck up this patch, if Ingo doesn't get to it 
> first. If he does.
> 
> Acked-by: Steven Rostedt <rostedt@goodmis.org>

I pulled it from your tree - thanks guys.

	Ingo

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Ingo Molnar]

note, this patch fails -tip testing:

kernel/built-in.o: In function `ftrace_event_enable_disable':
trace_events.c:(.text+0x6cf7a): undefined reference to `tracing_stop_cmdline_record'
trace_events.c:(.text+0x6cf91): undefined reference to `tracing_start_cmdline_record'

	Ingo

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Zhaolei]

* From: "Ingo Molnar" <mingo@elte.hu>
> 
> note, this patch fails -tip testing:
> 
> kernel/built-in.o: In function `ftrace_event_enable_disable':
> trace_events.c:(.text+0x6cf7a): undefined reference to `tracing_stop_cmdline_record'
> trace_events.c:(.text+0x6cf91): undefined reference to `tracing_start_cmdline_record'

Hello, Ingo

Sorry for this bug.

Maybe it is caused by not config sched_switch tracer.
trace_sched_switch.c is necessary for trace_event.c now.
I'll test and fix it.

Thanks
Zhaolei

> 
> Ingo
> 
>ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Christoph Hellwig]

On Thu, May 21, 2009 at 03:08:46PM +0800, Zhaolei wrote:
>             <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]

we should have a space after the colon.  Also wouldn't it be better
to place task->commit close to the pid in the output?

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Christoph Hellwig]

On Sat, May 23, 2009 at 11:16:28AM -0400, Christoph Hellwig wrote:
> On Thu, May 21, 2009 at 03:08:46PM +0800, Zhaolei wrote:
> >             <...>-2289  [000] 526276.724790: sched_switch: task bash:2289 [120] ==> sshd:2287 [120]
> 
> we should have a space after the colon.  Also wouldn't it be better
> to place task->commit close to the pid in the output?

Sorry, please ignore this mail, it doesn't make any sense :)  I took
the old example tracer output for the added comm information.  The patch
does look good to me.

Re: [PATCH 1/2] ftrace: Add task_comm support for trace_event

[Christoph Hellwig]

On Thu, May 21, 2009 at 10:18:14AM -0400, Steven Rostedt wrote:
> From: Zhaolei <zhaolei@cn.fujitsu.com>
> 
> If we use trace_event alone(without function trace, .etc),
> it can't output enough task command information.

For some reason I still only see the process name sometimes but not
always.  It is more likely to appear for later entries than earlier
ones (and no, this is not an IRQ context problem as this is with
my work in progress XFS trace events, and XFS runs no major piece of
code in IRQ context)