From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752427AbdGGTBn (ORCPT ); Fri, 7 Jul 2017 15:01:43 -0400 Received: from mail.kernel.org ([198.145.29.99]:46192 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750848AbdGGTBm (ORCPT ); Fri, 7 Jul 2017 15:01:42 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org E28E022BD8 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=goodmis.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=rostedt@goodmis.org Date: Fri, 7 Jul 2017 15:01:36 -0400 From: Steven Rostedt To: Arun Kalyanasundaram Cc: mhiramat@kernel.org, linux-kernel@vger.kernel.org, mingo@kernel.org, David Carrillo-Cisneros Subject: Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart Message-ID: <20170707150136.7f167b85@gandalf.local.home> In-Reply-To: References: X-Mailer: Claws Mail 3.14.0 (GTK+ 2.24.31; x86_64-pc-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 > > 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. > I don't see this with ftrace. What kernel are you using? # cd /sys/kernel/debug/tracing # echo perf > trace_clock # echo 'p:s1 __schedule' > kprobe_events # echo 'p:s2 __schedule+12' >> kprobe_events # echo 1 > events/kprobes/enable # cd # trace-cmd extract # trace-cmd report -t --cpu 0 | less I didn't see anything where they had the same timestamps. -- Steve