lkml.org 
[lkml]   [2017]   [Jul]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: 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

\
 
 \ /
  Last update: 2017-07-07 21:02    [W:0.044 / U:0.928 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site