Problem when profiling a process' running/sleeping/waiting time

Problem when profiling a process' running/sleeping/waiting time

[Victor Jimenez]

I am trying to profile a process in terms of running, sleeping and 
waiting time. I am using kernel 3.6.6 running on an IBM POWER7 machine. 
Initially, I decided to use a toy example where I would expect that the 
process remains in running state most of the time. This is the code for 
such a simple example:

int main() {
     for (int i = 0; i < 1000000; i++)
         for (int j = 0; j < 1000; j++);
}

I am using the following command line for reading kernel stats:

perf stat -e 
"sched:sched_stat_runtime,sched:sched_stat_sleep,sched:sched_stat_wait, \
     sched:sched_stat_iowait,sched:sched_stat_blocked" ./test

And these are the results that I obtain:

  Performance counter stats for './test':

     12,077,957,756 sched:sched_stat_runtime
    169,892,740,990 sched:sched_stat_sleep
          5,816,784 sched:sched_stat_wait
                  0 sched:sched_stat_iowait
                  0 sched:sched_stat_blocked

      12.084706279  seconds time elapsed

I cannot really understand why the counter for sched_stat_sleep is so 
high (even higher than sched_stat_runtime), especially for such a 
CPU-bound workload.

Am I missing anything, or there could be a problem with sched_stat_sleep 
counter?

Thank you,
Victor

WARNING / LEGAL TEXT: This message is intended only for the use of the
individual or entity to which it is addressed and may contain
information which is privileged, confidential, proprietary, or exempt
from disclosure under applicable law. If you are not the intended
recipient or the person responsible for delivering the message to the
intended recipient, you are strictly prohibited from disclosing,
distributing, copying, or in any way using this message. If you have
received this communication in error, please notify the sender and
destroy and delete any copies you may have received.

http://www.bsc.es/disclaimer

Re: Problem when profiling a process' running/sleeping/waiting time

[Michael Ellerman]

On Wed, 2013-01-09 at 11:56 +0100, Victor Jimenez wrote:
> I am trying to profile a process in terms of running, sleeping and 
> waiting time. I am using kernel 3.6.6 running on an IBM POWER7 machine. 
> Initially, I decided to use a toy example where I would expect that the 
> process remains in running state most of the time. This is the code for 
> such a simple example:
> 
> int main() {
>      for (int i = 0; i < 1000000; i++)
>          for (int j = 0; j < 1000; j++);
> }
> 
> I am using the following command line for reading kernel stats:
> 
> perf stat -e 
> "sched:sched_stat_runtime,sched:sched_stat_sleep,sched:sched_stat_wait, \
>      sched:sched_stat_iowait,sched:sched_stat_blocked" ./test
> 
> And these are the results that I obtain:
> 
>   Performance counter stats for './test':
> 
>      12,077,957,756 sched:sched_stat_runtime
>     169,892,740,990 sched:sched_stat_sleep
>           5,816,784 sched:sched_stat_wait
>                   0 sched:sched_stat_iowait
>                   0 sched:sched_stat_blocked
> 
>       12.084706279  seconds time elapsed
> 
> I cannot really understand why the counter for sched_stat_sleep is so 
> high (even higher than sched_stat_runtime), especially for such a 
> CPU-bound workload.
> 
> Am I missing anything, or there could be a problem with sched_stat_sleep 
> counter?

Hi Victor,

Did you ever work out what was going on here?

cheers