From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752385AbdGIMv7 (ORCPT ); Sun, 9 Jul 2017 08:51:59 -0400 Received: from mail.kernel.org ([198.145.29.99]:37562 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752125AbdGIMv6 (ORCPT ); Sun, 9 Jul 2017 08:51:58 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org BAED022BE3 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=kernel.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=mhiramat@kernel.org Date: Sun, 9 Jul 2017 21:51:54 +0900 From: Masami Hiramatsu To: Arun Kalyanasundaram Cc: rostedt@goodmis.org, linux-kernel@vger.kernel.org, mingo@kernel.org, David Carrillo-Cisneros , Peter Zijlstra , Arnaldo Carvalho de Melo , mingo@kernel.org Subject: Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart Message-Id: <20170709215154.493eda54c42f82d272938312@kernel.org> In-Reply-To: References: X-Mailer: Sylpheed 3.5.0 (GTK+ 2.24.31; x86_64-redhat-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, 7 Jul 2017 10:34:48 -0700 Arun Kalyanasundaram wrote: > Hi, > > I am trying to use kprobes to time a few kernel functions. However, when I > add two kprobes on a function that are a few instructions apart, I > sometimes get the same timestamp (measured in nano seconds) on the two > probes. > > For example, if I add the two probes as follows, > 1) perf probe -a "kprobe1=__schedule" > 2) perf probe -a "kprobe2=__schedule+12" > > I then use "perf record" on a multi-threaded benchmark (e.g. stream: > https://www.cs.virginia.edu/stream/) to collect samples. I then see the > same timestamp on kprobe1 and kprobe2 for the same thread running on the > same CPU. Following is an example of the output showing the same timestamp > on the two probes. > > comm,tid,cpu,time,event,ip,sym > stream,62182,[064],3020935.384132080,probe:kprobe1,ffffffffb36399f1,__schedule > stream,62182,[064],3020935.384132080,probe:kprobe2,ffffffffb36399fd,__schedule Could you tell me on what architecture are you running the benchmark? (It seems that your machine has more than 64 core(or SMT)) And would you see same issue when you are using ftrace debugfs (or tracefs) interface too? Actually, if you use "perf" to trace events, those are recorded in different buffers and different way to be read. So we have to investigate perf side too. Peter, Arnaldo, if there are 2 perf events occurs in very short period, is it possible to indicate same timestamp for those? Thank you, > > Since it happens intermittently, I am wondering if there is some sort of > race condition here. Please let me know if this is an expected behavior or > is there something wrong in the way I use kprobes. > > Thank you, > - Arun -- Masami Hiramatsu