linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 1/2] trace-cmd: Introduce tracecmd_peek_next_data()
@ 2016-07-08  5:56 Namhyung Kim
  2016-07-08  5:56 ` [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler Namhyung Kim
  0 siblings, 1 reply; 5+ messages in thread
From: Namhyung Kim @ 2016-07-08  5:56 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: LKML, Joonsoo Kim, Namhyung Kim

The tracecmd_peek_next_data() is similar to tracecmd_read_next_data()
but it doesn't consume the record.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 trace-cmd.h   |  3 +++
 trace-input.c | 43 +++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 46 insertions(+)

diff --git a/trace-cmd.h b/trace-cmd.h
index cef2458..5798345 100644
--- a/trace-cmd.h
+++ b/trace-cmd.h
@@ -164,6 +164,9 @@ struct pevent_record *
 tracecmd_read_next_data(struct tracecmd_input *handle, int *rec_cpu);
 
 struct pevent_record *
+tracecmd_peek_next_data(struct tracecmd_input *handle, int *rec_cpu);
+
+struct pevent_record *
 tracecmd_read_at(struct tracecmd_input *handle, unsigned long long offset,
 		 int *cpu);
 struct pevent_record *
diff --git a/trace-input.c b/trace-input.c
index 2fea066..e825328 100644
--- a/trace-input.c
+++ b/trace-input.c
@@ -1787,6 +1787,49 @@ tracecmd_read_next_data(struct tracecmd_input *handle, int *rec_cpu)
 }
 
 /**
+ * tracecmd_peek_next_data - return the next record
+ * @handle: input handle to the trace.dat file
+ * @rec_cpu: return pointer to the CPU that the record belongs to
+ *
+ * This returns the next record by time. This is different than
+ * tracecmd_peek_data in that it looks at all CPUs. It does a peek
+ * at each CPU and the record with the earliest time stame is
+ * returned. If @rec_cpu is not NULL it gets the CPU id the record was
+ * on. It does not increment the CPU iterator.
+ */
+struct pevent_record *
+tracecmd_peek_next_data(struct tracecmd_input *handle, int *rec_cpu)
+{
+	unsigned long long ts;
+	struct pevent_record *record, *next_record = NULL;
+	int next_cpu;
+	int cpu;
+
+	if (rec_cpu)
+		*rec_cpu = -1;
+
+	next_cpu = -1;
+	ts = 0;
+
+	for (cpu = 0; cpu < handle->cpus; cpu++) {
+		record = tracecmd_peek_data(handle, cpu);
+		if (record && (!next_record || record->ts < ts)) {
+			ts = record->ts;
+			next_cpu = cpu;
+			next_record = record;
+		}
+	}
+
+	if (next_record) {
+		if (rec_cpu)
+			*rec_cpu = next_cpu;
+		return next_record;
+	}
+
+	return NULL;
+}
+
+/**
  * tracecmd_read_prev - read the record before the given record
  * @handle: input handle to the trace.dat file
  * @record: the record to use to find the previous record.
-- 
2.9.0

^ permalink raw reply related	[flat|nested] 5+ messages in thread

* [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler
  2016-07-08  5:56 [PATCH 1/2] trace-cmd: Introduce tracecmd_peek_next_data() Namhyung Kim
@ 2016-07-08  5:56 ` Namhyung Kim
  2016-07-11 16:55   ` Steven Rostedt
  0 siblings, 1 reply; 5+ messages in thread
From: Namhyung Kim @ 2016-07-08  5:56 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: LKML, Joonsoo Kim, Namhyung Kim

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@lge.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 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);
 	if (rec)
 		rec = get_return_for_leaf(s, cpu, pid, val, rec, finfo);
 
-- 
2.9.0

^ permalink raw reply related	[flat|nested] 5+ messages in thread

* Re: [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler
  2016-07-08  5:56 ` [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler Namhyung Kim
@ 2016-07-11 16:55   ` Steven Rostedt
  2016-07-12  0:17     ` Namhyung Kim
  0 siblings, 1 reply; 5+ messages in thread
From: Steven Rostedt @ 2016-07-11 16:55 UTC (permalink / raw)
  To: Namhyung Kim; +Cc: LKML, Joonsoo Kim, Namhyung Kim

On Fri,  8 Jul 2016 14:56:12 +0900
Namhyung Kim <namhyung@gmail.com> 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@lge.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  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);
>  

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler
  2016-07-11 16:55   ` Steven Rostedt
@ 2016-07-12  0:17     ` Namhyung Kim
  2016-07-12 12:32       ` Steven Rostedt
  0 siblings, 1 reply; 5+ messages in thread
From: Namhyung Kim @ 2016-07-12  0:17 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: LKML, Joonsoo Kim

Hi Steve,

On Mon, Jul 11, 2016 at 12:55:22PM -0400, Steven Rostedt wrote:
> On Fri,  8 Jul 2016 14:56:12 +0900
> Namhyung Kim <namhyung@gmail.com> 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@lge.com>
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> >  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?

Yes, I think we should break.  Isn't it natural to show an event in
the middle of a function if it occurred before returning from the
function?  It would be more acccurate output IMHO.  I guess most leaf
functions are small so the end result would almost same.


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

But in this case, it's a problem even if it's the return of the same
function.  The task can be migrated to another cpu during the
function, and then can be migrated back to the original cpu while
calling same function again.  The entry of the first invocation would
match to the exit of the Nth invocation..

Thanks,
Namhyung


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

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler
  2016-07-12  0:17     ` Namhyung Kim
@ 2016-07-12 12:32       ` Steven Rostedt
  0 siblings, 0 replies; 5+ messages in thread
From: Steven Rostedt @ 2016-07-12 12:32 UTC (permalink / raw)
  To: Namhyung Kim; +Cc: LKML, Joonsoo Kim

On Tue, 12 Jul 2016 09:17:25 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> > 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?  
> 
> Yes, I think we should break.  Isn't it natural to show an event in
> the middle of a function if it occurred before returning from the
> function?  It would be more acccurate output IMHO.  I guess most leaf
> functions are small so the end result would almost same.

OK, that sounds fine then.

> 
> 
> > 
> > I wonder if we should grab a record from the same cpu and if it isn't
> > the return, then try another cpu?  
> 
> But in this case, it's a problem even if it's the return of the same
> function.  The task can be migrated to another cpu during the
> function, and then can be migrated back to the original cpu while
> calling same function again.  The entry of the first invocation would
> match to the exit of the Nth invocation..

I'll keep your patch as is then.

Thanks,

-- Steve

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2016-07-12 12:32 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-07-08  5:56 [PATCH 1/2] trace-cmd: Introduce tracecmd_peek_next_data() Namhyung Kim
2016-07-08  5:56 ` [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler Namhyung Kim
2016-07-11 16:55   ` Steven Rostedt
2016-07-12  0:17     ` Namhyung Kim
2016-07-12 12:32       ` Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).