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:
> 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
> 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.
> 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
# trace-cmd extract
# trace-cmd report -t --cpu 0 | less
I didn't see anything where they had the same timestamps.