Wrong statistics results for some cpus

[Vincent Guittot]

I have just tested the last version of idlestat (f0b53ce34662525e5fc2022fbb79c97d34446c71)and i'm a bit surprised by some results.

I have tested it on 3 traces and the results for mp3-2.dat file looks wrong. A quick look at the trace with kernelshark
will show you why i have reached such conclusion.

I have put below the results of idlestat for mp3-2.dat

$ ./idlestat trace-cpuidle-2.dat
Log is 10.015449 secs long with 51456 events
cpu0/state0, 12 hits, total 7942.00us, avg 661.83us, min 45.00us, max 1583.00us
cpu0/state1, 2265 hits, total 8194621.00us, avg 3617.93us, min 354.00us, max 4390.00us
cpu1/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu1/state1, 161 hits, total 9893397.00us, avg 61449.67us, min 6686.00us, max 201103.00us
cpu2/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu2/state1, 2 hits, total 10013913.00us, avg 5006956.50us, min 999999.00us, max 8736870.00us
cpu3/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu3/state1, 8 hits, total 500972.00us, avg 62621.50us, min 6556.00us, max 434479.00us
cpu4/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu4/state1, 16 hits, total 7486588.00us, avg 467911.75us, min 2182.00us, max 2237485.00us
cluster/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cluster/state1, 127 hits, total 403596.00us, avg 3177.92us, min 74.00us, max 4337.00us

The cpu3, cpu4 and cluster statistics look particularly suspicious

I have put my results below which look more aligned with the kernelshark output

system not busy 8196776us, 7942 switch,
system in C1 state 8188834us, 2359 switch, average 3471µs

I have attached the trace file mp3-2.dat

[Benoit Cousson (b-cousson)]

I updated the tree with various fixes to address the problem

git://gitorious.org/pm-tools/idlestat.git master

By default, a "fake" C-state transition to the max C-State is introduced to avoid missing a CPU that is already in idle at the beginning.

> idlestat mp3-2.report.dat

Trace duration: 10.017383s
Undefined period: 8.739899s
cpu_idle #events: 4936
cpu0/state0, 12 hits, total 7942.00us, avg 661.83us, min 45.00us, max 1583.00us
cpu0/state1, 2265 hits, total 8194621.00us, avg 3617.93us, min 354.00us, max 4390.00us
cpu1/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu1/state1, 162 hits, total 10007818.00us, avg 61776.65us, min 6686.00us, max 201103.00us
cpu2/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu2/state1, 3 hits, total 10013913.00us, avg 3337971.00us, min 999999.00us, max 8736870.00us
cpu3/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu3/state1, 9 hits, total 9239681.00us, avg 1026631.22us, min 6556.00us, max 8738709.00us
cpu4/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu4/state1, 17 hits, total 9239059.00us, avg 543474.06us, min 2182.00us, max 2237485.00us
cluster/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cluster/state1, 2176 hits, total 7549258.00us, avg 3469.33us, min 8.00us, max 4390.00us

A new option [-s|--skip] avoid adding a fake entry but then skip all the trace until every CPUs have transitioned to a valid C-state.

The trace in the case is:

>idlestat mp3-2.report.dat

dmtimer_platform_dataidlestat mp3-2.report.dat
Trace duration: 10.017383s
Undefined period: 8.739899s
cpu_idle #events: 4936
cpu0/state0, 2 hits, total 593.00us, avg 296.50us, min 260.00us, max 333.00us
cpu0/state1, 288 hits, total 1044403.00us, avg 3626.40us, min 394.00us, max 4337.00us
cpu1/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu1/state1, 28 hits, total 1274043.00us, avg 45501.54us, min 6908.00us, max 137461.00us
cpu2/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu2/state1, 1 hits, total 1275711.00us, avg 1275711.00us, min 999999.00us, max 1275711.00us
cpu3/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu3/state1, 8 hits, total 500972.00us, avg 62621.50us, min 6556.00us, max 434479.00us
cpu4/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cpu4/state1, 8 hits, total 501165.00us, avg 62645.63us, min 6890.00us, max 434484.00us
cluster/state0, 0 hits, total 0.00us, avg 0.00us, min 0.00us, max 0.00us
cluster/state1, 127 hits, total 403596.00us, avg 3177.92us, min 74.00us, max 4337.00us

A couple of options are added to help the debug:
[--verbose|-v] Print each valid C-state event
[--absolute|-a] Print time with absolute time instead of the default relative time to the beginning.