Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 7 Jul 2017 10:34:48 -0700
Arun Kalyanasundaram <arunkaly@google.com> 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