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