Re: Profiling sleep times?

[Arun Sharma <asharma@fb.com>]

On 10/4/11 1:34 AM, Peter Zijlstra wrote:

>> # cat foo.c
>> #include<unistd.h>
>> #include<time.h>
>> #include<sys/select.h>
>>
>> main()
>> {
>>           struct timespec ts1;
>>           struct timeval tv1;
>>           int i;
>>
>>
>>           for (i = 0; i<  1000; i++) {
>>                   ts1.tv_sec = 0;
>>                   ts1.tv_nsec = 1000000;
>>                   nanosleep(&ts1, NULL);
>>
>>                   tv1.tv_sec = 0;
>>                   tv1.tv_usec = 4000;
>>                   select(0, NULL, NULL, NULL,&tv1);
>>           }
>> }
>>

> Would you per-chance be suffering from this:
>
> http://lkml.kernel.org/r/1317052535-1765247-2-git-send-email-avagin@openvz.org
>

Thanks for the pointer. Yes - Andrew's patches help. But looks like we 
need more user space plumbing like Frederic noted.

perf record -ge sched:sched_stat_sleep -- ./foo

doesn't quite work.

perf record -age sched:sched_stat_sleep -- ./foo

gives me:

    58.62%              foo  [unknown]          [k] 0
                        |
                        --- schedule
                           |
                           |--54.99%-- schedule_hrtimeout_range_clock
                           |          schedule_hrtimeout_range
                           |          poll_schedule_timeout
                           |          do_select
                           |          core_sys_select
                           |          sys_select
                           |          system_call_fastpath
                           |
                           |--44.81%-- do_nanosleep
                           |          hrtimer_nanosleep
                           |          sys_nanosleep
                           |          system_call_fastpath
                            --0.20%-- [...]

i.e. select() should be weighted by 4x vs nanosleep() as confirmed via:

perf script | grep comm=foo

           foo 15516 [006]  2291.187831: sched_stat_sleep: comm=foo 
pid=15516 delay=4054262 [ns]
              foo 15516 [006]  2291.187832: sched_stat_sleep: comm=foo 
pid=15516 delay=4054262 [ns]
              foo 15516 [006]  2291.188895: sched_stat_sleep: comm=foo 
pid=15516 delay=1053565 [ns]
              foo 15516 [006]  2291.188896: sched_stat_sleep: comm=foo 
pid=15516 delay=1053565 [ns]
              foo 15516 [006]  2291.188897: sched_stat_sleep: comm=foo 
pid=15516 delay=1053565 [ns]

Andrew, are you already working on user space patches?

  -Arun