Re: Profiling sleep times?

[Arun Sharma <asharma@xxxxxx>]

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@xxxxxxxxxx

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
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html