Re: [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler

From: Steven Rostedt
Date: Mon Jul 11 2016 - 12:55:35 EST

On Fri, 8 Jul 2016 14:56:12 +0900
Namhyung Kim <namhyung@xxxxxxxxx> wrote:

> When a task was migrated to other cpu in the middle of a function, the
> fgraph_exit record will be in a different cpu than the enter record.
> But currently fgraph_ent_handler() only peeks at the same cpu so it
> could read an incorrect record.
>
> For example, please see following raw records:
>
> bash-10478 [007] 73.454273: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [000] 73.454650: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x111a37483c rettime=0x111a3d0285 overrun=0x0 depth=0
> bash-10478 [000] 74.456383: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [000] 74.456655: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x1155f24337 rettime=0x1155f66559 overrun=0x0 depth=0
> bash-10478 [000] 75.458517: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [001] 75.458849: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x1191ad9de0 rettime=0x1191b2a6aa overrun=0x0 depth=0
> bash-10478 [001] 76.460482: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [000] 76.460679: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x11cd6662b4 rettime=0x11cd695e03 overrun=0x0 depth=0
> bash-10478 [000] 77.462334: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [004] 77.462564: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x12091d71c4 rettime=0x120920e977 overrun=0x0 depth=0
> bash-10478 [004] 78.464315: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [001] 78.464644: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x1244d674de rettime=0x1244db7329 overrun=0x0 depth=0
> bash-10478 [001] 79.466018: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [004] 79.466326: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x12808b3940 rettime=0x12808fe819 overrun=0x0 depth=0
> bash-10478 [004] 80.468005: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [002] 80.468291: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x12bc44551f rettime=0x12bc48ac9a overrun=0x0 depth=0
> bash-10478 [002] 81.469718: funcgraph_entry: func=0xffffffff8123bf90 depth=0
> bash-10478 [007] 81.470088: funcgraph_exit: func=0xffffffff8123bf90 calltime=0x12f7f945b8 rettime=0x12f7fee028 overrun=0x0 depth=0
>
> The first entry was call to cma_alloc function, it was on cpu 7 but the
> task was migrated to cpu 0 before returning from the function.
> Currently trace-cmd shows like below:
>
> bash-10478 [007] 73.454273: funcgraph_entry: ! 367.216 us | cma_alloc();
> bash-10478 [000] 73.454650: funcgraph_exit: ! 375.369 us | }
> bash-10478 [000] 74.456383: funcgraph_entry: ! 270.882 us | cma_alloc();
> bash-10478 [000] 75.458517: funcgraph_entry: ! 195.407 us | cma_alloc();
> bash-10478 [001] 75.458849: funcgraph_exit: ! 329.930 us | }
> bash-10478 [001] 76.460482: funcgraph_entry: ! 327.243 us | cma_alloc();
> bash-10478 [000] 77.462334: funcgraph_entry: ! 293.465 us | cma_alloc();
> bash-10478 [004] 77.462564: funcgraph_exit: ! 227.251 us | }
> bash-10478 [004] 78.464315: funcgraph_entry: ! 306.905 us | cma_alloc();
> bash-10478 [001] 79.466018: funcgraph_entry: ! 303.196 us | cma_alloc();
> bash-10478 [004] 80.468005: funcgraph_entry: | cma_alloc() {
> bash-10478 [002] 80.468291: funcgraph_exit: ! 284.539 us | }
> bash-10478 [002] 81.469718: funcgraph_entry: ! 323.215 us | cma_alloc();
>
> This is because the first funcgraph_entry on cpu 7 matched to the last
> funcgraph_exit on cpu 7. And second funcgraph_exit on cpu 0 was shown
> alone. We need to match record from all cpu rather than the same cpu.
> In this case, entry on cpu 7 should be paired with exit on cpu 0.
>
> With this patch, the output look like below:
>
> bash-10478 [007] 73.454273: funcgraph_entry: ! 375.369 us | cma_alloc();
> bash-10478 [000] 74.456383: funcgraph_entry: ! 270.882 us | cma_alloc();
> bash-10478 [000] 75.458517: funcgraph_entry: ! 329.930 us | cma_alloc();
> bash-10478 [001] 76.460482: funcgraph_entry: ! 195.407 us | cma_alloc();
> bash-10478 [000] 77.462334: funcgraph_entry: ! 227.251 us | cma_alloc();
> bash-10478 [004] 78.464315: funcgraph_entry: ! 327.243 us | cma_alloc();
> bash-10478 [001] 79.466018: funcgraph_entry: ! 306.905 us | cma_alloc();
> bash-10478 [004] 80.468005: funcgraph_entry: ! 284.539 us | cma_alloc();
> bash-10478 [002] 81.469718: funcgraph_entry: ! 367.216 us | cma_alloc();
>
> Maybe we can separate enter and exit if they happened on different
> cpu. Anyway the time duration has correct value now.
>
> Reported-by: Joonsoo Kim <iamjoonsoo.kim@xxxxxxx>
> Signed-off-by: Namhyung Kim <namhyung@xxxxxxxxxx>
> ---
> trace-ftrace.c | 4 ++--
> 1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/trace-ftrace.c b/trace-ftrace.c
> index 636b08b..edc9349 100644
> --- a/trace-ftrace.c
> +++ b/trace-ftrace.c
> @@ -297,7 +297,7 @@ fgraph_ent_handler(struct trace_seq *s, struct pevent_record *record,
> struct tracecmd_ftrace *finfo = context;
> struct pevent_record *rec;
> unsigned long long val, pid;
> - int cpu = record->cpu;
> + int cpu;
>
> ret_event_check(finfo, event->pevent);
>
> @@ -307,7 +307,7 @@ fgraph_ent_handler(struct trace_seq *s, struct pevent_record *record,
> if (pevent_get_field_val(s, event, "func", record, &val, 1))
> return trace_seq_putc(s, '!');
>
> - rec = tracecmd_peek_data(tracecmd_curr_thread_handle, cpu);
> + rec = tracecmd_peek_next_data(tracecmd_curr_thread_handle, &cpu);

Hmm, but what happens if the next data is just some random event on
another CPU. Do we want to break it up just because there's data on
another cpu?

I wonder if we should grab a record from the same cpu and if it isn't
the return, then try another cpu?

-- Steve

> if (rec)
> rec = get_return_for_leaf(s, cpu, pid, val, rec, finfo);
>