From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S941368AbcJXTn2 (ORCPT ); Mon, 24 Oct 2016 15:43:28 -0400 Received: from terminus.zytor.com ([198.137.202.10]:47862 "EHLO mail.zytor.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S939727AbcJXTnX (ORCPT ); Mon, 24 Oct 2016 15:43:23 -0400 Date: Mon, 24 Oct 2016 12:07:26 -0700 From: tip-bot for Arnaldo Carvalho de Melo Message-ID: Cc: linux-kernel@vger.kernel.org, dsahern@gmail.com, adrian.hunter@intel.com, jolsa@kernel.org, acme@redhat.com, namhyung@kernel.org, hpa@zytor.com, mingo@kernel.org, tglx@linutronix.de, wangnan0@huawei.com Reply-To: mingo@kernel.org, hpa@zytor.com, namhyung@kernel.org, jolsa@kernel.org, acme@redhat.com, adrian.hunter@intel.com, dsahern@gmail.com, linux-kernel@vger.kernel.org, wangnan0@huawei.com, tglx@linutronix.de To: linux-tip-commits@vger.kernel.org Subject: [tip:perf/core] perf trace: Use the syscall raw_syscalls:sys_enter timestamp Git-Commit-ID: ecf1e2253ea79c6204f4d6a5e756e8fb4aed5a7e X-Mailer: tip-git-log-daemon Robot-ID: Robot-Unsubscribe: Contact to get blacklisted from these emails MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Content-Type: text/plain; charset=UTF-8 Content-Disposition: inline Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Commit-ID: ecf1e2253ea79c6204f4d6a5e756e8fb4aed5a7e Gitweb: http://git.kernel.org/tip/ecf1e2253ea79c6204f4d6a5e756e8fb4aed5a7e Author: Arnaldo Carvalho de Melo AuthorDate: Tue, 18 Oct 2016 11:28:32 -0300 Committer: Arnaldo Carvalho de Melo CommitDate: Mon, 24 Oct 2016 11:07:46 -0300 perf trace: Use the syscall raw_syscalls:sys_enter timestamp Instead of the one when another syscall takes place while another is being processed (in another CPU, but we show it serialized, so need to "interrupt" the other), and also when finally showing the sys_enter + sys_exit + duration, where we were showing the sample->time for the sys_exit, duh. Before: # perf trace sleep 1 0.373 ( 0.001 ms): close(fd: 3 ) = 0 1000.626 (1000.211 ms): nanosleep(rqtp: 0x7ffd6ddddfb0) = 0 1000.653 ( 0.003 ms): close(fd: 1 ) = 0 1000.657 ( 0.002 ms): close(fd: 2 ) = 0 1000.667 ( 0.000 ms): exit_group( ) # After: # perf trace sleep 1 0.336 ( 0.001 ms): close(fd: 3 ) = 0 0.373 (1000.086 ms): nanosleep(rqtp: 0x7ffe303e9550) = 0 1000.481 ( 0.002 ms): close(fd: 1 ) = 0 1000.485 ( 0.001 ms): close(fd: 2 ) = 0 1000.494 ( 0.000 ms): exit_group( ) [root@jouet linux]# Cc: Adrian Hunter Cc: David Ahern Cc: Jiri Olsa Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-ecbzgmu2ni6glc6zkw8p1zmx@git.kernel.org Fixes: 752fde44fd1c ("perf trace: Support interrupted syscalls") Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-trace.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c index c72a92c..5f45166 100644 --- a/tools/perf/builtin-trace.c +++ b/tools/perf/builtin-trace.c @@ -1451,7 +1451,7 @@ static int trace__printf_interrupted_entry(struct trace *trace, struct perf_samp duration = sample->time - ttrace->entry_time; - printed = trace__fprintf_entry_head(trace, trace->current, duration, sample->time, trace->output); + printed = trace__fprintf_entry_head(trace, trace->current, duration, ttrace->entry_time, trace->output); printed += fprintf(trace->output, "%-70s) ...\n", ttrace->entry_str); ttrace->entry_pending = false; @@ -1498,7 +1498,7 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel, if (sc->is_exit) { if (!(trace->duration_filter || trace->summary_only || trace->min_stack)) { - trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output); + trace__fprintf_entry_head(trace, thread, 1, ttrace->entry_time, trace->output); fprintf(trace->output, "%-70s)\n", ttrace->entry_str); } } else { @@ -1589,7 +1589,7 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel, if (trace->summary_only) goto out; - trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output); + trace__fprintf_entry_head(trace, thread, duration, ttrace->entry_time, trace->output); if (ttrace->entry_pending) { fprintf(trace->output, "%-70s", ttrace->entry_str);