0

The problem I'm seeing occurs with virtually any command I run with

perf sched record 

I'll use ls as a very simple example. So if I do

perf sched record ls

followed by

perf sched latency

the scheduler output is as follows

 perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.610 MB perf.data (772 samples) ]

 -------------------------------------------------------------------------------------
  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay 
 -------------------------------------------------------------------------------------
  kworker/u640:1:142368 |      0.064 ms |        1 | avg:    0.058 ms | max:    0.058 
  kworker/75:5:47904    |      0.031 ms |        1 | avg:    0.019 ms | max:    0.019 
  kworker/7:1:238110    |      0.020 ms |        1 | avg:    0.012 ms | max:    0.012 
  VM Periodic Tas:6310  |      0.031 ms |        1 | avg:    0.009 ms | max:    0.009 
  kworker/u640:2:216354 |      0.026 ms |        1 | avg:    0.009 ms | max:    0.009 
  watchdog/62:321       |      0.000 ms |        1 | avg:    0.008 ms | max:    0.008 
  ls:239340             |      4.934 ms |       75 | avg:    0.007 ms | max:    0.061 
  migration/7:47        |      0.000 ms |        1 | avg:    0.006 ms | max:    0.006 
  dsm_sa_datamgrd:13605 |      0.140 ms |        4 | avg:    0.006 ms | max:    0.008 
  rcu_sched:9           |      0.326 ms |        7 | avg:    0.005 ms | max:    0.007 
  sshd:191486           |      1.122 ms |       32 | avg:    0.004 ms | max:    0.051 
  postgres:(16)         |      0.381 ms |        9 | avg:    0.004 ms | max:    0.009 
  kworker/4:2:238454    |      0.668 ms |       73 | avg:    0.003 ms | max:    0.022 
  perf:239339           |     49.838 ms |        1 | avg:    0.002 ms | max:    0.002 
  xfsaild/dm-0:1294     |      0.023 ms |        1 | avg:    0.000 ms | max:    0.000 
  watchdog/61:316       |      0.000 ms |        1 | avg:    0.000 ms | max:    0.000 
  watchdog/60:311       |      0.000 ms |        1 | avg:    0.000 ms | max:    0.000 
  watchdog/59:306       |      0.000 ms |        1 | avg:    0.000 ms | max:    0.000 
  watchdog/58:301       |      0.000 ms |        1 | avg:    0.000 ms | max:    0.000 
 -------------------------------------------------------------------------------------
  TOTAL:                |     57.604 ms |      213 |
 ---------------------------------------------------

I would expect that "Runtime ms" should equal "Switches" * "Average delay ms", but in all cases, "Runtime ms" is much greater than "Switches" * "Average delay ms".

For example, ls:239340 switches 75 times, with an average delay of .007 ms. Multiplying, .007*75 = .525, not 4.934. So something is wrong.

Unless I'm missing something, "perf sched record" output is very wrong.

1 Answer 1

1
  ls:239340             |      4.934 ms |       75 | avg:    0.007 ms | max:    0.061 

means that process 239340, running ls, spent 4.934 ms on CPU in total (actually running), was switched to 75 times, and that the average and maximum scheduling delay (the time between wakeup and the actual context switch to run the process) were respectively 0.007 and 0.061 ms.

The columns measure different things, which aren’t directly related.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .