[PATCH 00/10] [GIT PULL] tracing: various fixes

[PATCH 00/10] [GIT PULL] tracing: various fixes

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1632 bytes --]


Ingo,

Please pull the latest tip/perf/core tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
tip/perf/core

Head SHA1: 7e9a49ef542610609144d1afcd516dc3fafac4d6


Gleb Natapov (1):
      jump_label: jump_label_inc may return before the code is patched

Ilya Dryomov (1):
      tracing: fix event_subsystem ref counting

Jiri Olsa (1):
      tracing/latency: Fix header output for latency tracers

Li Zefan (2):
      tracing: Restore system filter behavior
      tracing: update Documentation on max preds limit

Steven Rostedt (5):
      tracing: Add boiler plate for subsystem filter
      lockdep: Show subclass in pretty print of lockdep output
      ftrace: Remove force undef config value left for testing
      perf: Fix parsing of __print_flags() in TP_printk()
      ftrace: Fix hash record accounting bug

----
 Documentation/trace/events.txt      |    2 --
 include/linux/ftrace_event.h        |    2 ++
 kernel/jump_label.c                 |    3 ++-
 kernel/lockdep.c                    |   30 +++++++++++++-----------------
 kernel/trace/ftrace.c               |    5 +++--
 kernel/trace/trace.c                |   15 +++++++++++++++
 kernel/trace/trace.h                |    1 +
 kernel/trace/trace_events.c         |    1 -
 kernel/trace/trace_events_filter.c  |   33 +++++++++++++++++++++++++--------
 kernel/trace/trace_irqsoff.c        |   13 ++++++++++++-
 kernel/trace/trace_sched_wakeup.c   |   13 ++++++++++++-
 tools/perf/util/trace-event-parse.c |    2 ++
 12 files changed, 87 insertions(+), 33 deletions(-)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 01/10] tracing: fix event_subsystem ref counting

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1268 bytes --]

From: Ilya Dryomov <idryomov@gmail.com>

Fix a bug introduced by e9dbfae5, which prevents event_subsystem from
ever being released.

Ref_count was added to keep track of subsystem users, not for counting
events.  Subsystem is created with ref_count = 1, so there is no need to
increment it for every event, we have nr_events for that.  Fix this by
touching ref_count only when we actually have a new user -
subsystem_open().

Cc: stable@vger.kernel.org
Signed-off-by: Ilya Dryomov <idryomov@gmail.com>
Link: http://lkml.kernel.org/r/1320052062-7846-1-git-send-email-idryomov@gmail.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 581876f..c212a7f 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1078,7 +1078,6 @@ event_subsystem_dir(const char *name, struct dentry *d_events)
 	/* First see if we did not already create this dir */
 	list_for_each_entry(system, &event_subsystems, list) {
 		if (strcmp(system->name, name) == 0) {
-			__get_system(system);
 			system->nr_events++;
 			return system->entry;
 		}
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 02/10] tracing: Restore system filter behavior

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 2231 bytes --]

From: Li Zefan <lizf@cn.fujitsu.com>

Though not all events have field 'prev_pid', it was allowed to do this:

  # echo 'prev_pid == 100' > events/sched/filter

but commit 75b8e98263fdb0bfbdeba60d4db463259f1fe8a2 (tracing/filter: Swap
entire filter of events) broke it without any reason.

Link: http://lkml.kernel.org/r/4EAF46CF.8040408@cn.fujitsu.com

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace_event.h       |    2 ++
 kernel/trace/trace_events_filter.c |    7 ++++++-
 2 files changed, 8 insertions(+), 1 deletions(-)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 96efa67..c3da42d 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -172,6 +172,7 @@ enum {
 	TRACE_EVENT_FL_FILTERED_BIT,
 	TRACE_EVENT_FL_RECORDED_CMD_BIT,
 	TRACE_EVENT_FL_CAP_ANY_BIT,
+	TRACE_EVENT_FL_NO_SET_FILTER_BIT,
 };
 
 enum {
@@ -179,6 +180,7 @@ enum {
 	TRACE_EVENT_FL_FILTERED		= (1 << TRACE_EVENT_FL_FILTERED_BIT),
 	TRACE_EVENT_FL_RECORDED_CMD	= (1 << TRACE_EVENT_FL_RECORDED_CMD_BIT),
 	TRACE_EVENT_FL_CAP_ANY		= (1 << TRACE_EVENT_FL_CAP_ANY_BIT),
+	TRACE_EVENT_FL_NO_SET_FILTER	= (1 << TRACE_EVENT_FL_NO_SET_FILTER_BIT),
 };
 
 struct ftrace_event_call {
diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 816d3d0..86040d9 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -1649,7 +1649,9 @@ static int replace_system_preds(struct event_subsystem *system,
 		 */
 		err = replace_preds(call, NULL, ps, filter_string, true);
 		if (err)
-			goto fail;
+			call->flags |= TRACE_EVENT_FL_NO_SET_FILTER;
+		else
+			call->flags &= ~TRACE_EVENT_FL_NO_SET_FILTER;
 	}
 
 	list_for_each_entry(call, &ftrace_events, list) {
@@ -1658,6 +1660,9 @@ static int replace_system_preds(struct event_subsystem *system,
 		if (strcmp(call->class->system, system->name) != 0)
 			continue;
 
+		if (call->flags & TRACE_EVENT_FL_NO_SET_FILTER)
+			continue;
+
 		filter_item = kzalloc(sizeof(*filter_item), GFP_KERNEL);
 		if (!filter_item)
 			goto fail_mem;
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 03/10] tracing: Add boiler plate for subsystem filter

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 3130 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The system filter can be used to set multiple event filters that
exist within the system. But currently it displays the last filter
written that does not necessarily correspond to the filters within
the system. The system filter itself is not used to filter any events.
The system filter is just a means to set filters of the events within
it.

Because this causes an ambiguous state when the system filter reads
a filter string but the events within the system have different strings
it is best to just show a boiler plate:

 ### global filter ###
 # Use this to set filters for multiple events.
 # Only events with the given fields will be affected.
 # If no events are modified, an error message will be displayed here.

If an error occurs while writing to the system filter, the system
filter will replace the boiler plate with the error message as it
currently does.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events_filter.c |   26 +++++++++++++++++++-------
 1 files changed, 19 insertions(+), 7 deletions(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 86040d9..fdc6d22 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -27,6 +27,12 @@
 #include "trace.h"
 #include "trace_output.h"
 
+#define DEFAULT_SYS_FILTER_MESSAGE					\
+	"### global filter ###\n"					\
+	"# Use this to set filters for multiple events.\n"		\
+	"# Only events with the given fields will be affected.\n"	\
+	"# If no events are modified, an error message will be displayed here"
+
 enum filter_op_ids
 {
 	OP_OR,
@@ -646,7 +652,7 @@ void print_subsystem_event_filter(struct event_subsystem *system,
 	if (filter && filter->filter_string)
 		trace_seq_printf(s, "%s\n", filter->filter_string);
 	else
-		trace_seq_printf(s, "none\n");
+		trace_seq_printf(s, DEFAULT_SYS_FILTER_MESSAGE "\n");
 	mutex_unlock(&event_mutex);
 }
 
@@ -1838,7 +1844,10 @@ int apply_subsystem_event_filter(struct event_subsystem *system,
 	if (!filter)
 		goto out;
 
-	replace_filter_string(filter, filter_string);
+	/* System filters just show a default message */
+	kfree(filter->filter_string);
+	filter->filter_string = NULL;
+
 	/*
 	 * No event actually uses the system filter
 	 * we can free it without synchronize_sched().
@@ -1848,14 +1857,12 @@ int apply_subsystem_event_filter(struct event_subsystem *system,
 
 	parse_init(ps, filter_ops, filter_string);
 	err = filter_parse(ps);
-	if (err) {
-		append_filter_err(ps, system->filter);
-		goto out;
-	}
+	if (err)
+		goto err_filter;
 
 	err = replace_system_preds(system, ps, filter_string);
 	if (err)
-		append_filter_err(ps, system->filter);
+		goto err_filter;
 
 out:
 	filter_opstack_clear(ps);
@@ -1865,6 +1872,11 @@ out_unlock:
 	mutex_unlock(&event_mutex);
 
 	return err;
+
+err_filter:
+	replace_filter_string(filter, filter_string);
+	append_filter_err(ps, system->filter);
+	goto out;
 }
 
 #ifdef CONFIG_PERF_EVENTS
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 04/10] tracing: update Documentation on max preds limit

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 877 bytes --]

From: Li Zefan <lizf@cn.fujitsu.com>

Preds is no longer stored in a fixed-size stack. The max preds now
is 2^14, and is way more than enough, so don't bother to document it.

Link: http://lkml.kernel.org/r/4EAA5E54.1080102@cn.fujitsu.com

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 Documentation/trace/events.txt |    2 --
 1 files changed, 0 insertions(+), 2 deletions(-)

diff --git a/Documentation/trace/events.txt b/Documentation/trace/events.txt
index b510564..bb24c2a 100644
--- a/Documentation/trace/events.txt
+++ b/Documentation/trace/events.txt
@@ -191,8 +191,6 @@ And for string fields they are:
 
 Currently, only exact string matches are supported.
 
-Currently, the maximum number of predicates in a filter is 16.
-
 5.2 Setting filters
 -------------------
 
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 05/10] lockdep: Show subclass in pretty print of lockdep output

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 2895 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The pretty print of the lockdep debug splat uses just the lock name
to show how the locking scenario happens. But when it comes to
nesting locks, the output becomes confusing which takes away the point
of the pretty printing of the lock scenario.

Without displaying the subclass info, we get the following output:

  Possible unsafe locking scenario:

        CPU0                    CPU1
        ----                    ----
   lock(slock-AF_INET);
                                lock(slock-AF_INET);
                                lock(slock-AF_INET);
   lock(slock-AF_INET);

  *** DEADLOCK ***

The above looks more of a A->A locking bug than a A->B B->A.
By adding the subclass to the output, we can see what really happened:

 other info that might help us debug this:

  Possible unsafe locking scenario:

        CPU0                    CPU1
        ----                    ----
   lock(slock-AF_INET);
                                lock(slock-AF_INET/1);
                                lock(slock-AF_INET);
   lock(slock-AF_INET/1);

  *** DEADLOCK ***

This bug was discovered while tracking down a real bug caught by lockdep.

Link: http://lkml.kernel.org/r/20111025202049.GB25043@hostway.ca

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Reported-by: Thomas Gleixner <tglx@linutronix.de>
Tested-by: Simon Kirby <sim@hostway.ca>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/lockdep.c |   30 +++++++++++++-----------------
 1 files changed, 13 insertions(+), 17 deletions(-)

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 91d67ce..6bd915d 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -490,36 +490,32 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
 	usage[i] = '\0';
 }
 
-static int __print_lock_name(struct lock_class *class)
+static void __print_lock_name(struct lock_class *class)
 {
 	char str[KSYM_NAME_LEN];
 	const char *name;
 
 	name = class->name;
-	if (!name)
-		name = __get_key_name(class->key, str);
-
-	return printk("%s", name);
-}
-
-static void print_lock_name(struct lock_class *class)
-{
-	char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];
-	const char *name;
-
-	get_usage_chars(class, usage);
-
-	name = class->name;
 	if (!name) {
 		name = __get_key_name(class->key, str);
-		printk(" (%s", name);
+		printk("%s", name);
 	} else {
-		printk(" (%s", name);
+		printk("%s", name);
 		if (class->name_version > 1)
 			printk("#%d", class->name_version);
 		if (class->subclass)
 			printk("/%d", class->subclass);
 	}
+}
+
+static void print_lock_name(struct lock_class *class)
+{
+	char usage[LOCK_USAGE_CHARS];
+
+	get_usage_chars(class, usage);
+
+	printk(" (");
+	__print_lock_name(class);
 	printk("){%s}", usage);
 }
 
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 06/10] ftrace: Remove force undef config value left for testing

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1319 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

A forced undef of a config value was used for testing and was
accidently left in during the final commit. This causes x86 to
run slower than needed while running function tracing as well
as causes the function graph selftest to fail when DYNMAIC_FTRACE
is not set. This is because the code in MCOUNT expects the ftrace
code to be processed with the config value set that happened to
be forced not set.

The forced config option was left in by:
    commit 6331c28c962561aee59e5a493b7556a4bb585957
    ftrace: Fix dynamic selftest failure on some archs

Link: http://lkml.kernel.org/r/20111102150255.GA6973@debian

Cc: stable@vger.kernel.org
Reported-by: Rabin Vincent <rabin@rab.in>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 077d853..0fcc6ca 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -151,7 +151,6 @@ void clear_ftrace_function(void)
 	ftrace_pid_function = ftrace_stub;
 }
 
-#undef CONFIG_HAVE_FUNCTION_TRACE_MCOUNT_TEST
 #ifndef CONFIG_HAVE_FUNCTION_TRACE_MCOUNT_TEST
 /*
  * For those archs that do not test ftrace_trace_stop in their
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 07/10] jump_label: jump_label_inc may return before the code is patched

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1119 bytes --]

From: Gleb Natapov <gleb@redhat.com>

If cpu A calls jump_label_inc() just after atomic_add_return() is
called by cpu B, atomic_inc_not_zero() will return value greater then
zero and jump_label_inc() will return to a caller before jump_label_update()
finishes its job on cpu B.

Link: http://lkml.kernel.org/r/20111018175551.GH17571@redhat.com

Cc: stable@vger.kernel.org
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Acked-by: Jason Baron <jbaron@redhat.com>
Signed-off-by: Gleb Natapov <gleb@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/jump_label.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/kernel/jump_label.c b/kernel/jump_label.c
index a8ce450..e6f1f24 100644
--- a/kernel/jump_label.c
+++ b/kernel/jump_label.c
@@ -66,8 +66,9 @@ void jump_label_inc(struct jump_label_key *key)
 		return;
 
 	jump_label_lock();
-	if (atomic_add_return(1, &key->enabled) == 1)
+	if (atomic_read(&key->enabled) == 0)
 		jump_label_update(key, JUMP_LABEL_ENABLE);
+	atomic_inc(&key->enabled);
 	jump_label_unlock();
 }
 
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 08/10] perf: Fix parsing of __print_flags() in TP_printk()

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1126 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

A update is made to the sched:sched_switch event that adds some
logic to the first parameter of the __print_flags() that shows the
state of tasks. This change cause perf to fail parsing the flags.

A simple fix is needed to have the parser be able to process ops
within the argument.

Cc: stable@vger.kernel.org
Reported-by: Andrew Vagin <avagin@openvz.org>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 tools/perf/util/trace-event-parse.c |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
index 0a7ed5b..6c164dc 100644
--- a/tools/perf/util/trace-event-parse.c
+++ b/tools/perf/util/trace-event-parse.c
@@ -1537,6 +1537,8 @@ process_flags(struct event *event, struct print_arg *arg, char **tok)
 	field = malloc_or_die(sizeof(*field));
 
 	type = process_arg(event, field, &token);
+	while (type == EVENT_OP)
+		type = process_op(event, field, &token);
 	if (test_type_token(type, token, EVENT_DELIM, ","))
 		goto out_free;
 
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 09/10] ftrace: Fix hash record accounting bug

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1946 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

If the set_ftrace_filter is cleared by writing just whitespace to
it, then the filter hash refcounts will be decremented but not
updated. This causes two bugs:

1) No functions will be enabled for tracing when they all should be

2) If the users clears the set_ftrace_filter twice, it will crash ftrace:

------------[ cut here ]------------
WARNING: at /home/rostedt/work/git/linux-trace.git/kernel/trace/ftrace.c:1384 __ftrace_hash_rec_update.part.27+0x157/0x1a7()
Modules linked in:
Pid: 2330, comm: bash Not tainted 3.1.0-test+ #32
Call Trace:
 [<ffffffff81051828>] warn_slowpath_common+0x83/0x9b
 [<ffffffff8105185a>] warn_slowpath_null+0x1a/0x1c
 [<ffffffff810ba362>] __ftrace_hash_rec_update.part.27+0x157/0x1a7
 [<ffffffff810ba6e8>] ? ftrace_regex_release+0xa7/0x10f
 [<ffffffff8111bdfe>] ? kfree+0xe5/0x115
 [<ffffffff810ba51e>] ftrace_hash_move+0x2e/0x151
 [<ffffffff810ba6fb>] ftrace_regex_release+0xba/0x10f
 [<ffffffff8112e49a>] fput+0xfd/0x1c2
 [<ffffffff8112b54c>] filp_close+0x6d/0x78
 [<ffffffff8113a92d>] sys_dup3+0x197/0x1c1
 [<ffffffff8113a9a6>] sys_dup2+0x4f/0x54
 [<ffffffff8150cac2>] system_call_fastpath+0x16/0x1b
---[ end trace 77a3a7ee73794a02 ]---

Link: http://lkml.kernel.org/r/20111101141420.GA4918@debian

Reported-by: Rabin Vincent <rabin@rab.in>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 0fcc6ca..7caa450 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -1210,7 +1210,9 @@ ftrace_hash_move(struct ftrace_ops *ops, int enable,
 	if (!src->count) {
 		free_ftrace_hash_rcu(*dst);
 		rcu_assign_pointer(*dst, EMPTY_HASH);
-		return 0;
+		/* still need to update the function records */
+		ret = 0;
+		goto out;
 	}
 
 	/*
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 10/10] tracing/latency: Fix header output for latency tracers

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 6324 bytes --]

From: Jiri Olsa <jolsa@redhat.com>

In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.

The involved/fixed latency tracers are:
        wakeup_rt
        wakeup
        preemptirqsoff
        preemptoff
        irqsoff

The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.

* The current output (for wakeup tracer) with both graph and function
  tracers disabled is:

  # tracer: wakeup
  #
    <idle>-0       0d.h5    1us+:      0:120:R   + [000]     7:  0:R watchdog/0
    <idle>-0       0d.h5    3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
    ...

* The fixed output is:

  # tracer: wakeup
  #
  # wakeup latency trace v1.1.5 on 3.1.0-tip+
  # --------------------------------------------------------------------
  # latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
  #    -----------------
  #    | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
  #    -----------------
  #
  #                  _------=> CPU#
  #                 / _-----=> irqs-off
  #                | / _----=> need-resched
  #                || / _---=> hardirq/softirq
  #                ||| / _--=> preempt-depth
  #                |||| /     delay
  #  cmd     pid   ||||| time  |   caller
  #     \   /      |||||  \    |   /
       cat-1129    0d..4    1us :   1129:120:R   + [000]     6:  0:R migration/0
       cat-1129    0d..4    2us+: ttwu_do_activate.clone.1 <-try_to_wake_up

* The current output (for wakeup tracer) with only function
  tracer enabled is:

  # tracer: wakeup
  #
       cat-1140    0d..4    1us+:   1140:120:R   + [000]     6:  0:R migration/0
       cat-1140    0d..4    2us : ttwu_do_activate.clone.1 <-try_to_wake_up

* The fixed output is:
  # tracer: wakeup
  #
  # wakeup latency trace v1.1.5 on 3.1.0-tip+
  # --------------------------------------------------------------------
  # latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
  #    -----------------
  #    | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
  #    -----------------
  #
  #                  _------=> CPU#
  #                 / _-----=> irqs-off
  #                | / _----=> need-resched
  #                || / _---=> hardirq/softirq
  #                ||| / _--=> preempt-depth
  #                |||| /     delay
  #  cmd     pid   ||||| time  |   caller
  #     \   /      |||||  \    |   /
    <idle>-0       1d.h5    1us+:      0:120:R   + [001]    12:  0:R watchdog/1
    <idle>-0       1d.h5    3us : ttwu_do_activate.clone.1 <-try_to_wake_up

Link: http://lkml.kernel.org/r/20111107150849.GE1807@m.brq.redhat.com

Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace.c              |   15 +++++++++++++++
 kernel/trace/trace.h              |    1 +
 kernel/trace/trace_irqsoff.c      |   13 ++++++++++++-
 kernel/trace/trace_sched_wakeup.c |   13 ++++++++++++-
 4 files changed, 40 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b24a72d..b296186 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2140,6 +2140,21 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
 	return print_trace_fmt(iter);
 }
 
+void trace_latency_header(struct seq_file *m)
+{
+	struct trace_iterator *iter = m->private;
+
+	/* print nothing if the buffers are empty */
+	if (trace_empty(iter))
+		return;
+
+	if (iter->iter_flags & TRACE_FILE_LAT_FMT)
+		print_trace_header(m, iter);
+
+	if (!(trace_flags & TRACE_ITER_VERBOSE))
+		print_lat_help_header(m);
+}
+
 void trace_default_header(struct seq_file *m)
 {
 	struct trace_iterator *iter = m->private;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 092e1f8..f8ec229 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
 		    unsigned long ip,
 		    unsigned long parent_ip,
 		    unsigned long flags, int pc);
+void trace_latency_header(struct seq_file *m);
 void trace_default_header(struct seq_file *m);
 void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
 int trace_empty(struct trace_iterator *iter);
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index a1a3359..a248c68 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
 }
 
 static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
-static void irqsoff_print_header(struct seq_file *s) { }
 static void irqsoff_trace_open(struct trace_iterator *iter) { }
 static void irqsoff_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void irqsoff_print_header(struct seq_file *s)
+{
+	trace_default_header(s);
+}
+#else
+static void irqsoff_print_header(struct seq_file *s)
+{
+	trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
 
 /*
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index e4a70c0..ff791ea 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
 }
 
 static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
-static void wakeup_print_header(struct seq_file *s) { }
 static void wakeup_trace_open(struct trace_iterator *iter) { }
 static void wakeup_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void wakeup_print_header(struct seq_file *s)
+{
+	trace_default_header(s);
+}
+#else
+static void wakeup_print_header(struct seq_file *s)
+{
+	trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
 
 /*
-- 
1.7.7



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [PATCH 00/10] [GIT PULL] tracing: various fixes

[Ingo Molnar]

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

> Ingo,
> 
> Please pull the latest tip/perf/core tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> tip/perf/core
> 
> Head SHA1: 7e9a49ef542610609144d1afcd516dc3fafac4d6
> 
> 
> Gleb Natapov (1):
>       jump_label: jump_label_inc may return before the code is patched
> 
> Ilya Dryomov (1):
>       tracing: fix event_subsystem ref counting
> 
> Jiri Olsa (1):
>       tracing/latency: Fix header output for latency tracers
> 
> Li Zefan (2):
>       tracing: Restore system filter behavior
>       tracing: update Documentation on max preds limit
> 
> Steven Rostedt (5):
>       tracing: Add boiler plate for subsystem filter
>       lockdep: Show subclass in pretty print of lockdep output
>       ftrace: Remove force undef config value left for testing
>       perf: Fix parsing of __print_flags() in TP_printk()
>       ftrace: Fix hash record accounting bug
> 
> ----
>  Documentation/trace/events.txt      |    2 --
>  include/linux/ftrace_event.h        |    2 ++
>  kernel/jump_label.c                 |    3 ++-
>  kernel/lockdep.c                    |   30 +++++++++++++-----------------
>  kernel/trace/ftrace.c               |    5 +++--
>  kernel/trace/trace.c                |   15 +++++++++++++++
>  kernel/trace/trace.h                |    1 +
>  kernel/trace/trace_events.c         |    1 -
>  kernel/trace/trace_events_filter.c  |   33 +++++++++++++++++++++++++--------
>  kernel/trace/trace_irqsoff.c        |   13 ++++++++++++-
>  kernel/trace/trace_sched_wakeup.c   |   13 ++++++++++++-
>  tools/perf/util/trace-event-parse.c |    2 ++
>  12 files changed, 87 insertions(+), 33 deletions(-)

Pulled, thanks a lot Steve!

	Ingo

Re: [PATCH 00/10] [GIT PULL] tracing: various fixes

[Steven Rostedt]

On Fri, 2011-11-11 at 09:33 +0100, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > Ingo,
> > 
> > Please pull the latest tip/perf/core tree, which can be found at:
> > 
> >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > tip/perf/core
> > 
> > Head SHA1: 7e9a49ef542610609144d1afcd516dc3fafac4d6
> > 
> > 
> > Gleb Natapov (1):
> >       jump_label: jump_label_inc may return before the code is patched
> > 
> > Ilya Dryomov (1):
> >       tracing: fix event_subsystem ref counting
> > 
> > Jiri Olsa (1):
> >       tracing/latency: Fix header output for latency tracers
> > 
> > Li Zefan (2):
> >       tracing: Restore system filter behavior
> >       tracing: update Documentation on max preds limit
> > 
> > Steven Rostedt (5):
> >       tracing: Add boiler plate for subsystem filter
> >       lockdep: Show subclass in pretty print of lockdep output
> >       ftrace: Remove force undef config value left for testing
> >       perf: Fix parsing of __print_flags() in TP_printk()
> >       ftrace: Fix hash record accounting bug
> > 
> > ----
> >  Documentation/trace/events.txt      |    2 --
> >  include/linux/ftrace_event.h        |    2 ++
> >  kernel/jump_label.c                 |    3 ++-
> >  kernel/lockdep.c                    |   30 +++++++++++++-----------------
> >  kernel/trace/ftrace.c               |    5 +++--
> >  kernel/trace/trace.c                |   15 +++++++++++++++
> >  kernel/trace/trace.h                |    1 +
> >  kernel/trace/trace_events.c         |    1 -
> >  kernel/trace/trace_events_filter.c  |   33 +++++++++++++++++++++++++--------
> >  kernel/trace/trace_irqsoff.c        |   13 ++++++++++++-
> >  kernel/trace/trace_sched_wakeup.c   |   13 ++++++++++++-
> >  tools/perf/util/trace-event-parse.c |    2 ++
> >  12 files changed, 87 insertions(+), 33 deletions(-)
> 
> Pulled, thanks a lot Steve!

Hi Ingo,

All these were bug fixes and I was hopping that it would have been
pushed to Linus. I know it just missed the merge window (it was posted
during -rc1) but they are fixes, not enhancements, and I still believe
they are fine for an -rc3 release. I would have even had it pushed
before -rc1 but it took time running them through all my tests.

-- Steve

Re: [PATCH 00/10] [GIT PULL] tracing: various fixes

[Ingo Molnar]

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

> On Fri, 2011-11-11 at 09:33 +0100, Ingo Molnar wrote:
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > Ingo,
> > > 
> > > Please pull the latest tip/perf/core tree, which can be found at:
> > > 
> > >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > > tip/perf/core
> > > 
> > > Head SHA1: 7e9a49ef542610609144d1afcd516dc3fafac4d6
> > > 
> > > 
> > > Gleb Natapov (1):
> > >       jump_label: jump_label_inc may return before the code is patched
> > > 
> > > Ilya Dryomov (1):
> > >       tracing: fix event_subsystem ref counting
> > > 
> > > Jiri Olsa (1):
> > >       tracing/latency: Fix header output for latency tracers
> > > 
> > > Li Zefan (2):
> > >       tracing: Restore system filter behavior
> > >       tracing: update Documentation on max preds limit
> > > 
> > > Steven Rostedt (5):
> > >       tracing: Add boiler plate for subsystem filter
> > >       lockdep: Show subclass in pretty print of lockdep output
> > >       ftrace: Remove force undef config value left for testing
> > >       perf: Fix parsing of __print_flags() in TP_printk()
> > >       ftrace: Fix hash record accounting bug
> > > 
> > > ----
> > >  Documentation/trace/events.txt      |    2 --
> > >  include/linux/ftrace_event.h        |    2 ++
> > >  kernel/jump_label.c                 |    3 ++-
> > >  kernel/lockdep.c                    |   30 +++++++++++++-----------------
> > >  kernel/trace/ftrace.c               |    5 +++--
> > >  kernel/trace/trace.c                |   15 +++++++++++++++
> > >  kernel/trace/trace.h                |    1 +
> > >  kernel/trace/trace_events.c         |    1 -
> > >  kernel/trace/trace_events_filter.c  |   33 +++++++++++++++++++++++++--------
> > >  kernel/trace/trace_irqsoff.c        |   13 ++++++++++++-
> > >  kernel/trace/trace_sched_wakeup.c   |   13 ++++++++++++-
> > >  tools/perf/util/trace-event-parse.c |    2 ++
> > >  12 files changed, 87 insertions(+), 33 deletions(-)
> > 
> > Pulled, thanks a lot Steve!
> 
> Hi Ingo,
> 
> All these were bug fixes and I was hopping that it would have 
> been pushed to Linus. I know it just missed the merge window 
> (it was posted during -rc1) but they are fixes, not 
> enhancements, and I still believe they are fine for an -rc3 
> release. I would have even had it pushed before -rc1 but it 
> took time running them through all my tests.

Hm, not all were regression fixes and the branch was named 
*/core so i took it into perf/core.

Could you perhaps cherry-pick the most crutial regression fixes 
into an urgent branch? We could still push that upstream.

Thanks,

	Ingo

Re: [PATCH 00/10] [GIT PULL] tracing: various fixes

[Steven Rostedt]

On Sat, 2011-12-03 at 10:20 +0100, Ingo Molnar wrote:

> Hm, not all were regression fixes and the branch was named 
> */core so i took it into perf/core.

Yeah it happened just at the end of the merge window. I didn't really
know what branch to name it.

> 
> Could you perhaps cherry-pick the most crutial regression fixes 
> into an urgent branch? We could still push that upstream.

Looking at each patch, I would say 6 of the ten need to go in. Most are
marked as stable since they break the last tree. I could just send them
all to stable if it seems strange to have this many patches in two pull
requests.

-- Steve

Re: [PATCH 00/10] [GIT PULL] tracing: various fixes

[Ingo Molnar]

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

> On Sat, 2011-12-03 at 10:20 +0100, Ingo Molnar wrote:
> 
> > Hm, not all were regression fixes and the branch was named 
> > */core so i took it into perf/core.
> 
> Yeah it happened just at the end of the merge window. I didn't really
> know what branch to name it.
> 
> > 
> > Could you perhaps cherry-pick the most crutial regression 
> > fixes into an urgent branch? We could still push that 
> > upstream.
> 
> Looking at each patch, I would say 6 of the ten need to go in. 
> Most are marked as stable since they break the last tree. I 
> could just send them all to stable if it seems strange to have 
> this many patches in two pull requests.

We can cherry-pick those 6 patches into perf/urgent - just make 
sure you merge the cherry-picked branch into your devel branch 
before adding new changes to the same files, there will be tons 
of conflicts otherwise.

Thanks,

	Ingo