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

From: Steven Rostedt
Date: Fri Jul 07 2017 - 15:01:47 EST

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