From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752596AbdGGXGn (ORCPT ); Fri, 7 Jul 2017 19:06:43 -0400 Received: from mail-vk0-f42.google.com ([209.85.213.42]:33423 "EHLO mail-vk0-f42.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751034AbdGGXGm (ORCPT ); Fri, 7 Jul 2017 19:06:42 -0400 MIME-Version: 1.0 In-Reply-To: <20170707150136.7f167b85@gandalf.local.home> References: <20170707150136.7f167b85@gandalf.local.home> From: Arun Kalyanasundaram Date: Fri, 7 Jul 2017 16:06:40 -0700 Message-ID: Subject: Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart To: Steven Rostedt Cc: mhiramat@kernel.org, linux-kernel@vger.kernel.org, mingo@kernel.org, David Carrillo-Cisneros Content-Type: text/plain; charset="UTF-8" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi Steven, Thank you very much for your reply. I am using kernel - v4.12-rc3. I did something like this and see the issue: # trace-cmd record -e kprobes:s1 -e kprobes:s2 -- taskset -c 0 my_program # ./trace-cmd report -t --cpu 0 The issue is pretty intermittent and only happens when there are a lot of samples, and so "my_program" generates a few hundred threads. Any pointers on debugging this would be very helpful, or please let me know if you want me to collect any log messages. On Fri, Jul 7, 2017 at 12:01 PM, Steven Rostedt wrote: > 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