Timing Discrepancy

Chris Kottaridis chiskot at quietwind.net
Tue Jan 31 17:30:32 UTC 2012


I know that mpstat uses /proc/stat to gather it's data and pidstat uses 
/proc/<pid>/stat to get it's data so they are kind of looking at 
different info. The mpstat is looking at the cpustat structure in the 
kernel and the pidsat is looking at the data inside each task structure.

I get a situation once in a while where things don't seem to add up:

# mpstat -P 4 1
05:34:51     CPU   %user   %nice    %sys %iowait    %irq   %soft  
%steal   %idle    intr/s
05:34:51       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    525.00
05:34:52       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    533.00
05:34:53       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    508.00
05:34:54       4    0.99    0.00    0.00    0.00    0.00    0.00    
0.00   99.01    512.00
05:34:55       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00   1010.00
05:34:56       4    0.99    0.00    0.99    0.00    0.99    0.00    
0.00   97.03    751.00
05:34:57       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    746.00
05:34:58       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    762.00
05:34:59       4    0.00    0.00    0.00    0.00    0.00    0.00    
0.00  100.00    642.00

# pidstat -p 2358 -p 592 -p 3607 -p 2362 -p 2324 -u  1
05:34:51          PID   %user %system    %CPU   CPU  Command
05:34:52        2358    2.00    0.00    2.00     4  prog1
05:34:52        592    2.00    0.00    2.00     4  prog2
05:34:52        3607   10.00    2.00   12.00     4  prog3
05:34:52        2362    0.00    0.00    0.00     4  prog4
05:34:52        2324    0.00    0.00    0.00     8  prog5

05:34:52          PID   %user %system    %CPU   CPU  Command
05:34:53        2358    0.00    0.00    0.00     4  prog1
05:34:53        592    2.00    0.00    2.00     4  prog2
05:34:53        3607   12.00    3.00   15.00     4  prog3
05:34:53        2362    0.00    0.00    0.00     4  prog4
05:34:53        2324    0.00    0.00    0.00     8  prog5

05:34:53          PID   %user %system    %CPU   CPU  Command
05:34:54        2358    0.00    0.00    0.00     4  prog1
05:34:54        592    6.00    1.00    7.00     4  prog2
05:34:54        3607    7.00    2.00    9.00     4  prog3
05:34:54        2362    0.00    0.00    0.00     4  prog4
05:34:54        2324    0.00    0.00    0.00     8  prog5

05:34:54          PID   %user %system    %CPU   CPU  Command
05:34:55        2358    0.00    0.00    0.00     4  prog1
05:34:55        592    2.00    1.00    3.00     4  prog2
05:34:55        3607   10.00    3.00   13.00     4  prog3
05:34:55        2362    0.00    0.00    0.00     4  prog4
05:34:55        2324    0.00    0.00    0.00     8  prog5

05:34:55          PID   %user %system    %CPU   CPU  Command
05:34:56        2358    0.00    1.00    1.00     4  prog1
05:34:56        592    7.00    0.00    7.00     4  prog2
05:34:56        3607   12.00    2.00   14.00     4  prog3
05:34:56        2362    0.00    0.00    0.00     4  prog4
05:34:56        2324    0.00    0.00    0.00     8  prog5

05:34:56          PID   %user %system    %CPU   CPU  Command
05:34:57        2358    0.00    0.00    0.00     4  prog1
05:34:57        592    1.00    1.00    2.00     4  prog2
05:34:57        3607   15.00    3.00   18.00     4  prog3
05:34:57        2362    0.00    0.00    0.00     4  prog4
05:34:57        2324    0.00    0.00    0.00     8  prog5

05:34:57          PID   %user %system    %CPU   CPU  Command
05:34:58        2358    2.00    0.00    2.00     4  prog1
05:34:58        592    5.00    1.00    6.00     4  prog2
05:34:58        3607   11.00    3.00   14.00     4  prog3
05:34:58        2362    0.00    0.00    0.00     4  prog4
05:34:58        2324    0.00    0.00    0.00     8  prog5

These processes are tied to processor 4.

You'll see that mpstat shows 0% user while prog3 shows as much as 10% or 
12% in some of the corresponding intervals.
 From looking in the kernel is seems this routine increments both the 
task utime used by pidstat and the cpustat used by mpstat.

/*
  * Account user cpu time to a process.
  * @p: the process that the cpu time gets accounted to
  * @cputime: the cpu time spent in user space since the last update
  */
void account_user_time(struct task_struct *p, cputime_t cputime)
{
         struct cpu_usage_stat *cpustat = &kstat_this_cpu.cpustat;
         cputime64_t tmp;

         p->utime = cputime_add(p->utime, cputime);

         /* Add user time to cpustat. */
         tmp = cputime_to_cputime64(cputime);
         if (TASK_NICE(p) > 0)
                 cpustat->nice = cputime64_add(cpustat->nice, tmp);
         else
                 cpustat->user = cputime64_add(cpustat->user, tmp);
         /* Account for user time used */
         acct_update_integrals(p);
}

This essentially gets called from tick_periodic(), which I assume gets 
called each tick, from the update_process_times() routine which calls 
the account_process_tick() routine which calls the above routine, if 
it's in userspace at the tim eof the tick or a corresponding 
account_system_time() routine if it is in the kernel at the time of the 
tick.

I believe the p->utime = sputime_add() increments the task structure 
that pidstat uses and cpustat->user|nice = cputime64_add() increments 
the cpustat that mpstat looks at. This seems like the only palce in the 
kernel where the task utime gets incemented or the cpustat user time 
gets incremented.

The data shows that the specific process times are as much as 10% but 
the overall is 0%.

How can this happen if these get incremented together in this one place?

What am I missing ?

Thanks
Chris Kottaridis



More information about the users mailing list