[PATCH] perf sched: Add max delay time snapshot

[PATCH] perf sched: Add max delay time snapshot

[Frederic Weisbecker]

When we have a maximum latency reported for a task, we need a
convenient way to find the matching location to the raw traces
or to perf sched map that shows where the task has been eventually
scheduled in. This gives a pointer to retrieve the events that occured
during this max latency.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 tools/perf/builtin-sched.c |   16 ++++++++++------
 1 files changed, 10 insertions(+), 6 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index b12b23a..7cca7c1 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -140,6 +140,7 @@ struct work_atoms {
 	struct thread		*thread;
 	struct rb_node		node;
 	u64			max_lat;
+	u64			max_lat_at;
 	u64			total_lat;
 	u64			nb_atoms;
 	u64			total_runtime;
@@ -1013,8 +1014,10 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
 
 	delta = atom->sched_in_time - atom->wake_up_time;
 	atoms->total_lat += delta;
-	if (delta > atoms->max_lat)
+	if (delta > atoms->max_lat) {
 		atoms->max_lat = delta;
+		atoms->max_lat_at = timestamp;
+	}
 	atoms->nb_atoms++;
 }
 
@@ -1210,10 +1213,11 @@ static void output_lat_thread(struct work_atoms *work_list)
 
 	avg = work_list->total_lat / work_list->nb_atoms;
 
-	printf("|%11.3f ms |%9llu | avg:%9.3f ms | max:%9.3f ms |\n",
+	printf("|%11.3f ms |%9llu | avg:%9.3f ms | max:%9.3f ms | max at: %9.6f s\n",
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
-		 (double)work_list->max_lat / 1e6);
+		 (double)work_list->max_lat / 1e6,
+		 (double)work_list->max_lat_at / 1e9);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
@@ -1704,9 +1708,9 @@ static void __cmd_lat(void)
 	read_events();
 	sort_lat();
 
-	printf("\n -----------------------------------------------------------------------------------------\n");
-	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms |\n");
-	printf(" -----------------------------------------------------------------------------------------\n");
+	printf("\n ---------------------------------------------------------------------------------------------------------------\n");
+	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at     |\n");
+	printf(" ---------------------------------------------------------------------------------------------------------------\n");
 
 	next = rb_first(&sorted_atom_root);
 
-- 
1.6.2.3

Re: [PATCH] perf sched: Add max delay time snapshot

[Xiao Guangrong]

Frederic Weisbecker wrote:
> When we have a maximum latency reported for a task, we need a
> convenient way to find the matching location to the raw traces
> or to perf sched map that shows where the task has been eventually
> scheduled in. This gives a pointer to retrieve the events that occured
> during this max latency.
> 

Then, we can cooperate with ftrace's data to know what the cpu is
doing at that time.

Reviewed-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>

Thanks,
Xiao

Re: [PATCH] perf sched: Add max delay time snapshot

[Ingo Molnar]

* Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> wrote:

> Frederic Weisbecker wrote:
>
> > When we have a maximum latency reported for a task, we need a 
> > convenient way to find the matching location to the raw traces or to 
> > perf sched map that shows where the task has been eventually 
> > scheduled in. This gives a pointer to retrieve the events that 
> > occured during this max latency.
> 
> Then, we can cooperate with ftrace's data to know what the cpu is 
> doing at that time.

What do you mean by mixing it with ftrace data? These events ought to be 
a full replacement for the sched and wakeup tracers. In the long run we 
want a single stream of events and phase out most of the pretty-printing 
ftrace plugins.

	Ingo

Re: [PATCH] perf sched: Add max delay time snapshot

[Xiao Guangrong]

Ingo Molnar wrote:
> * Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> wrote:
> 
>> Frederic Weisbecker wrote:
>>
>>> When we have a maximum latency reported for a task, we need a 
>>> convenient way to find the matching location to the raw traces or to 
>>> perf sched map that shows where the task has been eventually 
>>> scheduled in. This gives a pointer to retrieve the events that 
>>> occured during this max latency.
>> Then, we can cooperate with ftrace's data to know what the cpu is 
>> doing at that time.
> 
> What do you mean by mixing it with ftrace data? These events ought to be 
> a full replacement for the sched and wakeup tracers. In the long run we 
> want a single stream of events and phase out most of the pretty-printing 
> ftrace plugins.

Hi Ingo,

I think sometimes perf tool cooperate with ftrace can do more
useful things, take this case for example:

By 'perf sched latency' we can get the schedule latency time,
if the time is abnormal, then we can run this command and enable
function tracer. 

After running, 'perf sched latency' can show us the timestamps
when the maximum latency(the worst case) occurs, then we can find
what the cpu is doing at this timestamps by reading function
tracer's output.

Thanks,
Xiao

Re: [PATCH] perf sched: Add max delay time snapshot

[Ingo Molnar]

* Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> wrote:

> 
> 
> Ingo Molnar wrote:
> > * Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> wrote:
> > 
> >> Frederic Weisbecker wrote:
> >>
> >>> When we have a maximum latency reported for a task, we need a 
> >>> convenient way to find the matching location to the raw traces or to 
> >>> perf sched map that shows where the task has been eventually 
> >>> scheduled in. This gives a pointer to retrieve the events that 
> >>> occured during this max latency.
> >> Then, we can cooperate with ftrace's data to know what the cpu is 
> >> doing at that time.
> > 
> > What do you mean by mixing it with ftrace data? These events ought to be 
> > a full replacement for the sched and wakeup tracers. In the long run we 
> > want a single stream of events and phase out most of the pretty-printing 
> > ftrace plugins.
> 
> Hi Ingo,
> 
> I think sometimes perf tool cooperate with ftrace can do more useful 
> things, take this case for example:
> 
> By 'perf sched latency' we can get the schedule latency time, if the 
> time is abnormal, then we can run this command and enable function 
> tracer.
> 
> After running, 'perf sched latency' can show us the timestamps when 
> the maximum latency(the worst case) occurs, then we can find what the 
> cpu is doing at this timestamps by reading function tracer's output.

Actually, i think the natural solution here is not any ugly interaction 
between two largely disjunct sets of APIs, but a new feature: to turn 
the function tracer into an event.

That would allow perf sched to also record function traces if so 
desired. And it would also allow a whole lot of other things - mixing 
function tracer events and other events.

As a starter we could create a new function tracer event. A crude 
prototype hack is attached below - via that it should already be 
possible to 'count' function calls via:

  perf stat -a --repeat 3 -e context-switches sleep 1

( obviously the real patch would introduce PERF_COUNT_SW_FUNCTION_CALLS, 
  but you get the point. )

	Ingo

---
 include/trace/events/function.h |   33 +++++++++++++++++++++++++++++++++
 kernel/trace/ftrace.c           |   15 +++++++++++++++
 2 files changed, 48 insertions(+)

Index: linux/include/trace/events/function.h
===================================================================
--- /dev/null
+++ linux/include/trace/events/function.h
@@ -0,0 +1,33 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM function
+
+#if !defined(_TRACE_FUNCTION_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_FUNCTION_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(function_call,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip),
+
+	TP_ARGS(ip, parent_ip),
+
+	TP_STRUCT__entry(
+		__field(	u64,		ip		)
+		__field(	u64,		parent_ip	)
+	),
+
+	TP_fast_assign(
+		__entry->ip		= ip;
+		__entry->parent_ip	= parent_ip;
+	),
+
+	TP_printk("IP: %016Lx, parent IP: %016Lx",
+		__entry->ip,
+		__entry->parent_ip)
+);
+
+#endif /* _TRACE_FUNCTION_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
Index: linux/kernel/trace/ftrace.c
===================================================================
--- linux.orig/kernel/trace/ftrace.c
+++ linux/kernel/trace/ftrace.c
@@ -2769,9 +2769,24 @@ void __init ftrace_init(void)
 
 #else
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/function.h>
+
+static void perf_ftrace_func(unsigned long ip, unsigned long parent_ip)
+{
+	struct pt_regs *regs = task_pt_regs(current);
+
+	perf_sw_event(PERF_COUNT_SW_CONTEXT_SWITCHES, 1, 1, regs, 0);
+}
+
 static int __init ftrace_nodyn_init(void)
 {
 	ftrace_enabled = 1;
+
+	printk("enabling function tracer test\n");
+
+	ftrace_trace_function = perf_ftrace_func;
+
 	return 0;
 }
 device_initcall(ftrace_nodyn_init);

Re: [PATCH] perf sched: Add max delay time snapshot

[Xiao Guangrong]

Ingo Molnar wrote:

> Actually, i think the natural solution here is not any ugly interaction 
> between two largely disjunct sets of APIs, but a new feature: to turn 
> the function tracer into an event.
> 
> That would allow perf sched to also record function traces if so 
> desired. And it would also allow a whole lot of other things - mixing 
> function tracer events and other events.

It's a useful feature! :-)

Thanks,
Xiao

[tip:perf/urgent] perf sched: Add max delay time snapshot

[tip-bot for Frederic Weisbecker]

Commit-ID:  3786310afe738070be31c439b8deeaeb69b9735d
Gitweb:     http://git.kernel.org/tip/3786310afe738070be31c439b8deeaeb69b9735d
Author:     Frederic Weisbecker <fweisbec@gmail.com>
AuthorDate: Wed, 9 Dec 2009 21:40:08 +0100
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Thu, 10 Dec 2009 08:30:26 +0100

perf sched: Add max delay time snapshot

When we have a maximum latency reported for a task, we need a
convenient way to find the matching location to the raw traces
or to perf sched map that shows where the task has been
eventually scheduled in. This gives a pointer to retrieve the
events that occured during this max latency.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Reviewed-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
LKML-Reference: <1260391208-6808-1-git-send-regression-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 tools/perf/builtin-sched.c |   16 ++++++++++------
 1 files changed, 10 insertions(+), 6 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index b12b23a..7cca7c1 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -140,6 +140,7 @@ struct work_atoms {
 	struct thread		*thread;
 	struct rb_node		node;
 	u64			max_lat;
+	u64			max_lat_at;
 	u64			total_lat;
 	u64			nb_atoms;
 	u64			total_runtime;
@@ -1013,8 +1014,10 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
 
 	delta = atom->sched_in_time - atom->wake_up_time;
 	atoms->total_lat += delta;
-	if (delta > atoms->max_lat)
+	if (delta > atoms->max_lat) {
 		atoms->max_lat = delta;
+		atoms->max_lat_at = timestamp;
+	}
 	atoms->nb_atoms++;
 }
 
@@ -1210,10 +1213,11 @@ static void output_lat_thread(struct work_atoms *work_list)
 
 	avg = work_list->total_lat / work_list->nb_atoms;
 
-	printf("|%11.3f ms |%9llu | avg:%9.3f ms | max:%9.3f ms |\n",
+	printf("|%11.3f ms |%9llu | avg:%9.3f ms | max:%9.3f ms | max at: %9.6f s\n",
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
-		 (double)work_list->max_lat / 1e6);
+		 (double)work_list->max_lat / 1e6,
+		 (double)work_list->max_lat_at / 1e9);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
@@ -1704,9 +1708,9 @@ static void __cmd_lat(void)
 	read_events();
 	sort_lat();
 
-	printf("\n -----------------------------------------------------------------------------------------\n");
-	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms |\n");
-	printf(" -----------------------------------------------------------------------------------------\n");
+	printf("\n ---------------------------------------------------------------------------------------------------------------\n");
+	printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at     |\n");
+	printf(" ---------------------------------------------------------------------------------------------------------------\n");
 
 	next = rb_first(&sorted_atom_root);