linux-kernel - [Resend: Adding linux-kernel] 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>] [day] [month] [year] [list]

Date:   Fri, 7 Jul 2017 11:00:56 -0700
From:   Arun Kalyanasundaram <arunkaly@...gle.com>
To:     rostedt@...dmis.org, mhiramat@...nel.org,
        linux-kernel@...r.kernel.org
Cc:     mingo@...nel.org, David Carrillo-Cisneros <davidcc@...gle.com>
Subject: [Resend: Adding linux-kernel] tracing/kprobes: [Bug] Identical
 timestamps on two kprobes that are few instructions apart

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.
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.

Thank you,
- Arun