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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Fri, 7 Jul 2017 15:01:36 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Arun Kalyanasundaram <arunkaly@...gle.com>
Cc:     mhiramat@...nel.org, linux-kernel@...r.kernel.org,
        mingo@...nel.org, David Carrillo-Cisneros <davidcc@...gle.com>
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@...gle.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