Eric Lee / smarc-ti-linux-kernel

Download as
Browse Code ยป

Commit 60c907abc635622964f7862c8f2977182124f89d

Authored by Arnaldo Carvalho de Melo
1 parent 752fde44fd
Exists in master and in 20 other branches dlt-processor-sdk-linux-03.00.00.04, newt-ti-linux-3.12.y, processor-sdk-linux-01.00.00, processor-sdk-linux-02.00.01, smarc-ti-linux-3.12.10, smarc-ti-linux-3.12.y, smarc-ti-linux-3.14.y, smarc-ti-linux-3.15.y, smarc-ti-lsk-linux-4.1.y, smarct3x-processor-sdk-04.01.00.06, smarct3x-processor-sdk-linux-02.00.01, smarct3x-processor-sdk-linux-03.00.00.04, smarct4x-800-processor-sdk-linux-02.00.01, smarct4x-processor-sdk-04.01.00.06, smarct4x-processor-sdk-linux-02.00.01, smarct4x-processor-sdk-linux-03.00.00.04, ti-linux-3.12.y, ti-linux-3.14.y, ti-linux-3.15.y, ti-lsk-linux-4.1.y

perf trace: Add an event duration column 

# perf trace usleep 1 | tail -10
     0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0   ) = -763342848
     0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0   ) = -763346944
     0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
     0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1                     ) = 0
     0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1                      ) = 0
     0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882                              ) = 0
     0.540 ( 0.001 ms): brk(brk: 0                                                            ) = 31928320
     0.542 ( 0.002 ms): brk(brk: 32063488                                                     ) = 32063488
     1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0                              ) = 0
     1.462 ( 0.000 ms): exit_group(error_code: 0
 #

This also comes from the tmp.perf/trace2 branch.

Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

Showing 1 changed file with 23 additions and 4 deletions Side-by-side Diff

tools/perf/builtin-trace.c
Diff comments   View file @ 60c907a
... ... @@ -46,6 +46,20 @@
46 46 struct syscall_fmt *fmt;
47 47 };
48 48  
  49 +static size_t fprintf_duration(unsigned long t, FILE *fp)
  50 +{
  51 + double duration = (double)t / NSEC_PER_MSEC;
  52 + size_t printed = fprintf(fp, "(");
  53 +
  54 + if (duration >= 1.0)
  55 + printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
  56 + else if (duration >= 0.01)
  57 + printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
  58 + else
  59 + printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
  60 + return printed + fprintf(stdout, "): ");
  61 +}
  62 +
49 63 struct thread_trace {
50 64 u64 entry_time;
51 65 u64 exit_time;
... ... @@ -92,7 +106,7 @@
92 106 {
93 107 double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;
94 108  
95   - return fprintf(fp, "%10.3f: ", ts);
  109 + return fprintf(fp, "%10.3f ", ts);
96 110 }
97 111  
98 112 static bool done = false;
99 113  
... ... @@ -103,9 +117,10 @@
103 117 }
104 118  
105 119 static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
106   - u64 tstamp, FILE *fp)
  120 + u64 duration, u64 tstamp, FILE *fp)
107 121 {
108 122 size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
  123 + printed += fprintf_duration(duration, fp);
109 124  
110 125 if (trace->multiple_threads)
111 126 printed += fprintf(fp, "%d ", thread->pid);
... ... @@ -292,7 +307,7 @@
292 307 printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed, args);
293 308  
294 309 if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
295   - trace__fprintf_entry_head(trace, thread, sample->time, stdout);
  310 + trace__fprintf_entry_head(trace, thread, 1, sample->time, stdout);
296 311 printf("%-70s\n", ttrace->entry_str);
297 312 } else
298 313 ttrace->entry_pending = true;
... ... @@ -304,6 +319,7 @@
304 319 struct perf_sample *sample)
305 320 {
306 321 int ret;
  322 + u64 duration = 0;
307 323 struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
308 324 struct thread_trace *ttrace = thread__trace(thread);
309 325 struct syscall *sc = trace__syscall_info(trace, evsel, sample);
... ... @@ -317,7 +333,10 @@
317 333  
318 334 ttrace->exit_time = sample->time;
319 335  
320   - trace__fprintf_entry_head(trace, thread, sample->time, stdout);
  336 + if (ttrace->entry_time)
  337 + duration = sample->time - ttrace->entry_time;
  338 +
  339 + trace__fprintf_entry_head(trace, thread, duration, sample->time, stdout);
321 340  
322 341 if (ttrace->entry_pending) {
323 342 printf("%-70s", ttrace->entry_str);