From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753018AbcGHF4l (ORCPT ); Fri, 8 Jul 2016 01:56:41 -0400 Received: from LGEAMRELO12.lge.com ([156.147.23.52]:53310 "EHLO lgeamrelo12.lge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751550AbcGHF4c (ORCPT ); Fri, 8 Jul 2016 01:56:32 -0400 X-Original-SENDERIP: 156.147.1.126 X-Original-MAILFROM: namhyung@gmail.com X-Original-SENDERIP: 10.177.227.17 X-Original-MAILFROM: namhyung@gmail.com From: Namhyung Kim To: Steven Rostedt Cc: LKML , Joonsoo Kim , Namhyung Kim Subject: [PATCH 2/2] trace-cmd: Use tracecmd_peek_next_data() in fgraph_ent_handler Date: Fri, 8 Jul 2016 14:56:12 +0900 Message-Id: <20160708055612.32221-2-namhyung@gmail.com> X-Mailer: git-send-email 2.9.0 In-Reply-To: <20160708055612.32221-1-namhyung@gmail.com> References: <20160708055612.32221-1-namhyung@gmail.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 Signed-off-by: Namhyung Kim --- 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