Re: CPU utilization reporting

[Jens Axboe <axboe@kernel.dk>]

On 2011-09-08 14:31, Kurt wrote:
> Hello FIO community
>  
> I have been working with FIO for a month or so and have studied the source code quite a bit as well.  I have run into an issue where my CPU utilization (sys/user) is actually higher than 100% and in some cases it is higher than 200%!!! When my actual cpu utilization is nowhere near that. 
>  
> These tests were performed on a
> Dell T610 
> 1x E5520 @ 2.27GHz    4 core / 8 thread
> 6GB Ram
>  
> Example:
>  
> [global]
> direct=1
> ramp_time=15
> runtime=30
> loops=1
> sync=0
> filename=/dev/sdb
>  
> [512_Seq_Read-256]
> rw=read
> bs=512
> rwmixread=100
> iodepth=256
> randrepeat=0
> ioengine=libaio
> name=512_Seq_Read-256
> numjobs=2
>  
> 512_Seq_Read-256: (g=0): rw=read, bs=512-512/512-512, ioengine=libaio, iodepth=256
> 512_Seq_Read-256: (g=0): rw=read, bs=512-512/512-512, ioengine=libaio, iodepth=256
> fio 1.57
> Starting 2 threads
>  
> 512_Seq_Read-256: (groupid=0, jobs=1): err= 0: pid=25402
>   read : io=2107.7MB, bw=71933KB/s, iops=143857 , runt= 30003msec
>     slat (usec): min=1 , max=472 , avg= 3.73, stdev=11.11
>     clat (usec): min=133 , max=9529 , avg=1774.29, stdev=867.16
>      lat (usec): min=137 , max=9531 , avg=1778.35, stdev=868.14
>     bw (KB/s) : min=    0, max=102671, per=9.42%, avg=13701.43, stdev=29175.35
>   cpu          : usr=135.37%, sys=132.84%, ctx=346431, majf=0, minf=302
>   IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=151.0%
>      submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.1%
>      issued r/w/d: total=4316167/0/0, short=0/0/0
>      lat (usec): 250=0.39%, 500=6.15%, 750=9.10%, 1000=8.69%
>      lat (msec): 2=29.94%, 4=44.97%, 10=0.76%
> 512_Seq_Read-256: (groupid=0, jobs=1): err= 0: pid=25403
>   read : io=2156.4MB, bw=73590KB/s, iops=147171 , runt= 30001msec
>     slat (usec): min=1 , max=650 , avg= 3.69, stdev=11.05
>     clat (usec): min=130 , max=10959 , avg=1734.38, stdev=860.90
>      lat (usec): min=133 , max=10961 , avg=1738.34, stdev=861.86
>     bw (KB/s) : min=    0, max=103101, per=49.60%, avg=72180.12, stdev=18747.47
>   cpu          : usr=135.38%, sys=132.85%, ctx=346416, majf=0, minf=217
>   IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=149.7%
>      submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.1%
>      issued r/w/d: total=4415302/0/0, short=0/0/0
>      lat (usec): 250=0.42%, 500=6.52%, 750=9.49%, 1000=9.03%
>      lat (msec): 2=30.91%, 4=42.90%, 10=0.74%, 20=0.01%
>  
> Run status group 0 (all jobs):
>    READ: io=4263.7MB, aggrb=145518KB/s, minb=73659KB/s, maxb=75356KB/s, mint=30001msec, maxt=30003msec
>  
> Disk stats (read/write):
>   sdb: ios=3980775/0, merge=9097849/0, ticks=4798475/0, in_queue=4798485, util=99.98%
>  
> As you see the CPU is 135% both usr and sys�    do I need to divide by the number of processor threads (8)?

I suspect you didn't copy the job file correctly, as it has no mention
of 'thread' but you are indeed using threads and not processes. The
usr/sys are accumulated for all threads in a group, so that is why it
could in theory be nr_threads * 100% for both usr and sys time. So yes,
if you wish to inspect per-thread usage, divide by the number of jobs
that you are running. In your case that would be 2.

-- 
Jens Axboe