* Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart [not found] <CAGjB_BpTmk+gvNMpuxWweu1UnzFixPrxKKAxzJxm2svz+-FVXg@mail.gmail.com> @ 2017-07-07 19:01 ` Steven Rostedt 2017-07-07 23:06 ` Arun Kalyanasundaram 2017-07-09 12:51 ` Masami Hiramatsu 1 sibling, 1 reply; 5+ messages in thread From: Steven Rostedt @ 2017-07-07 19:01 UTC (permalink / raw) To: Arun Kalyanasundaram Cc: mhiramat, linux-kernel, mingo, David Carrillo-Cisneros 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 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart 2017-07-07 19:01 ` tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart Steven Rostedt @ 2017-07-07 23:06 ` Arun Kalyanasundaram 2017-07-10 0:18 ` Masami Hiramatsu 0 siblings, 1 reply; 5+ messages in thread From: Arun Kalyanasundaram @ 2017-07-07 23:06 UTC (permalink / raw) To: Steven Rostedt; +Cc: mhiramat, linux-kernel, mingo, David Carrillo-Cisneros Hi Steven, Thank you very much for your reply. I am using kernel - v4.12-rc3. I did something like this and see the issue: # trace-cmd record -e kprobes:s1 -e kprobes:s2 -- taskset -c 0 my_program # ./trace-cmd report -t --cpu 0 The issue is pretty intermittent and only happens when there are a lot of samples, and so "my_program" generates a few hundred threads. Any pointers on debugging this would be very helpful, or please let me know if you want me to collect any log messages. On Fri, Jul 7, 2017 at 12:01 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > 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 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart 2017-07-07 23:06 ` Arun Kalyanasundaram @ 2017-07-10 0:18 ` Masami Hiramatsu 2017-07-10 17:38 ` Arun Kalyanasundaram 0 siblings, 1 reply; 5+ messages in thread From: Masami Hiramatsu @ 2017-07-10 0:18 UTC (permalink / raw) To: Arun Kalyanasundaram Cc: Steven Rostedt, mhiramat, linux-kernel, mingo, David Carrillo-Cisneros Hello Arun, On Fri, 7 Jul 2017 16:06:40 -0700 Arun Kalyanasundaram <arunkaly@google.com> wrote: > Hi Steven, > > Thank you very much for your reply. I am using kernel - v4.12-rc3. > > I did something like this and see the issue: > # trace-cmd record -e kprobes:s1 -e kprobes:s2 -- taskset -c 0 my_program > # ./trace-cmd report -t --cpu 0 > > The issue is pretty intermittent and only happens when there are a lot > of samples, and so "my_program" generates a few hundred threads. Any > pointers on debugging this would be very helpful, or please let me > know if you want me to collect any log messages. Ok, so this happens with ftrace+trace-cmd too. If you run it on x86-64, could you add "-C x86-tsc" and check still it happens? If not, I guess it happens when it adjusts timestamp. Thank you, -- Masami Hiramatsu <mhiramat@kernel.org> ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart 2017-07-10 0:18 ` Masami Hiramatsu @ 2017-07-10 17:38 ` Arun Kalyanasundaram 0 siblings, 0 replies; 5+ messages in thread From: Arun Kalyanasundaram @ 2017-07-10 17:38 UTC (permalink / raw) To: Masami Hiramatsu Cc: Steven Rostedt, linux-kernel, mingo, David Carrillo-Cisneros Hi Masama, Thank you for looking into this. You are right, I don't see the issue when my trace_clock = x86-tsc. I tried with other clocks and apparently, I only see this when my clock is either perf or global. You mentioned this happens when "it adjusts timestamp", so does that mean this is an expected behavior in this case? I am running this on a haswell x86 architecture with 72 cores. Thank you, - Arun On Sun, Jul 9, 2017 at 5:18 PM, Masami Hiramatsu <mhiramat@kernel.org> wrote: > Hello Arun, > > On Fri, 7 Jul 2017 16:06:40 -0700 > Arun Kalyanasundaram <arunkaly@google.com> wrote: > >> Hi Steven, >> >> Thank you very much for your reply. I am using kernel - v4.12-rc3. >> >> I did something like this and see the issue: >> # trace-cmd record -e kprobes:s1 -e kprobes:s2 -- taskset -c 0 my_program >> # ./trace-cmd report -t --cpu 0 >> >> The issue is pretty intermittent and only happens when there are a lot >> of samples, and so "my_program" generates a few hundred threads. Any >> pointers on debugging this would be very helpful, or please let me >> know if you want me to collect any log messages. > > Ok, so this happens with ftrace+trace-cmd too. > If you run it on x86-64, could you add "-C x86-tsc" and check still > it happens? If not, I guess it happens when it adjusts timestamp. > > Thank you, > > -- > Masami Hiramatsu <mhiramat@kernel.org> ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart [not found] <CAGjB_BpTmk+gvNMpuxWweu1UnzFixPrxKKAxzJxm2svz+-FVXg@mail.gmail.com> 2017-07-07 19:01 ` tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart Steven Rostedt @ 2017-07-09 12:51 ` Masami Hiramatsu 1 sibling, 0 replies; 5+ messages in thread From: Masami Hiramatsu @ 2017-07-09 12:51 UTC (permalink / raw) To: Arun Kalyanasundaram Cc: rostedt, linux-kernel, mingo, David Carrillo-Cisneros, Peter Zijlstra, Arnaldo Carvalho de Melo, mingo 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 Could you tell me on what architecture are you running the benchmark? (It seems that your machine has more than 64 core(or SMT)) And would you see same issue when you are using ftrace debugfs (or tracefs) interface too? Actually, if you use "perf" to trace events, those are recorded in different buffers and different way to be read. So we have to investigate perf side too. Peter, Arnaldo, if there are 2 perf events occurs in very short period, is it possible to indicate same timestamp for those? Thank you, > > 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 -- Masami Hiramatsu <mhiramat@kernel.org> ^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2017-07-10 17:38 UTC | newest] Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- [not found] <CAGjB_BpTmk+gvNMpuxWweu1UnzFixPrxKKAxzJxm2svz+-FVXg@mail.gmail.com> 2017-07-07 19:01 ` tracing/kprobes: [Bug] Identical timestamps on two kprobes that are few instructions apart Steven Rostedt 2017-07-07 23:06 ` Arun Kalyanasundaram 2017-07-10 0:18 ` Masami Hiramatsu 2017-07-10 17:38 ` Arun Kalyanasundaram 2017-07-09 12:51 ` Masami Hiramatsu
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).