Re: [LKP] [block] 34b48db66e0: +3291.6% iostat.sde.wrqm/s

[Jens Axboe]

On 01/22/2015 10:47 AM, Jeff Moyer wrote:
> Jens Axboe <axboe@xxxxxx> writes:
> 
>> On 01/21/2015 06:21 PM, Huang Ying wrote:
>>> FYI, we noticed the below changes on
>>>
>>> commit 34b48db66e08ca1c1bc07cf305d672ac940268dc ("block: remove artifical max_hw_sectors cap")
>>>
>>> testbox/testcase/testparams: lkp-ws02/fileio/600s-100%-1HDD-btrfs-64G-1024f-seqrewr-sync
>>>
>>> c2661b806092d8ea  34b48db66e08ca1c1bc07cf305
>>> ----------------  --------------------------
>>>           %stddev     %change         %stddev
>>>               \          |                \
>>>       47176 Â  2%     -67.3%      15406 Â  4%  softirqs.BLOCK
>>>        1110 Â 44%     -51.0%        544 Â 35%  sched_debug.cpu#8.curr->pid
>>>          22 Â 33%     -48.9%         11 Â 43%  sched_debug.cpu#1.cpu_load[0]
>>>          91 Â 43%    +125.0%        204 Â 32%  sched_debug.cfs_rq[4]:/.blocked_load_avg
>>>          17 Â 46%     -65.2%          6 Â 31%  sched_debug.cfs_rq[1]:/.runnable_load_avg
>>>         105 Â 43%    +102.6%        213 Â 32%  sched_debug.cfs_rq[4]:/.tg_load_contrib
>>>         163 Â 35%     +62.6%        265 Â 27%  sched_debug.cfs_rq[16]:/.blocked_load_avg
>>>         183 Â 29%     +51.4%        277 Â 26%  sched_debug.cfs_rq[16]:/.tg_load_contrib
>>>        1411 Â 31%     -42.5%        812 Â 32%  sched_debug.cpu#6.curr->pid
>>>    57565068 Â 15%     +66.8%   96024066 Â 17%  cpuidle.C1E-NHM.time
>>>       94625 Â  9%     -32.5%      63893 Â  4%  cpuidle.C3-NHM.usage
>>>         200 Â 14%     -22.8%        155 Â 24%  sched_debug.cfs_rq[8]:/.tg_load_contrib
>>>         244 Â 33%     -39.0%        149 Â 11%  sched_debug.cfs_rq[6]:/.blocked_load_avg
>>>         265 Â 31%     -38.4%        163 Â  9%  sched_debug.cfs_rq[6]:/.tg_load_contrib
>>>        4959 Â  9%     -18.2%       4058 Â  1%  slabinfo.kmalloc-128.active_objs
>>>        4987 Â  9%     -18.6%       4058 Â  1%  slabinfo.kmalloc-128.num_objs
>>>          19 Â  8%     -19.7%         15 Â 14%  sched_debug.cpu#0.cpu_load[1]
>>>      662307 Â  7%     -12.6%     579108 Â  3%  cpuidle.C6-NHM.usage
>>>        3028 Â  7%     -12.3%       2656 Â  1%  slabinfo.ext4_extent_status.num_objs
>>>        3028 Â  7%     -12.3%       2656 Â  1%  slabinfo.ext4_extent_status.active_objs
>>>        4.87 Â  0%   +3291.6%     165.07 Â  0%  iostat.sde.wrqm/s
>>>        1006 Â  0%    +120.3%       2216 Â  0%  iostat.sde.avgrq-sz
>>
>> So these two above tells us that we are doing way more write merges
>> per second, and that the average request size has roughly doubled from
>> 1006 to 2216 - both are excellent news.
>>
>>>         466 Â  0%    +115.9%       1007 Â  0%  iostat.sde.await
>>>         466 Â  0%    +115.9%       1007 Â  0%  iostat.sde.w_await
>>
>> Service time roughly doubled, must be mostly stream time.
>>
>>>         301 Â  0%     -52.7%        142 Â  0%  iostat.sde.w/s
>>
>> About half the number of writes completed, but from the stats above,
>> those writes are more than double. 1006 * 301 < 2216 * 142, so again,
>> this looks good.
>>
>>>        2230 Â  2%      -8.2%       2048 Â  2%  vmstat.system.in
>>
>> And a nice reduction in irq rate, also nice. Way less software irqs
>> from the first few lines, also a win.
> 
> Agreed on all above, but are the actual benchmark numbers included
> somewhere in all this mess?  I'd like to see if the benchmark numbers
> improved first, before digging into the guts of which functions are
> called more or which stats changed.

I deleted the original email, but the latter tables had drive throughput
rates and it looked higher for the ones I checked on the newer kernel.
Which the above math would indicate as well, multiplying reqs-per-sec
and req-size.

-- 
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/