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