Re: [LKP] Re: [ext4] d3b6f23f71: stress-ng.fiemap.ops_per_sec -60.5% regression

[Xing Zhengjun <zhengjun.xing@linux.intel.com>]

On 7/22/2020 2:17 PM, Xing Zhengjun wrote:
> 
> 
> On 7/15/2020 7:04 PM, Ritesh Harjani wrote:
>> Hello Xing,
>>
>> On 4/7/20 1:30 PM, kernel test robot wrote:
>>> Greeting,
>>>
>>> FYI, we noticed a -60.5% regression of stress-ng.fiemap.ops_per_sec 
>>> due to commit:
>>>
>>>
>>> commit: d3b6f23f71670007817a5d59f3fbafab2b794e8c ("ext4: move 
>>> ext4_fiemap to use iomap framework")
>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
>>>
>>> in testcase: stress-ng
>>> on test machine: 96 threads Intel(R) Xeon(R) Gold 6252 CPU @ 2.10GHz 
>>> with 192G memory
>>> with following parameters:
>>>
>>>     nr_threads: 10%
>>>     disk: 1HDD
>>>     testtime: 1s
>>>     class: os
>>>     cpufreq_governor: performance
>>>     ucode: 0x500002c
>>>     fs: ext4
>>
>> I started looking into this issue. But with my unit testing, I didn't
>> find any perf issue with fiemap ioctl call. I haven't yet explored about
>> how stress-ng take fiemap performance numbers, it could be doing
>> something differently. But in my testing I just made sure to create a
>> file with large number of extents and used xfs_io -c "fiemap -v" cmd
>> to check how much time it takes to read all the entries in 1st
>> and subsequent iterations.
>>
>>
>> Setup comprised of qemu machine on x86_64 with latest linux branch.
>>
>> 1. created a file of 10G using fallocate. (this allocated unwritten
>> extents for this file).
>>
>> 2. Then I punched hole on every alternate block of file. This step took
>> a long time. And after sufficiently long time, I had to cancel it.
>> for i in $(seq 1 2 xxxxx); do echo $i; fallocate -p -o $(($i*4096)) -l 
>> 4096; done
>>
>> 3. Then issued fiemap call via xfs_io and took the time measurement.
>> time xfs_io -c "fiemap -v" bigfile > /dev/null
>>
>>
>> Perf numbers on latest default kernel build for above cmd.
>>
>> 1st iteration
>> ==============
>> real    0m31.684s
>> user    0m1.593s
>> sys     0m24.174s
>>
>> 2nd and subsequent iteration
>> ============================
>> real    0m3.379s
>> user    0m1.300s
>> sys     0m2.080s
>>
>>
>> 4. Then I reverted all the iomap_fiemap patches and re-tested this.
>> With this the older ext4_fiemap implementation will be tested:-
>>
>>
>> 1st iteration
>> ==============
>> real    0m31.591s
>> user    0m1.400s
>> sys     0m24.243s
>>
>>
>> 2nd and subsequent iteration (had to cancel it since it was taking 
>> more time then 15m)
>> ============================
>> ^C^C
>> real    15m49.884s
>> user    0m0.032s
>> sys     15m49.722s
>>
>> I guess the reason why 2nd iteration with older implementation is taking
>> too much time is since with previous implementation we never cached
>> extent entries in extent_status tree. And also in 1st iteration the page
>> cache may get filled with lot of buffer_head entries. So maybe page
>> reclaims are taking more time.
>>
>> While with the latest implementation using iomap_fiemap(), the call to 
>> query extent blocks is done using ext4_map_blocks(). ext4_map_blocks()
>> by default will also cache the extent entries into extent_status tree.
>> Hence during 2nd iteration, we will directly read the entries from 
>> extent_status tree and will not do any disk I/O.
>>
>> -ritesh

I re-test it on the v5.9-rc1, the regression still existed. Have you 
tried stress-ng test cases?

> 
> Could you try stress-ng( https://kernel.ubuntu.com/~cking/stress-ng/) 
> test cases?  The tarballs can be get from 
> https://kernel.ubuntu.com/~cking/tarballs/stress-ng/.
> The command for this case you can try "stress-ng --timeout 1 --times 
> --verify --metrics-brief --sequential 9 --class os --minimize --exclude 
> spawn,exec,swap"
> I re-test it on the v5.8-rc6, the regression still existed.
> 
> ========================================================================================= 
> 
> tbox_group/testcase/rootfs/kconfig/compiler/debug-setup/nr_threads/disk/testtime/fs/class/cpufreq_governor/ucode: 
> 
> 
> lkp-csl-2sp5/stress-ng/debian-10.4-x86_64-20200603.cgz/x86_64-rhel-8.3/gcc-9/test/10%/1HDD/1s/ext4/os/performance/0x5002f01 
> 
> 
> commit:
>    b2c5764262edded1b1cfff5a6ca82c3d61bb4a4a
>    d3b6f23f71670007817a5d59f3fbafab2b794e8c
>    v5.8-rc6
> 
> b2c5764262edded1 d3b6f23f71670007817a5d59f3f                    v5.8-rc6
> ---------------- --------------------------- ---------------------------
>           %stddev     %change         %stddev     %change         %stddev
>               \          |                \          |                \
>       20419 ±  3%      -4.9%      19423 ±  4%     +27.1%      25959   
> stress-ng.af-alg.ops
>       19655 ±  3%      -5.7%      18537 ±  4%     +27.8%      25111   
> stress-ng.af-alg.ops_per_sec
>       64.67 ±  5%     -17.0%      53.67 ± 38%     +22.2%      79.00 ± 
> 9%  stress-ng.chdir.ops
>       55.34 ±  3%     -13.3%      47.99 ± 38%     +26.4%      69.96 ± 
> 10%  stress-ng.chdir.ops_per_sec
>       64652 ±  7%     -14.1%      55545 ± 11%     -13.6%      55842 ± 
> 6%  stress-ng.chown.ops
>       64683 ±  7%     -14.1%      55565 ± 11%     -13.6%      55858 ± 
> 6%  stress-ng.chown.ops_per_sec
>        2805 ±  2%      +0.6%       2820 ±  2%    +130.0%       6452   
> stress-ng.clone.ops
>        2802 ±  2%      +0.6%       2818 ±  2%    +129.9%       6443   
> stress-ng.clone.ops_per_sec
>       34.67            +1.9%      35.33 ±  3%      -9.6%      31.33 ± 
> 3%  stress-ng.copy-file.ops
>       22297 ± 23%     +26.7%      28258 ±  2%     +38.1%      30783 ± 
> 14%  stress-ng.dir.ops_per_sec
>        4743 ±  7%     -12.6%       4147 ±  4%     -19.9%       3801 ± 
> 14%  stress-ng.dirdeep.ops_per_sec
>       24499 ±  8%      -9.3%      22223 ±  3%     -19.8%      19647 ± 
> 2%  stress-ng.enosys.ops
>       24494 ±  8%      -9.3%      22207 ±  3%     -19.8%      19637 ± 
> 2%  stress-ng.enosys.ops_per_sec
>       76618           -63.8%      27756 ±  5%     -55.5%      34092 ± 
> 2%  stress-ng.fiemap.ops
>       76042           -63.8%      27492 ±  5%     -55.4%      33899 ± 
> 2%  stress-ng.fiemap.ops_per_sec
>     3816791            -6.2%    3581880 ±  2%     -10.7%    3409584 ± 
> 3%  stress-ng.file-ioctl.ops
>     3817421            -6.2%    3582248 ±  2%     -10.7%    3409544 ± 
> 3%  stress-ng.file-ioctl.ops_per_sec
>       27332 ± 17%     +30.2%      35574           +37.2%      37506 ± 
> 6%  stress-ng.filename.ops
>       26222 ± 16%     +28.6%      33722           +35.6%      35567 ± 
> 6%  stress-ng.filename.ops_per_sec
>       23431 ±  2%      +0.5%      23559           +22.5%      28711 ± 
> 4%  stress-ng.fork.ops
>       23433 ±  2%      +0.5%      23558           +22.5%      28709 ± 
> 4%  stress-ng.fork.ops_per_sec
>       48074 ± 15%      -0.6%      47786 ±  9%     -42.5%      27623   
> stress-ng.get.ops
>       48088 ± 15%      -0.6%      47793 ±  9%     -42.6%      27624   
> stress-ng.get.ops_per_sec
>      111379            -1.4%     109815 ±  2%      -7.8%     102662 ± 
> 4%  stress-ng.getdent.ops
>      111398            -1.4%     109818 ±  2%      -7.9%     102651 ± 
> 4%  stress-ng.getdent.ops_per_sec
>      226.67 ±  2%      -1.0%     224.33           -15.1%     192.33 ± 
> 6%  stress-ng.inotify.ops
>      226.39 ±  2%      -1.3%     223.53           -15.3%     191.82 ± 
> 6%  stress-ng.inotify.ops_per_sec
>       18.00            +9.3%      19.67 ±  2%      +3.7%      18.67 ± 
> 2%  stress-ng.iomix.ops
>        4846 ± 10%      +2.9%       4984 ±  7%     -36.8%       3062 ± 
> 7%  stress-ng.kill.ops
>        4846 ± 10%      +2.8%       4982 ±  7%     -36.9%       3058 ± 
> 7%  stress-ng.kill.ops_per_sec
>      851324 ±  3%      -9.9%     766988 ±  2%      +2.3%     870703   
> stress-ng.lease.ops
>      850238 ±  3%      -9.9%     766255 ±  2%      +2.3%     870047   
> stress-ng.lease.ops_per_sec
>      134492 ± 14%      -7.0%     125085 ± 16%     -19.9%     107736 ± 
> 3%  stress-ng.mlock.ops_per_sec
>        1.38            +2.9%       1.42 ±  5%     -20.2%       1.10 ± 
> 12%  stress-ng.mmapfork.ops_per_sec
>     1117721 ±  5%      -9.2%    1015321 ± 20%     -36.2%     713598   
> stress-ng.mq.ops
>     1117186 ±  5%      -9.2%    1014593 ± 20%     -36.2%     712387   
> stress-ng.mq.ops_per_sec
>     4584592 ±  2%      -2.7%    4460470 ±  7%     -12.0%    4036627 ± 
> 8%  stress-ng.msg.ops_per_sec
>        8179 ± 10%      +7.3%       8772 ±  9%     +24.0%      10144   
> stress-ng.opcode.ops
>        8177 ± 10%      +7.2%       8770 ±  9%     +24.0%      10141   
> stress-ng.opcode.ops_per_sec
>        5218 ±  3%      +3.6%       5408 ±  2%     +27.3%       6642   
> stress-ng.reboot.ops
>        5217 ±  3%      +3.6%       5407 ±  2%     +27.3%       6640   
> stress-ng.reboot.ops_per_sec
>        1724 ± 21%     +27.9%       2205 ± 18%     +54.3%       2660 ± 
> 19%  stress-ng.resources.ops
>     1217728           -31.4%     835808 ± 14%     -18.7%     989423 ± 
> 10%  stress-ng.revio.ops
>     1217899           -31.4%     835846 ± 14%     -18.8%     989313 ± 
> 10%  stress-ng.revio.ops_per_sec
>      752664 ±  9%      -7.6%     695116 ± 10%      -0.6%     748117 ± 
> 6%  stress-ng.seal.ops
>      752957 ±  9%      -7.7%     695278 ± 10%      -0.6%     748068 ± 
> 6%  stress-ng.seal.ops_per_sec
>      628.00 ± 83%     -20.1%     502.00 ±  8%    +176.2%       1734   
> stress-ng.seccomp.ops
>      628.22 ± 83%     -20.1%     502.08 ±  8%    +176.1%       1734   
> stress-ng.seccomp.ops_per_sec
>     1361741 ±  7%      +4.0%    1416628 ±  8%     +17.2%    1596549 ± 
> 9%  stress-ng.seek.ops
>     1361799 ±  7%      +4.0%    1416578 ±  8%     +17.2%    1596376 ± 
> 9%  stress-ng.seek.ops_per_sec
>     1537496            +1.2%    1556468            -9.9%    1385679   
> stress-ng.sigrt.ops
>     1532297            +1.3%    1551993            -9.9%    1381175   
> stress-ng.sigrt.ops_per_sec
>     1324589 ± 12%     -26.6%     972626 ±  9%     -14.8%    1128923 ± 
> 4%  stress-ng.sigsuspend.ops
>     1323957 ± 12%     -26.6%     972084 ±  9%     -14.8%    1128174 ± 
> 4%  stress-ng.sigsuspend.ops_per_sec
>      806.67 ± 13%     +11.2%     896.67 ± 10%     +31.3%       1059 ± 
> 4%  stress-ng.sockabuse.ops
>      806.73 ± 13%     +11.1%     896.44 ± 10%     +31.3%       1059 ± 
> 4%  stress-ng.sockabuse.ops_per_sec
>     6224635 ±  2%      +0.8%    6274521 ±  2%     -12.8%    5427883 ± 
> 2%  stress-ng.sockpair.ops
>     5383397            -1.9%    5279526 ±  2%     -14.9%    4579084 ± 
> 4%  stress-ng.sockpair.ops_per_sec
>       22409 ±  6%      -2.8%      21784 ±  5%     -41.2%      13172 ± 
> 9%  stress-ng.sysbadaddr.ops
>       22414 ±  6%      -2.8%      21784 ±  5%     -41.3%      13167 ± 
> 9%  stress-ng.sysbadaddr.ops_per_sec
>      525.33 ± 13%      +2.6%     539.00 ± 15%     -42.1%     304.33 ± 
> 25%  stress-ng.sysfs.ops
>      524.98 ± 13%      +2.6%     538.58 ± 15%     -42.1%     303.79 ± 
> 25%  stress-ng.sysfs.ops_per_sec
>        3077 ± 12%     +19.9%       3689 ±  4%     +23.0%       3786 ± 
> 4%  stress-ng.sysinfo.ops
>        3009 ± 11%     +22.6%       3688 ±  4%     +25.7%       3783 ± 
> 4%  stress-ng.sysinfo.ops_per_sec
>     3001932            +1.2%    3038017           +15.7%    3474274   
> stress-ng.udp.ops
>     3002618            +1.2%    3037939           +15.7%    3473606   
> stress-ng.udp.ops_per_sec
>      184634 ± 12%      -6.9%     171823           +24.5%     229788 ± 
> 4%  stress-ng.utime.ops
>      184678 ± 12%      -7.0%     171836           +24.4%     229784 ± 
> 4%  stress-ng.utime.ops_per_sec
>        1835 ±  5%      +2.2%       1875 ±  4%      +8.2%       1986 ± 
> 3%  stress-ng.vforkmany.ops
>        1829 ±  5%      +1.9%       1863 ±  4%      +8.1%       1978 ± 
> 3%  stress-ng.vforkmany.ops_per_sec
>       14829            -1.0%      14682 ±  2%     -20.1%      11848 ± 
> 3%  stress-ng.vm-segv.ops
>       14830            -1.0%      14682 ±  2%     -29.7%      10433 ± 
> 13%  stress-ng.vm-segv.ops_per_sec
>     3527835 ±  3%      +1.9%    3596613 ±  5%    +495.6%   21010377   
> stress-ng.vm-splice.ops
>     3528845 ±  3%      +1.9%    3597219 ±  5%    +495.4%   21011045   
> stress-ng.vm-splice.ops_per_sec
> 
> 
> 
> 
> 

-- 
Zhengjun Xing