Commit dc02bf71 authored by Ingo Molnar's avatar Ingo Molnar

perf sched: Account for lost events, increase default buffering

Output such lost event and state machine weirdness stats:

   TOTAL:                |  14974.910 ms |    46384 |
  ---------------------------------------------------
   INFO: 8.865% lost events (19132 out of 215819, in 8 chunks)
   INFO: 0.198% state machine bugs (49 out of 24708) (due to lost events?)

And increase buffering to -m 1024 (4 MB) by default. Since we
use output multiplexing that kind of space is needed.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
parent 39aeb52f
...@@ -117,7 +117,11 @@ static u64 run_avg; ...@@ -117,7 +117,11 @@ static u64 run_avg;
static unsigned long replay_repeat = 10; static unsigned long replay_repeat = 10;
static unsigned long nr_timestamps; static unsigned long nr_timestamps;
static unsigned long unordered_timestamps; static unsigned long nr_unordered_timestamps;
static unsigned long nr_state_machine_bugs;
static unsigned long nr_events;
static unsigned long nr_lost_chunks;
static unsigned long nr_lost_events;
#define TASK_STATE_TO_CHAR_STR "RSDTtZX" #define TASK_STATE_TO_CHAR_STR "RSDTtZX"
...@@ -668,14 +672,14 @@ process_comm_event(event_t *event, unsigned long offset, unsigned long head) ...@@ -668,14 +672,14 @@ process_comm_event(event_t *event, unsigned long offset, unsigned long head)
thread = threads__findnew(event->comm.pid, &threads, &last_match); thread = threads__findnew(event->comm.pid, &threads, &last_match);
dump_printf("%p [%p]: PERF_EVENT_COMM: %s:%d\n", dump_printf("%p [%p]: perf_event_comm: %s:%d\n",
(void *)(offset + head), (void *)(offset + head),
(void *)(long)(event->header.size), (void *)(long)(event->header.size),
event->comm.comm, event->comm.pid); event->comm.comm, event->comm.pid);
if (thread == NULL || if (thread == NULL ||
thread__set_comm(thread, event->comm.comm)) { thread__set_comm(thread, event->comm.comm)) {
dump_printf("problem processing PERF_EVENT_COMM, skipping event.\n"); dump_printf("problem processing perf_event_comm, skipping event.\n");
return -1; return -1;
} }
total_comm++; total_comm++;
...@@ -1168,14 +1172,12 @@ latency_wakeup_event(struct trace_wakeup_event *wakeup_event, ...@@ -1168,14 +1172,12 @@ latency_wakeup_event(struct trace_wakeup_event *wakeup_event,
atom = list_entry(atoms->work_list.prev, struct work_atom, list); atom = list_entry(atoms->work_list.prev, struct work_atom, list);
if (atom->state != THREAD_SLEEPING) { if (atom->state != THREAD_SLEEPING)
printf("boo2\n"); nr_state_machine_bugs++;
return;
}
nr_timestamps++; nr_timestamps++;
if (atom->sched_out_time > timestamp) { if (atom->sched_out_time > timestamp) {
unordered_timestamps++; nr_unordered_timestamps++;
return; return;
} }
...@@ -1214,7 +1216,7 @@ static void output_lat_thread(struct work_atoms *work_list) ...@@ -1214,7 +1216,7 @@ static void output_lat_thread(struct work_atoms *work_list)
avg = work_list->total_lat / work_list->nb_atoms; avg = work_list->total_lat / work_list->nb_atoms;
printf("|%9.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 |\n",
(double)work_list->total_runtime / 1e6, (double)work_list->total_runtime / 1e6,
work_list->nb_atoms, (double)avg / 1e6, work_list->nb_atoms, (double)avg / 1e6,
(double)work_list->max_lat / 1e6); (double)work_list->max_lat / 1e6);
...@@ -1359,9 +1361,9 @@ static void __cmd_lat(void) ...@@ -1359,9 +1361,9 @@ static void __cmd_lat(void)
read_events(); read_events();
sort_lat(); sort_lat();
printf("\n ---------------------------------------------------------------------------------------\n"); printf("\n -----------------------------------------------------------------------------------------\n");
printf(" Task | Runtime ms | Switches | Average delay ms | Maximum delay ms |\n"); printf(" Task | Runtime ms | Switches | Average delay ms | Maximum delay ms |\n");
printf(" ---------------------------------------------------------------------------------------\n"); printf(" -----------------------------------------------------------------------------------------\n");
next = rb_first(&sorted_atom_root); next = rb_first(&sorted_atom_root);
...@@ -1373,18 +1375,32 @@ static void __cmd_lat(void) ...@@ -1373,18 +1375,32 @@ static void __cmd_lat(void)
next = rb_next(next); next = rb_next(next);
} }
printf(" ---------------------------------------------------------------------------------------\n"); printf(" -----------------------------------------------------------------------------------------\n");
printf(" TOTAL: |%9.3f ms |%9Ld |", printf(" TOTAL: |%11.3f ms |%9Ld |\n",
(double)all_runtime/1e6, all_count); (double)all_runtime/1e6, all_count);
if (unordered_timestamps && nr_timestamps) { printf(" ---------------------------------------------------\n");
printf(" INFO: %.2f%% unordered events.\n", if (nr_unordered_timestamps && nr_timestamps) {
(double)unordered_timestamps/(double)nr_timestamps*100.0); printf(" INFO: %.3f%% unordered timestamps (%ld out of %ld)\n",
(double)nr_unordered_timestamps/(double)nr_timestamps*100.0,
nr_unordered_timestamps, nr_timestamps);
} else { } else {
}
if (nr_lost_events && nr_events) {
printf(" INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
(double)nr_lost_events/(double)nr_events*100.0,
nr_lost_events, nr_events, nr_lost_chunks);
}
if (nr_state_machine_bugs && nr_timestamps) {
printf(" INFO: %.3f%% state machine bugs (%ld out of %ld)",
(double)nr_state_machine_bugs/(double)nr_timestamps*100.0,
nr_state_machine_bugs, nr_timestamps);
if (nr_lost_events)
printf(" (due to lost events?)");
printf("\n"); printf("\n");
} }
printf("\n");
printf(" -------------------------------------------------\n\n");
} }
static struct trace_sched_handler *trace_handler; static struct trace_sched_handler *trace_handler;
...@@ -1585,8 +1601,13 @@ process_event(event_t *event, unsigned long offset, unsigned long head) ...@@ -1585,8 +1601,13 @@ process_event(event_t *event, unsigned long offset, unsigned long head)
{ {
trace_event(event); trace_event(event);
nr_events++;
switch (event->header.type) { switch (event->header.type) {
case PERF_EVENT_MMAP ... PERF_EVENT_LOST: case PERF_EVENT_MMAP:
return 0;
case PERF_EVENT_LOST:
nr_lost_chunks++;
nr_lost_events += event->lost.lost;
return 0; return 0;
case PERF_EVENT_COMM: case PERF_EVENT_COMM:
...@@ -1768,6 +1789,7 @@ static const char *record_args[] = { ...@@ -1768,6 +1789,7 @@ static const char *record_args[] = {
"-R", "-R",
"-M", "-M",
"-f", "-f",
"-m", "1024",
"-c", "1", "-c", "1",
"-e", "sched:sched_switch:r", "-e", "sched:sched_switch:r",
"-e", "sched:sched_stat_wait:r", "-e", "sched:sched_stat_wait:r",
......
...@@ -52,7 +52,7 @@ struct lost_event { ...@@ -52,7 +52,7 @@ struct lost_event {
*/ */
struct read_event { struct read_event {
struct perf_event_header header; struct perf_event_header header;
u32 pid,tid; u32 pid, tid;
u64 value; u64 value;
u64 time_enabled; u64 time_enabled;
u64 time_running; u64 time_running;
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment