Messages in this thread | | | Date | Fri, 7 Jul 2017 15:01:36 -0400 | From | Steven Rostedt <> | Subject | Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart |
| |
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
| |