perf: timehist command

RFC PATCH In review David Ahern 3 participants 9 messages Jun 7, 2013 – Jul 19, 2013 perf events

Share & tools

David Ahern

author

2013-06-07 22:22 UTC #0 lore raw

cover perf: timehist command

I have commented a few times over the years about a perf-based command that does a time history analysis of task scheduling. Internal to the product I work on it has been extremely helpful debugging systems with heavy CPU contention - understanding which tasks are consuming cpu cycles over a given time window; when, why and how long a task was off the CPU and how much time did the task get when it was scheduled; inefficiencies from process bombs (shell scripts); and more.

This is the first exported version of that command. It contains the basic features. It is also availabe at:
https://github.com/dsahern/linux/commits/timehist-basic-3.9

We rely on the version that also provides time-of-day correlations. e.g., task X raised an alarm at time Y due to lack of access to a CPU. Take time Y from the log file and correlate with perf data to gain some insights into what was happening before, during and after the time of interest. The time-of-day version can be found here:
https://github.com/dsahern/linux/commits/timehist-timeofday-3.9

The command currently uses the context-switch event -- for legacy reasons with the kernel version we use. The command needs to be updated to leverage the many scheduling tracepoints and with it updating the data that can be generated from the analysis. Until then throwing it out for comments and in case others find it useful.

David Ahern (4):
perf: move setup_list from symbol.c to strlist.c
perf: add methods for setting/retrieving priv element of thread struct
perf: sample after exit loses thread correlation
perf: add timehist command

 tools/perf/Makefile           |    2 ++
 tools/perf/builtin-inject.c   |    2 +-
 tools/perf/builtin-kmem.c     |    3 ++-
 tools/perf/builtin-kvm.c      |    3 ++-
 tools/perf/builtin-lock.c     |    3 ++-
 tools/perf/builtin-sched.c    |   17 +++++++-------
 tools/perf/builtin-script.c   |    3 ++-
 tools/perf/builtin-trace.c    |    9 +++++---
 tools/perf/builtin.h          |    1 +
 tools/perf/perf.c             |    1 +
 tools/perf/perf.h             |    6 +++++
 tools/perf/tests/hists_link.c |    2 +-
 tools/perf/util/build-id.c    |   11 ++++-----
 tools/perf/util/event.c       |   11 +++++++--
 tools/perf/util/machine.c     |   49 ++++++++++++++++++++++++++++++++---------
 tools/perf/util/machine.h     |    6 +++--
 tools/perf/util/session.c     |    2 +-
 tools/perf/util/strlist.c     |   15 +++++++++++++
 tools/perf/util/strlist.h     |    2 ++
 tools/perf/util/symbol.c      |   14 ------------
 tools/perf/util/thread.h      |   12 +++++++++-
 21 files changed, 121 insertions(+), 53 deletions(-)

Signature · 1 line

1.7.10.1

David Ahern

author

2013-06-07 22:22 UTC #1 lore raw

RFC PATCH 1/4 perf: move setup_list from symbol.c to strlist.c

Code move only; no functional changes

Signed-off-by David Ahern <[email protected]>

---
 tools/perf/util/strlist.c |   15 +++++++++++++++
 tools/perf/util/strlist.h |    2 ++
 tools/perf/util/symbol.c  |   14 --------------
 3 files changed, 17 insertions(+), 14 deletions(-)

tools/perf/util/strlist.c +15 -0

index eabdce0..faa0e0f 100644
@@ -170,3 +170,18 @@ struct str_node *strlist__entry(const struct strlist *slist, unsigned int idx)
 
 	return snode;
 }
+
+int setup_list(struct strlist **list, const char *list_str,
+		              const char *list_name)
+{
+	if (list_str == NULL)
+		return 0;
+
+	*list = strlist__new(true, list_str);
+	if (!*list) {
+		pr_err("problems parsing %s list\n", list_name);
+		return -1;
+	}
+
+	return 0;
+}

tools/perf/util/strlist.h +2 -0

index 5c7f870..a5f433c 100644
@@ -16,6 +16,8 @@ struct strlist {
 	bool	       dupstr;
 };
 
+int setup_list(struct strlist **list, const char *list_str,
+	       const char *list_name);
 struct strlist *strlist__new(bool dupstr, const char *slist);
 void strlist__delete(struct strlist *slist);

tools/perf/util/symbol.c +0 ~~-14~~

index 8cf3b54..3ef8be8 100644
@@ -1164,20 +1164,6 @@ out_fail:
 	return -1;
 }
 
-static int setup_list(struct strlist **list, const char *list_str,
-		      const char *list_name)
-{
-	if (list_str == NULL)
-		return 0;
-
-	*list = strlist__new(true, list_str);
-	if (!*list) {
-		pr_err("problems parsing %s list\n", list_name);
-		return -1;
-	}
-	return 0;
-}
-
 static bool symbol__read_kptr_restrict(void)
 {
 	bool value = false;

Signature · 1 line

1.7.10.1

David Ahern

author

2013-06-07 22:22 UTC #2 lore raw

RFC PATCH 2/4 perf: add methods for setting/retrieving priv element of thread struct

In reply to David Ahern

Signed-off-by David Ahern <[email protected]>

---
 tools/perf/util/thread.h |   10 ++++++++++
 1 file changed, 10 insertions(+)

tools/perf/util/thread.h +10 -0

index eeb7ac6..5e7ba35 100644
@@ -47,4 +47,14 @@ void thread__find_addr_location(struct thread *thread, struct machine *machine,
 				u8 cpumode, enum map_type type, u64 addr,
 				struct addr_location *al,
 				symbol_filter_t filter);
+
+static inline void *thread__priv(struct thread *thread)
+{
+	return thread->priv;
+}
+
+static inline void thread__set_priv(struct thread *thread, void *p)
+{
+	thread->priv = p;
+}
 #endif	/* __PERF_THREAD_H */

Signature · 1 line

1.7.10.1

tip-bot for David Ahern

merge bot

2013-07-19 07:44 UTC #3 lore raw

[tip:perf/core] perf tools: Add methods for setting/ retrieving priv element of thread struct

perf tools: Add methods for setting/retrieving priv element of thread struct

Commit-ID:  ba58041a8f0f0437c6c33414aa0d3fcf62ba90a5
Gitweb:     http://git.kernel.org/tip/ba58041a8f0f0437c6c33414aa0d3fcf62ba90a5
Author:     David Ahern <[email protected]>
AuthorDate: Fri, 7 Jun 2013 16:22:12 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Fri, 12 Jul 2013 13:45:56 -0300

perf tools: Add methods for setting/retrieving priv element of thread struct

Signed-off-by David Ahern <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Jiri Olsa <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Stephane Eranian <[email protected]>

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Arnaldo Carvalho de Melo <[email protected]>

---
 tools/perf/util/thread.h | 10 ++++++++++
 1 file changed, 10 insertions(+)

tools/perf/util/thread.h +10 -0

index eeb7ac6..5e7ba35 100644
@@ -47,4 +47,14 @@ void thread__find_addr_location(struct thread *thread, struct machine *machine,
 				u8 cpumode, enum map_type type, u64 addr,
 				struct addr_location *al,
 				symbol_filter_t filter);
+
+static inline void *thread__priv(struct thread *thread)
+{
+	return thread->priv;
+}
+
+static inline void thread__set_priv(struct thread *thread, void *p)
+{
+	thread->priv = p;
+}
 #endif	/* __PERF_THREAD_H */

David Ahern

author

2013-06-07 22:23 UTC #4 lore raw

PATCH 3/4 perf: sample after exit loses thread correlation

In reply to David Ahern

[patch already sent separately]

Some events (context-switch, sched:sched_switch) are losing the conversion of sample data associated with a thread. For example:

$ perf record -e sched:sched_switch -c 1 -a -- sleep 5
$ perf script
<selected events shown>
    ls 30482 [000] 1379727.583037: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
    ls 30482 [000] 1379727.586339: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
:30482 30482 [000] 1379727.589462: sched:sched_switch: prev_comm=ls prev_pid=30482 ...

The last line lost the conversion from pid to comm. If you look at the events (perf script -D) you see why - a SAMPLE is generated after the EXIT:

0 1379727589449774 0x1540b0 [0x38]: PERF_RECORD_EXIT(30482:30482):(30482:30482)
0 1379727589462497 0x1540e8 [0x80]: PERF_RECORD_SAMPLE(IP, 1): 30482/30482: 0xffffffff816416f1 period: 1 addr: 0 ... thread: :30482:30482

When perf processes the EXIT event the thread is moved to the dead_threads list. When the SAMPLE event is processed no thread exists for the pid so a new one is created by machine__findnew_thread.

This patch addresses the problem by saving the exit time and checking the dead_threads list for the requested pid. If the time passed into machine_findnew_thread is non-0 the dead_threads list is walked looking for the pid. If the thread struct associated with the pid exited within 1usec of the time passed in the thread is considered a match and returned.

If samples do not contain timestamps then sample->time will be 0 and the dead_threads list will not be checked. -1 can be used to force always checking the dead_threads list and returning a match.

with this patch we get:
ls 30482 [000] 1379727.583037: sched:sched_switch: prev_comm=ls prev_pid=30482 ... ls 30482 [000] 1379727.586339: sched:sched_switch: prev_comm=ls prev_pid=30482 ... ls 30482 [000] 1379727.589462: sched:sched_switch: prev_comm=ls prev_pid=30482 ...

and

Signed-off-by David Ahern <[email protected]>

---
 tools/perf/builtin-inject.c   |    2 +-
 tools/perf/builtin-kmem.c     |    3 ++-
 tools/perf/builtin-kvm.c      |    3 ++-
 tools/perf/builtin-lock.c     |    3 ++-
 tools/perf/builtin-sched.c    |   17 +++++++-------
 tools/perf/builtin-script.c   |    3 ++-
 tools/perf/builtin-trace.c    |    9 +++++---
 tools/perf/perf.h             |    3 +++
 tools/perf/tests/hists_link.c |    2 +-
 tools/perf/util/build-id.c    |   11 ++++-----
 tools/perf/util/event.c       |   11 +++++++--
 tools/perf/util/machine.c     |   49 ++++++++++++++++++++++++++++++++---------
 tools/perf/util/machine.h     |    6 +++--
 tools/perf/util/session.c     |    2 +-
 tools/perf/util/thread.h      |    2 +-
 15 files changed, 87 insertions(+), 39 deletions(-)

tools/perf/builtin-inject.c +1 -1

index 84ad6ab..60f42c8 100644
@@ -209,7 +209,7 @@ static int perf_event__inject_buildid(struct perf_tool *tool,
 
 	cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;
 
-	thread = machine__findnew_thread(machine, event->ip.pid);
+	thread = machine__findnew_thread(machine, event->ip.pid, sample->time);
 	if (thread == NULL) {
 		pr_err("problem processing %d event, skipping it.\n",
 		       event->header.type);

tools/perf/builtin-kmem.c +2 -1

index 46878da..873647a 100644
@@ -305,8 +305,9 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,
 				struct perf_evsel *evsel,
 				struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, event->ip.pid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, event->ip.pid, sample->time);
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
 			 event->header.type);

tools/perf/builtin-kvm.c +2 -1

index 24b78ae..221213a 100644
@@ -691,10 +691,11 @@ static int process_sample_event(struct perf_tool *tool,
 				struct perf_evsel *evsel,
 				struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, sample->tid);
+	struct thread *thread;
 	struct perf_kvm_stat *kvm = container_of(tool, struct perf_kvm_stat,
 						 tool);
 
+	thread = machine__findnew_thread(machine, sample->tid, sample->time);
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
 			event->header.type);

tools/perf/builtin-lock.c +2 -1

index 4258300..1854eb9 100644
@@ -805,8 +805,9 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,
 				struct perf_evsel *evsel,
 				struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, sample->tid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, sample->tid, sample->time);
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
 			event->header.type);

tools/perf/builtin-sched.c +9 -8

index 2da2a6c..abdcdbc 100644
@@ -934,8 +934,8 @@ static int latency_switch_event(struct perf_sched *sched,
 		return -1;
 	}
 
-	sched_out = machine__findnew_thread(machine, prev_pid);
-	sched_in = machine__findnew_thread(machine, next_pid);
+	sched_out = machine__findnew_thread(machine, prev_pid, timestamp);
+	sched_in = machine__findnew_thread(machine, next_pid, timestamp);
 
 	out_events = thread_atoms_search(&sched->atom_root, sched_out, &sched->cmp_pid);
 	if (!out_events) {

@@ -978,7 +978,7 @@ static int latency_runtime_event(struct perf_sched *sched,
 {
 	const u32 pid	   = perf_evsel__intval(evsel, sample, "pid");
 	const u64 runtime  = perf_evsel__intval(evsel, sample, "runtime");
-	struct thread *thread = machine__findnew_thread(machine, pid);
+	struct thread *thread = machine__findnew_thread(machine, pid, sample->time);
 	struct work_atoms *atoms = thread_atoms_search(&sched->atom_root, thread, &sched->cmp_pid);
 	u64 timestamp = sample->time;
 	int cpu = sample->cpu;

@@ -1016,7 +1016,7 @@ static int latency_wakeup_event(struct perf_sched *sched,
 	if (!success)
 		return 0;
 
-	wakee = machine__findnew_thread(machine, pid);
+	wakee = machine__findnew_thread(machine, pid, timestamp);
 	atoms = thread_atoms_search(&sched->atom_root, wakee, &sched->cmp_pid);
 	if (!atoms) {
 		if (thread_atoms_insert(sched, wakee))

@@ -1070,7 +1070,7 @@ static int latency_migrate_task_event(struct perf_sched *sched,
 	if (sched->profile_cpu == -1)
 		return 0;
 
-	migrant = machine__findnew_thread(machine, pid);
+	migrant = machine__findnew_thread(machine, pid, timestamp);
 	atoms = thread_atoms_search(&sched->atom_root, migrant, &sched->cmp_pid);
 	if (!atoms) {
 		if (thread_atoms_insert(sched, migrant))

@@ -1289,8 +1289,8 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
 		return -1;
 	}
 
-	sched_out = machine__findnew_thread(machine, prev_pid);
-	sched_in = machine__findnew_thread(machine, next_pid);
+	sched_out = machine__findnew_thread(machine, prev_pid, timestamp);
+	sched_in = machine__findnew_thread(machine, next_pid, timestamp);
 
 	sched->curr_thread[this_cpu] = sched_in;

@@ -1425,9 +1425,10 @@ static int perf_sched__process_tracepoint_sample(struct perf_tool *tool __maybe_
 						 struct perf_evsel *evsel,
 						 struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, sample->tid);
+	struct thread *thread;
 	int err = 0;
 
+	thread = machine__findnew_thread(machine, sample->tid, sample->time);
 	if (thread == NULL) {
 		pr_debug("problem processing %s event, skipping it.\n",
 			 perf_evsel__name(evsel));

tools/perf/builtin-script.c +2 -1

index 92d4658..2e07c70 100644
@@ -479,8 +479,9 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,
 				struct machine *machine)
 {
 	struct addr_location al;
-	struct thread *thread = machine__findnew_thread(machine, event->ip.tid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, event->ip.tid, sample->time);
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
 			 event->header.type);

tools/perf/builtin-trace.c +6 -3

index ab3ed4a..937de13 100644
@@ -301,7 +301,8 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 	char *msg;
 	void *args;
 	size_t printed = 0;
-	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
+	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid,
+							sample->time);
 	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
 	struct thread_trace *ttrace = thread__trace(thread);

@@ -344,7 +345,8 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 {
 	int ret;
 	u64 duration = 0;
-	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
+	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid,
+							sample->time);
 	struct thread_trace *ttrace = thread__trace(thread);
 	struct syscall *sc = trace__syscall_info(trace, evsel, sample);

@@ -397,7 +399,8 @@ static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evs
 {
         u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
 	double runtime_ms = (double)runtime / NSEC_PER_MSEC;
-	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
+	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid,
+							sample->time);
 	struct thread_trace *ttrace = thread__trace(thread);
 
 	if (ttrace == NULL)

tools/perf/perf.h +3 -0

index 32bd102..c98e9c9 100644
@@ -125,6 +125,9 @@
 #ifndef NSEC_PER_SEC
 # define NSEC_PER_SEC			1000000000ULL
 #endif
+#ifndef USECS_PER_SEC
+#define USECS_PER_SEC           1000000ULL
+#endif
 
 static inline unsigned long long rdclock(void)
 {

tools/perf/tests/hists_link.c +1 -1

index 89085a9..963d21e 100644
@@ -88,7 +88,7 @@ static struct machine *setup_fake_machine(struct machines *machines)
 	for (i = 0; i < ARRAY_SIZE(fake_threads); i++) {
 		struct thread *thread;
 
-		thread = machine__findnew_thread(machine, fake_threads[i].pid);
+		thread = machine__findnew_thread(machine, fake_threads[i].pid, 0);
 		if (thread == NULL)
 			goto out;

tools/perf/util/build-id.c +6 -5

index 5295625..c524906 100644
@@ -18,14 +18,15 @@
 
 int build_id__mark_dso_hit(struct perf_tool *tool __maybe_unused,
 			   union perf_event *event,
-			   struct perf_sample *sample __maybe_unused,
+			   struct perf_sample *sample,
 			   struct perf_evsel *evsel __maybe_unused,
 			   struct machine *machine)
 {
 	struct addr_location al;
 	u8 cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;
-	struct thread *thread = machine__findnew_thread(machine, event->ip.pid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, event->ip.pid, sample->time);
 	if (thread == NULL) {
 		pr_err("problem processing %d event, skipping it.\n",
 			event->header.type);

@@ -43,12 +44,12 @@ int build_id__mark_dso_hit(struct perf_tool *tool __maybe_unused,
 
 static int perf_event__exit_del_thread(struct perf_tool *tool __maybe_unused,
 				       union perf_event *event,
-				       struct perf_sample *sample
-				       __maybe_unused,
+				       struct perf_sample *sample,
 				       struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, event->fork.tid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, event->fork.tid, sample->time);
 	dump_printf("(%d:%d):(%d:%d)\n", event->fork.pid, event->fork.tid,
 		    event->fork.ppid, event->fork.ptid);

tools/perf/util/event.c +9 -2

index 5cd13d7..4c15f82 100644
@@ -552,9 +552,15 @@ int perf_event__process_fork(struct perf_tool *tool __maybe_unused,
 
 int perf_event__process_exit(struct perf_tool *tool __maybe_unused,
 			     union perf_event *event,
-			     struct perf_sample *sample __maybe_unused,
+			     struct perf_sample *sample,
 			     struct machine *machine)
 {
+	struct thread *thread;
+
+	thread = machine__find_thread(machine, event->fork.tid, 0);
+	if (thread)
+		thread->t_exit = sample->time;
+
 	return machine__process_exit_event(machine, event);
 }

@@ -677,8 +683,9 @@ int perf_event__preprocess_sample(const union perf_event *event,
 				  symbol_filter_t filter)
 {
 	u8 cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;
-	struct thread *thread = machine__findnew_thread(machine, event->ip.pid);
+	struct thread *thread;
 
+	thread = machine__findnew_thread(machine, event->ip.pid, sample->time);
 	if (thread == NULL)
 		return -1;

tools/perf/util/machine.c +38 ~~-11~~

101 lines not on this page · raw message

tools/perf/util/machine.h +4 -2

index 7794068..30612f3 100644
@@ -36,7 +36,8 @@ struct map *machine__kernel_map(struct machine *machine, enum map_type type)
 	return machine->vmlinux_maps[type];
 }
 
-struct thread *machine__find_thread(struct machine *machine, pid_t pid);
+struct thread *machine__find_thread(struct machine *machine, pid_t pid,
+				    u64 sample_time);
 
 int machine__process_comm_event(struct machine *machine, union perf_event *event);
 int machine__process_exit_event(struct machine *machine, union perf_event *event);

@@ -99,7 +100,8 @@ static inline bool machine__is_host(struct machine *machine)
 	return machine ? machine->pid == HOST_KERNEL_ID : false;
 }
 
-struct thread *machine__findnew_thread(struct machine *machine, pid_t pid);
+struct thread *machine__findnew_thread(struct machine *machine, pid_t pid,
+				       u64 sample_time);
 
 size_t machine__fprintf(struct machine *machine, FILE *fp);

tools/perf/util/session.c +1 -1

index cf1fe01..504ae0c 100644
@@ -999,7 +999,7 @@ void perf_event_header__bswap(struct perf_event_header *self)
 
 struct thread *perf_session__findnew(struct perf_session *session, pid_t pid)
 {
-	return machine__findnew_thread(&session->machines.host, pid);
+	return machine__findnew_thread(&session->machines.host, pid, 0);
 }
 
 static struct thread *perf_session__register_idle_thread(struct perf_session *self)

tools/perf/util/thread.h +1 -1

index 5e7ba35..c545502 100644
@@ -18,7 +18,7 @@ struct thread {
 	bool			comm_set;
 	char			*comm;
 	int			comm_len;
-
+	u64			t_exit;
 	void			*priv;
 };

Signature · 1 line

1.7.10.1

David Ahern

author

2013-06-07 22:22 UTC #5 lore raw

RFC PATCH 4/4 perf: add timehist command

In reply to David Ahern

perf timehist provides an analysis of scheduling event data. Right now it uses the context-switch softwar event; it needs to be updated to use the scheduling tracepoints along with analysis enhancements those tracepoints provide. For now, the context switch event provides a well-tested start point.

This command has been extremely helpful debugging systems with heavy CPU contention.

Use case:
1. collect context switch data for the system (or cpu) along with the stack trace:
perf record -e cs -c 1 -ag -- <workload>

2. run the timehist command to show the time between schedule-in times (ie., how long did the task go between access to the CPU) as well as run times (ie., how long did the task run once scheduled) and the stack trace of the task when scheduled out:

perf timehist

time cpu task [tid/pid] b/n time run time
------------- ---- ----------------- --------- ---------

227959.352628 [02] make[17133]       0.004877  0.000285  do_wait         sys_wait4 ...
227959.352762 [03] sh[17136]         0.000000  0.000135  __cond_resched  _cond_resched  ...
227959.352777 [03] migration/3[23]   0.003163  0.000014  smpboot_thread_fn kthread      ...
227959.352801 [02] <idle>            0.000285  0.000173  cpu_idle        start_secondary
227959.353552 [02] sh[17136]         0.000038  0.000750  do_exit         do_group_exit   ...
227959.353564 [04] <idle>            0.000014  0.001113  cpu_idle        start_secondary
227959.353722 [04] make[17133]       0.000936  0.000157  do_exit         do_group_exit   ...
227959.353761 [06] <idle>            0.001210  0.021919  cpu_idle        start_secondary
227959.353900 [06] make[17127]       0.001310  0.000139  wait_for_completion_killable do_fork ...
227959.353921 [03] <idle>            0.000150  0.001143  cpu_idle        start_secondary
227959.353945 [03] make[17137]       0.000000  0.000023  __cond_resched  _cond_resched   ...
227959.353962 [03] migration/3[23]   0.001167  0.000017  smpboot_thread_fn kthread         ret_from_fork
227959.353990 [02] <idle>            0.000750  0.000438  cpu_idle        start_secondary
227959.354034 [03] <idle>            0.000041  0.000071  cpu_idle        start_secondary
227959.354044 [03] rcu_sched[10]     0.002931  0.000010  rcu_gp_kthread  kthread         ret_from_fork
227959.354089 [06] <idle>            0.000139  0.000189  cpu_idle        start_secondary
227959.354096 [06] rcu_sched[10]     0.000044  0.000006  rcu_gp_kthread  kthread         ret_from_fork
227959.354110 [06] make[17127]       0.000195  0.000014  pipe_wait       pipe_read       ...
227959.354382 [00] <idle>            0.000013  0.003307  cpu_idle        rest_init       ...
227959.354452 [00] qemu-kvm[25781/25777]  0.000000  0.000069  kvm_vcpu_block  kvm_arch_vcpu_ioctl_run ...
227959.354498 [04] <idle>                 0.000157  0.000776  cpu_idle        start_secondary

Additional options:
i. --cpu-visual - useful for multi-core. Adds a field to highlight
visually which cpu had an event

ii. --summary - show a run time summary of how long each task ran over
the time interval analyzed

Runtime summary (times are in seconds)
comm parent number run-time min-run max-run avg-run stddev(%)
...

          qemu-kvm[25777]     -1       8   0.000398   0.000037   0.000076   0.000049   8.99
    qemu-kvm[25781/25777]     -1      22   0.001532   0.000040   0.000193   0.000069  10.39
    qemu-kvm[25782/25777]     -1      21   0.001536   0.000038   0.000255   0.000073  14.13
              sshd[28339]     -1      12   0.001337   0.000073   0.000129   0.000111   4.69

...

Terminated tasks:

                sh[17126]  17125       2   0.000778
              make[17125]  17124       3   0.002007
                sh[17129]  17128       2   0.000945
                sh[17130]  17128       2   0.001600
              make[17128]  17127       4   0.002272

...

iii. --tree - show parent-child summary with runtimes:

Parent-child relationships
--------------------------
...
perf[17124] 0.002964

    make[17125]  0.002007
        sh[17126]  0.000778
    make[17127]  0.101272
        make[17128]  0.002272
            sh[17129]  0.000945
            sh[17130]  0.001600
        make[17131]  0.001888
        make[17132]  0.000715
        make[17133]  0.002273
            sh[17134]  0.002230
                gcc[17135]  0.002527
            sh[17136]  0.000886
        make[17137]  0.002408
            sh[17138]  0.002420
                gcc[17139]  0.010634
                gcc[17140]  0.006208

This command has been a work in progress for years and many more options and features will be added in time.

Signed-off-by David Ahern <[email protected]>

---
 tools/perf/Makefile           |    2 +
 tools/perf/builtin-timehist.c | 1047 +++++++++++++++++++++++++++++++++++++++++
 tools/perf/builtin.h          |    1 +
 tools/perf/perf.c             |    1 +
 tools/perf/perf.h             |    3 +
 tools/perf/util/time-utils.c  |  230 +++++++++
 tools/perf/util/time-utils.h  |   12 +
 7 files changed, 1296 insertions(+)
 create mode 100644 tools/perf/builtin-timehist.c
 create mode 100644 tools/perf/util/time-utils.c
 create mode 100644 tools/perf/util/time-utils.h

tools/perf/Makefile +2 -0

index 203cb0e..731d1a4 100644
@@ -423,6 +423,8 @@ BUILTIN_OBJS += $(OUTPUT)builtin-kvm.o
 BUILTIN_OBJS += $(OUTPUT)builtin-inject.o
 BUILTIN_OBJS += $(OUTPUT)tests/builtin-test.o
 BUILTIN_OBJS += $(OUTPUT)builtin-mem.o
+BUILTIN_OBJS += $(OUTPUT)builtin-timehist.o
+BUILTIN_OBJS += $(OUTPUT)util/time-utils.o
 
 PERFLIBS = $(LIB_FILE) $(LIBLK) $(LIBTRACEEVENT)

tools/perf/builtin-timehist.c new file +1047 -0

1,047 lines not on this page · raw message

tools/perf/builtin.h +1 -0

index b210d62..f593f41 100644
@@ -37,6 +37,7 @@ extern int cmd_test(int argc, const char **argv, const char *prefix);
 extern int cmd_trace(int argc, const char **argv, const char *prefix);
 extern int cmd_inject(int argc, const char **argv, const char *prefix);
 extern int cmd_mem(int argc, const char **argv, const char *prefix);
+extern int cmd_timehist(int argc, const char **argv, const char *prefix);
 
 extern int find_scripts(char **scripts_array, char **scripts_path_array);
 #endif

tools/perf/perf.c +1 -0

index 85e1aed..dc8ae0d 100644
@@ -61,6 +61,7 @@ static struct cmd_struct commands[] = {
 #endif
 	{ "inject",	cmd_inject,	0 },
 	{ "mem",	cmd_mem,	0 },
+	{ "timehist",   cmd_timehist,   0 },
 };
 
 struct pager_config {

tools/perf/perf.h +3 -0

index c98e9c9..07f17c4 100644
@@ -128,6 +128,9 @@
 #ifndef USECS_PER_SEC
 #define USECS_PER_SEC           1000000ULL
 #endif
+#ifndef NSEC_PER_USEC
+# define NSEC_PER_USEC         1000ULL
+#endif
 
 static inline unsigned long long rdclock(void)
 {

tools/perf/util/time-utils.c new file +230 -0

230 lines not on this page · raw message

tools/perf/util/time-utils.h new file +12 -0

new file mode 100644
index 0000000..a54110b
@@ -0,0 +1,12 @@
+#ifndef _TIME_UTIL_H_
+#define _TIME_UTIL_H_
+
+#define DEFAULT_TOD_FMT "%H:%M:%S"
+
+int perf_time__parse_str(const char *str, const char *fmt);
+
+int perf_time__tod_str(char *buf, int buflen, u64 t, const char *fmt);
+
+bool perf_time__skip_sample(struct perf_sample *sample);
+
+#endif

Signature · 1 line

1.7.10.1

Ingo Molnar

2013-06-20 10:47 UTC #6 lore raw

Re: [RFC PATCH 4/4] perf: add timehist command

Quoted 92 lines · David Ahern

perf timehist provides an analysis of scheduling event data. Right now it uses the context-switch softwar event; it needs to be updated to use the scheduling tracepoints along with analysis enhancements those tracepoints provide. For now, the context switch event provides a well-tested start point.
This command has been extremely helpful debugging systems with heavy CPU contention.
Use case:
1. collect context switch data for the system (or cpu) along with the stack trace:
perf record -e cs -c 1 -ag -- <workload>
2. run the timehist command to show the time between schedule-in times (ie., how long did the task go between access to the CPU) as well as run times (ie., how long did the task run once scheduled) and the stack trace of the task when scheduled out:
perf timehist
time cpu task [tid/pid] b/n time run time
------------- ---- ----------------- --------- ---------
227959.352628 [02] make[17133]       0.004877  0.000285  do_wait         sys_wait4 ...
227959.352762 [03] sh[17136]         0.000000  0.000135  __cond_resched  _cond_resched  ...
227959.352777 [03] migration/3[23]   0.003163  0.000014  smpboot_thread_fn kthread      ...
227959.352801 [02] <idle>            0.000285  0.000173  cpu_idle        start_secondary
227959.353552 [02] sh[17136]         0.000038  0.000750  do_exit         do_group_exit   ...
227959.353564 [04] <idle>            0.000014  0.001113  cpu_idle        start_secondary
227959.353722 [04] make[17133]       0.000936  0.000157  do_exit         do_group_exit   ...
227959.353761 [06] <idle>            0.001210  0.021919  cpu_idle        start_secondary
227959.353900 [06] make[17127]       0.001310  0.000139  wait_for_completion_killable do_fork ...
227959.353921 [03] <idle>            0.000150  0.001143  cpu_idle        start_secondary
227959.353945 [03] make[17137]       0.000000  0.000023  __cond_resched  _cond_resched   ...
227959.353962 [03] migration/3[23]   0.001167  0.000017  smpboot_thread_fn kthread         ret_from_fork
227959.353990 [02] <idle>            0.000750  0.000438  cpu_idle        start_secondary
227959.354034 [03] <idle>            0.000041  0.000071  cpu_idle        start_secondary
227959.354044 [03] rcu_sched[10]     0.002931  0.000010  rcu_gp_kthread  kthread         ret_from_fork
227959.354089 [06] <idle>            0.000139  0.000189  cpu_idle        start_secondary
227959.354096 [06] rcu_sched[10]     0.000044  0.000006  rcu_gp_kthread  kthread         ret_from_fork
227959.354110 [06] make[17127]       0.000195  0.000014  pipe_wait       pipe_read       ...
227959.354382 [00] <idle>            0.000013  0.003307  cpu_idle        rest_init       ...
227959.354452 [00] qemu-kvm[25781/25777]  0.000000  0.000069  kvm_vcpu_block  kvm_arch_vcpu_ioctl_run ...
227959.354498 [04] <idle>                 0.000157  0.000776  cpu_idle        start_secondary
Additional options:
i. --cpu-visual - useful for multi-core. Adds a field to highlight
visually which cpu had an event
ii. --summary - show a run time summary of how long each task ran over
the time interval analyzed
Runtime summary (times are in seconds)
comm parent number run-time min-run max-run avg-run stddev(%)
...
          qemu-kvm[25777]     -1       8   0.000398   0.000037   0.000076   0.000049   8.99
    qemu-kvm[25781/25777]     -1      22   0.001532   0.000040   0.000193   0.000069  10.39
    qemu-kvm[25782/25777]     -1      21   0.001536   0.000038   0.000255   0.000073  14.13
              sshd[28339]     -1      12   0.001337   0.000073   0.000129   0.000111   4.69
...
Terminated tasks:
                sh[17126]  17125       2   0.000778
              make[17125]  17124       3   0.002007
                sh[17129]  17128       2   0.000945
                sh[17130]  17128       2   0.001600
              make[17128]  17127       4   0.002272
...
iii. --tree - show parent-child summary with runtimes:
Parent-child relationships
--------------------------
...
perf[17124] 0.002964
    make[17125]  0.002007
        sh[17126]  0.000778
    make[17127]  0.101272
        make[17128]  0.002272
            sh[17129]  0.000945
            sh[17130]  0.001600
        make[17131]  0.001888
        make[17132]  0.000715
        make[17133]  0.002273
            sh[17134]  0.002230
                gcc[17135]  0.002527
            sh[17136]  0.000886
        make[17137]  0.002408
            sh[17138]  0.002420
                gcc[17139]  0.010634
                gcc[17140]  0.006208

Quoted 2 lines

This command has been a work in progress for years and many more options and features will be added in time.

Looks very useful!

This is the kind of analysis I thought 'perf sched' might one day end up doing.

Do you plan to submit it non-RFC, to be merged?

Your tool could take over the somewhat stale 'perf sched' command as well btw., while possibly carrying over some of the perf sched features like 'replay'.

'perf sched record' enough events to support the ones you need:

Quoted 1 line

perf record -e cs -c 1 -ag -- <workload>

plus:

 'perf sched sum[mary]'       # show the summary
 'perf sched tree'            # could show the tree.
 'perf sched hist[ogram]'     # would show the histogram

i.e. feel free to take over 'perf sched' to suit your 'timehist' workflow and logic. As the main (and somewhat overworked) author of 'perf sched' I have no problem with you taking it over, at all.

You could also add a 'perf timehist' alias to the new 'perf sched' command, to keep your original (and well established?) naming.

Thanks,

Ingo

David Ahern

author

2013-06-20 15:00 UTC #7 lore raw

Re: [RFC PATCH 4/4] perf: add timehist command

Quoted 6 lines · Ingo Molnar

Looks very useful!
This is the kind of analysis I thought 'perf sched' might one day end up doing.
Do you plan to submit it non-RFC, to be merged?

Yes. Hopefully I can find time to work on it over the next 2 months for 3.12, 3.13 at the latest.

Quoted 10 lines

Your tool could take over the somewhat stale 'perf sched' command as well btw., while possibly carrying over some of the perf sched features like 'replay'.
'perf sched record' enough events to support the ones you need:
Quoted 1 line
Quoted 1 line
perf record -e cs -c 1 -ag -- <workload>
plus:

Quoted 7 lines

  'perf sched sum[mary]'       # show the summary
  'perf sched tree'            # could show the tree.
  'perf sched hist[ogram]'     # would show the histogram
i.e. feel free to take over 'perf sched' to suit your 'timehist' workflow and logic. As the main (and somewhat overworked) author of 'perf sched' I have no problem with you taking it over, at all.

It should be part of perf-sched. It is not at the moment for a number of (mostly shortcut) reasons. For the next iteration I will look at combining it with perf-sched and in the process I will go through the existing code for perf-sched.

As an FYI I also have a daemon that provides the functionality in a flight recorder mode but with data dumped only when requested. Future project to integrate that with perf. ;-)

Quoted 3 lines

You could also add a 'perf timehist' alias to the new 'perf sched' command, to keep your original (and well established?) naming.

It is well established internally, so a convenience shortcut would lessen the pain of moving to newer perf versions when the time comes.

David

Ingo Molnar

2013-06-20 15:26 UTC #8 lore raw

Re: [RFC PATCH 4/4] perf: add timehist command

Quoted 25 lines · David Ahern

Quoted 6 lines · Ingo Molnar
Looks very useful!
This is the kind of analysis I thought 'perf sched' might one day end up doing.
Do you plan to submit it non-RFC, to be merged?
Yes. Hopefully I can find time to work on it over the next 2 months for 3.12, 3.13 at the latest.
Quoted 14 lines
Your tool could take over the somewhat stale 'perf sched' command as well btw., while possibly carrying over some of the perf sched features like 'replay'.
'perf sched record' enough events to support the ones you need:
Quoted 1 line
Quoted 1 line
perf record -e cs -c 1 -ag -- <workload>
plus:
 'perf sched sum[mary]'       # show the summary
 'perf sched tree'            # could show the tree.
 'perf sched hist[ogram]'     # would show the histogram

Quoted 8 lines

Quoted 3 lines
i.e. feel free to take over 'perf sched' to suit your 'timehist' workflow and logic. As the main (and somewhat overworked) author of 'perf sched' I have no problem with you taking it over, at all.
It should be part of perf-sched. It is not at the moment for a number of (mostly shortcut) reasons. For the next iteration I will look at combining it with perf-sched and in the process I will go through the existing code for perf-sched.

If it's easier you could start by using your code as the starting point and add back perf sched features after that. I find your tool fundamentally more valuable because it's in active use.

Quoted 3 lines

As an FYI I also have a daemon that provides the functionality in a flight recorder mode but with data dumped only when requested. Future project to integrate that with perf. ;-)

:-)

Thanks,

Ingo