* 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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.