* lost some call trace for sleep function
@ 2017-10-26 10:24 yuzhoujian
2017-10-26 17:32 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 2+ messages in thread
From: yuzhoujian @ 2017-10-26 10:24 UTC (permalink / raw)
To: peterz, mingo, alexander.shishkin, jolsa, dsahern, namhyung,
milian.wolff, arnaldo.melo, yuzhoujian, adrian.hunter, wangnan0
Cc: linux-perf-users, linux-kernel, acme
Hi, all.
I find a strange problem. Perf cannot record call stack which contains sleep functions.
The last function of the call trace is always "__GI___libc_nanosleep" for each sample.
one of the sample for perf script is below:
test_sleep 12275 185233.961287: 1 cycles:ppp:
ffffffff8100add0 intel_bts_enable_local ([kernel.kallsyms])
ffffffff81008f20 intel_pmu_enable_all ([kernel.kallsyms])
ffffffff810057ec x86_pmu_enable ([kernel.kallsyms])
ffffffff81173e57 perf_pmu_enable ([kernel.kallsyms])
ffffffff81175404 __perf_event_task_sched_in ([kernel.kallsyms])
ffffffff810c1aa8 finish_task_switch ([kernel.kallsyms])
ffffffff81690e00 __schedule ([kernel.kallsyms])
ffffffff81691409 schedule ([kernel.kallsyms])
ffffffff816902d6 do_nanosleep ([kernel.kallsyms])
ffffffff810b747b hrtimer_nanosleep ([kernel.kallsyms])
ffffffff810b75be sys_nanosleep ([kernel.kallsyms])
ffffffff8169c749 system_call_fastpath ([kernel.kallsyms])
bf190 __GI___libc_nanosleep (/usr/lib64/libc-2.17.so)
Below is the source code of test_sleep:
void f2()
{
sleep(1);
}
void f1()
{
f2();
}
int main()
{
while(1)
f1();
return 0;
}
I think the right call stack should contain the __sleep function in glibc, just as follow
test_sleep 12275 185233.961287: 1 cycles:ppp:
ffffffff8100add0 intel_bts_enable_local ([kernel.kallsyms])
ffffffff81008f20 intel_pmu_enable_all ([kernel.kallsyms])
ffffffff810057ec x86_pmu_enable ([kernel.kallsyms])
ffffffff81173e57 perf_pmu_enable ([kernel.kallsyms])
ffffffff81175404 __perf_event_task_sched_in ([kernel.kallsyms])
ffffffff810c1aa8 finish_task_switch ([kernel.kallsyms])
ffffffff81690e00 __schedule ([kernel.kallsyms])
ffffffff81691409 schedule ([kernel.kallsyms])
ffffffff816902d6 do_nanosleep ([kernel.kallsyms])
ffffffff810b747b hrtimer_nanosleep ([kernel.kallsyms])
ffffffff810b75be sys_nanosleep ([kernel.kallsyms])
ffffffff8169c749 system_call_fastpath ([kernel.kallsyms])
bf190 __GI___libc_nanosleep (/usr/lib64/libc-2.17.so)
bef70 __sleep (/usr/lib64/libc-2.17.so)
5a1 f2 (/home/test_sleep)
5c1 f1 (/home/test_sleep)
5d1 main (/home/test_sleep)
21c05 __libc_start_main (/usr/lib64/libc-2.17.so)
Is it a bug for perf record ??
^ permalink raw reply [flat|nested] 2+ messages in thread* Re: lost some call trace for sleep function
2017-10-26 10:24 lost some call trace for sleep function yuzhoujian
@ 2017-10-26 17:32 ` Arnaldo Carvalho de Melo
0 siblings, 0 replies; 2+ messages in thread
From: Arnaldo Carvalho de Melo @ 2017-10-26 17:32 UTC (permalink / raw)
To: yuzhoujian
Cc: peterz, mingo, alexander.shishkin, jolsa, dsahern, namhyung,
milian.wolff, arnaldo.melo, yuzhoujian, adrian.hunter, wangnan0,
linux-perf-users, linux-kernel, acme
Em Thu, Oct 26, 2017 at 06:24:56PM +0800, yuzhoujian escreveu:
> Hi, all.
> I find a strange problem. Perf cannot record call stack which contains sleep functions.
> The last function of the call trace is always "__GI___libc_nanosleep" for each sample.
> one of the sample for perf script is below:
How are you recording it? Please state the exact command line you use for 'record'.
Here are some attempts at doing that on a fedora 26 x86_64 system:
[acme@jouet linux]$ uname -a
Linux jouet 4.14.0-rc3+ #1 SMP Fri Oct 13 12:21:12 -03 2017 x86_64 x86_64 x86_64 GNU/Linux
# perf trace -e nanosleep --max-stack=10 sleep 1
0.649 (1000.121 ms): sleep/9566 nanosleep(rqtp: 0x7ffe56769570 ) = 0
__nanosleep_nocancel (/usr/lib64/libc-2.25.so)
rpl_nanosleep (/usr/bin/sleep)
xnanosleep (/usr/bin/sleep)
main (/usr/bin/sleep)
__libc_start_main (/usr/lib64/libc-2.25.so)
_start (/usr/bin/sleep)
#
Which is equivalent to:
# perf record -e syscalls:sys_enter_nanosleep/call-graph=dwarf,max-stack=10/ sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.027 MB perf.data (1 samples) ]
# perf script
sleep 9629 [001] 210689.400780: syscalls:sys_enter_nanosleep: rqtp: 0x7ffd6a99b180, rmtp: 0x00000000
d4420 __nanosleep_nocancel (/usr/lib64/libc-2.25.so)
46c6 rpl_nanosleep (/usr/bin/sleep)
449f xnanosleep (/usr/bin/sleep)
1773 main (/usr/bin/sleep)
20509 __libc_start_main (/usr/lib64/libc-2.25.so)
1869 _start (/usr/bin/sleep)
#
But why are you trying to sample CPU cycles used on a function that sleeps?
- Arnaldo
> test_sleep 12275 185233.961287: 1 cycles:ppp:
> ffffffff8100add0 intel_bts_enable_local ([kernel.kallsyms])
> ffffffff81008f20 intel_pmu_enable_all ([kernel.kallsyms])
> ffffffff810057ec x86_pmu_enable ([kernel.kallsyms])
> ffffffff81173e57 perf_pmu_enable ([kernel.kallsyms])
> ffffffff81175404 __perf_event_task_sched_in ([kernel.kallsyms])
> ffffffff810c1aa8 finish_task_switch ([kernel.kallsyms])
> ffffffff81690e00 __schedule ([kernel.kallsyms])
> ffffffff81691409 schedule ([kernel.kallsyms])
> ffffffff816902d6 do_nanosleep ([kernel.kallsyms])
> ffffffff810b747b hrtimer_nanosleep ([kernel.kallsyms])
> ffffffff810b75be sys_nanosleep ([kernel.kallsyms])
> ffffffff8169c749 system_call_fastpath ([kernel.kallsyms])
> bf190 __GI___libc_nanosleep (/usr/lib64/libc-2.17.so)
>
> Below is the source code of test_sleep:
>
> void f2()
> {
> sleep(1);
> }
> void f1()
> {
> f2();
> }
> int main()
> {
> while(1)
> f1();
> return 0;
> }
>
> I think the right call stack should contain the __sleep function in glibc, just as follow
>
> test_sleep 12275 185233.961287: 1 cycles:ppp:
> ffffffff8100add0 intel_bts_enable_local ([kernel.kallsyms])
> ffffffff81008f20 intel_pmu_enable_all ([kernel.kallsyms])
> ffffffff810057ec x86_pmu_enable ([kernel.kallsyms])
> ffffffff81173e57 perf_pmu_enable ([kernel.kallsyms])
> ffffffff81175404 __perf_event_task_sched_in ([kernel.kallsyms])
> ffffffff810c1aa8 finish_task_switch ([kernel.kallsyms])
> ffffffff81690e00 __schedule ([kernel.kallsyms])
> ffffffff81691409 schedule ([kernel.kallsyms])
> ffffffff816902d6 do_nanosleep ([kernel.kallsyms])
> ffffffff810b747b hrtimer_nanosleep ([kernel.kallsyms])
> ffffffff810b75be sys_nanosleep ([kernel.kallsyms])
> ffffffff8169c749 system_call_fastpath ([kernel.kallsyms])
> bf190 __GI___libc_nanosleep (/usr/lib64/libc-2.17.so)
> bef70 __sleep (/usr/lib64/libc-2.17.so)
> 5a1 f2 (/home/test_sleep)
> 5c1 f1 (/home/test_sleep)
> 5d1 main (/home/test_sleep)
> 21c05 __libc_start_main (/usr/lib64/libc-2.17.so)
>
> Is it a bug for perf record ??
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2017-10-26 17:32 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-10-26 10:24 lost some call trace for sleep function yuzhoujian
2017-10-26 17:32 ` Arnaldo Carvalho de Melo
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).