Re: [lkp-robot] [f2fs] 4ac912427c: -33.7% aim7.jobs-per-min regression
From: Ye Xiaolong
Date: Thu Mar 16 2017 - 20:58:27 EST
On 03/15, Jaegeuk Kim wrote:
>On 03/14, Ye Xiaolong wrote:
>> On 03/14, Chao Yu wrote:
>> >On 2017/3/14 3:22, Jaegeuk Kim wrote:
>> >> On 03/13, Thorsten Leemhuis wrote:
>> >>> @Chao Yu/@Jaegeuk Kim: I'm considering to add this to the regressions
>> >>> report for 4.11; or is there a reason why it shouldn't be considered a
>> >>> regression? Ciao, Thorsten
>> >>
>> >> Hi,
>> >>
>> >> I'm planning to submit f2fs updates for 4.11-rcX including a patch which
>> >> resolves this issue as well, as I expect.
>> >>
>> >> https://lkml.org/lkml/2017/3/7/813
>> >
>> >Sorry for late repay.
>> >
>> >I expect below patches in Jaegeuk's tree could help to recover the performance
>> >as well
>> >
>> > f2fs: skip scanning free nid bitmap of full NAT blocks
>> > f2fs: combine nat_bits and free_nid_bitmap cache
>>
>> These 2 patches do help recover the performance back. Details as below.
>>
>> Tested-by: Xiaolong Ye <xiaolong.ye@xxxxxxxxx>
>>
>> commit:
>> 4ac912427c4214d8031d9ad6fbc3bc75e71512df ("f2fs: introduce free nid bitmap")
>> ced2c7ea8e99b46755a270872cd5ba61c27cffad <= parent commit of 4ac912427c
>> c0e39d642e41be12937f4532721fc2538182e264 ("f2fs: combine nat_bits and free_nid_bitmap cache")
>
>Thank you for testing them.
>
>BTW, I found one missing clear_bit_le conversion from c0e39d642e41b.
>I updated the original patch and uploaded it into f2fs.git.
>
> d00030cf9cd0bb9 ("f2fs: use __set{__clear}_bit_le")
> 1382c0f3f9d3f93 ("f2fs: combine nat_bits and free_nid_bitmap cache")
>
>Could you please test the above patches from f2fs.git one more time?
>I need to confirm there-in root-cause for next upstream.
>
Here is the comparison results, each commit has been tested for 5 times.
commit:
4ac912427c4214d8031d9ad6fbc3bc75e71512df ("f2fs: introduce free nid bitmap")
d00030cf9cd0bb96fdccc41e33d3c91dcbb672ba ("f2fs: use __set{__clear}_bit_le")
1382c0f3f9d3f936c8bc42ed1591cf7a593ef9f7 ("f2fs: combine nat_bits and free_nid_bitmap cache")
4ac912427c4214d8 d00030cf9cd0bb96fdccc41e33 1382c0f3f9d3f936c8bc42ed15
---------------- -------------------------- --------------------------
%stddev %change %stddev %change %stddev
\ | \ | \
77863 ± 0% +2.1% 79485 ± 1% +50.8% 117404 ± 0% aim7.jobs-per-min
231.63 ± 0% -2.0% 227.01 ± 1% -33.6% 153.80 ± 0% aim7.time.elapsed_time
231.63 ± 0% -2.0% 227.01 ± 1% -33.6% 153.80 ± 0% aim7.time.elapsed_time.max
896604 ± 0% -0.8% 889221 ± 3% -20.2% 715260 ± 1% aim7.time.involuntary_context_switches
2394 ± 1% +4.6% 2503 ± 1% +3.7% 2481 ± 2% aim7.time.maximum_resident_set_size
6240 ± 0% -1.5% 6145 ± 1% -14.1% 5360 ± 1% aim7.time.system_time
1111357 ± 3% +1.9% 1132509 ± 2% -6.2% 1041932 ± 2% aim7.time.voluntary_context_switches
5600256 ± 9% -4.7% 5339136 ± 8% -9.4% 5074534 ± 0% meminfo.DirectMap2M
78738 ± 8% +10.0% 86602 ± 8% +25.0% 98448 ± 2% meminfo.Dirty
20625 ± 0% +18.3% 24403 ± 11% +11.4% 22985 ± 6% meminfo.Mapped
393582 ± 85% -84.9% 59547 ± 2% -86.1% 54561 ± 9% meminfo.Shmem
1328 ± 18% +786.4% 11771 ± 18% +440.6% 7179 ± 26% softirqs.NET_RX
669152 ± 3% -0.7% 664708 ± 2% -11.9% 589420 ± 2% softirqs.RCU
170724 ± 0% +0.1% 170929 ± 7% -19.8% 136921 ± 7% softirqs.SCHED
2688290 ± 0% -1.6% 2646510 ± 1% -13.8% 2317797 ± 1% softirqs.TIMER
4948 ± 3% +5.9% 5240 ± 1% +55.6% 7700 ± 0% vmstat.io.bo
39.00 ± 2% -69.2% 12.00 ± 15% -67.2% 12.80 ± 15% vmstat.procs.b
171.50 ± 2% +17.6% 201.75 ± 12% +41.0% 241.80 ± 9% vmstat.procs.r
13425 ± 1% +24.4% 16706 ± 9% +41.3% 18974 ± 9% vmstat.system.cs
45100 ± 1% +1.4% 45733 ± 0% +6.8% 48162 ± 0% vmstat.system.in
231.63 ± 0% -2.0% 227.01 ± 1% -33.6% 153.80 ± 0% time.elapsed_time
231.63 ± 0% -2.0% 227.01 ± 1% -33.6% 153.80 ± 0% time.elapsed_time.max
896604 ± 0% -0.8% 889221 ± 3% -20.2% 715260 ± 1% time.involuntary_context_switches
2701 ± 0% +0.5% 2713 ± 0% +29.3% 3492 ± 0% time.percent_of_cpu_this_job_got
6240 ± 0% -1.5% 6145 ± 1% -14.1% 5360 ± 1% time.system_time
16.66 ± 0% -4.2% 15.96 ± 7% -26.0% 12.34 ± 5% time.user_time
Thanks,
Xiaolong
>Thanks,
>
>>
>> 4ac912427c4214d8 ced2c7ea8e99b46755a270872c c0e39d642e41be12937f453272
>> ---------------- -------------------------- --------------------------
>> %stddev %change %stddev %change %stddev
>> \ | \ | \
>> 77863 ± 0% +50.8% 117419 ± 1% +50.9% 117500 ± 0% aim7.jobs-per-min
>> 231.63 ± 0% -33.6% 153.78 ± 1% -33.7% 153.67 ± 0% aim7.time.elapsed_time
>> 231.63 ± 0% -33.6% 153.78 ± 1% -33.7% 153.67 ± 0% aim7.time.elapsed_time.max
>> 896604 ± 0% -10.1% 805644 ± 3% -20.8% 710207 ± 1% aim7.time.involuntary_context_switches
>> 6240 ± 0% -13.3% 5408 ± 1% -14.2% 5353 ± 1% aim7.time.system_time
>> 1111357 ± 3% -1.3% 1097209 ± 2% -7.8% 1024716 ± 0% aim7.time.voluntary_context_switches
>> 5600256 ± 9% -9.5% 5066069 ± 0% -9.3% 5078220 ± 13% meminfo.DirectMap2M
>> 78738 ± 8% +72.1% 135538 ± 8% +23.2% 96995 ± 6% meminfo.Dirty
>> 315.50 ± 12% +210.8% 980.67 ± 16% +123.9% 706.40 ± 22% meminfo.Writeback
>> 1328 ± 18% +357.1% 6069 ± 57% +231.1% 4397 ± 75% softirqs.NET_RX
>> 669152 ± 3% -7.4% 619333 ± 4% -14.4% 572896 ± 1% softirqs.RCU
>> 170724 ± 0% -25.0% 128030 ± 2% -23.0% 131531 ± 4% softirqs.SCHED
>> 2688290 ± 0% -13.3% 2331994 ± 1% -14.7% 2292443 ± 1% softirqs.TIMER
>> 4948 ± 3% +55.6% 7701 ± 1% +55.8% 7710 ± 0% vmstat.io.bo
>> 39.00 ± 2% +65.8% 64.67 ± 2% -52.8% 18.40 ± 30% vmstat.procs.b
>> 171.50 ± 2% +94.4% 333.33 ± 7% +29.7% 222.40 ± 7% vmstat.procs.r
>> 13425 ± 1% +30.6% 17530 ± 1% +43.9% 19321 ± 10% vmstat.system.cs
>> 45100 ± 1% +5.6% 47642 ± 1% +6.3% 47957 ± 0% vmstat.system.in
>> 19068 ± 0% +75.8% 33522 ± 4% +24.5% 23745 ± 5% proc-vmstat.nr_dirty
>> 80.00 ± 3% +195.0% 236.00 ± 14% +126.0% 180.80 ± 23% proc-vmstat.nr_writeback
>> 19222 ± 0% +76.4% 33907 ± 4% +24.9% 24004 ± 5% proc-vmstat.nr_zone_write_pending
>>
>> Thanks,
>> Xiaolong
>> >
>> >Xiaolong, Thorsten
>> >
>> >Could you help to test these patches?
>> >
>> >Thanks,
>> >
>> >>
>> >> Thanks,
>> >>
>> >>>
>> >>> On 08.03.2017 02:21, kernel test robot wrote:
>> >>>>
>> >>>> Greeting,
>> >>>>
>> >>>> We noticed a -33.7 regression of aim7.jobs-per-min due to commit:
>> >>>>
>> >>>> commit: 4ac912427c4214d8031d9ad6fbc3bc75e71512df ("f2fs: introduce free nid bitmap")
>> >>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
>> >>>>
>> >>>> in testcase: aim7
>> >>>> on test machine: 40 threads Intel(R) Xeon(R) CPU E5-2690 v2 @ 3.00GHz with 384G memory
>> >>>> with following parameters:
>> >>>>
>> >>>> disk: 1BRD_48G
>> >>>> fs: f2fs
>> >>>> test: disk_wrt
>> >>>> load: 3000
>> >>>> cpufreq_governor: performance
>> >>>>
>> >>>> test-description: AIM7 is a traditional UNIX system level benchmark suite which is used to test and measure the performance of multiuser system.
>> >>>> test-url: https://sourceforge.net/projects/aimbench/files/aim-suite7/
>> >>>>
>> >>>>
>> >>>>
>> >>>> Details are as below:
>> >>>> -------------------------------------------------------------------------------------------------->
>> >>>>
>> >>>>
>> >>>> To reproduce:
>> >>>>
>> >>>> git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
>> >>>> cd lkp-tests
>> >>>> bin/lkp install job.yaml # job file is attached in this email
>> >>>> bin/lkp run job.yaml
>> >>>>
>> >>>> testcase/path_params/tbox_group/run: aim7/1BRD_48G-f2fs-disk_wrt-3000-performance/lkp-ivb-ep01
>> >>>>
>> >>>> ced2c7ea8e99b467 4ac912427c4214d8031d9ad6fb
>> >>>> ---------------- --------------------------
>> >>>> %stddev change %stddev
>> >>>> \ | \
>> >>>> 117419 ± 1% -33.7% 77863 ± 0% aim7.jobs-per-min
>> >>>> 153.78 ± 1% +50.6% 231.63 ± 0% aim7.time.elapsed_time
>> >>>> 153.78 ± 1% +50.6% 231.63 ± 0% aim7.time.elapsed_time.max
>> >>>> 805644 ± 3% +11.3% 896604 ± 0% aim7.time.involuntary_context_switches
>> >>>> 5408 ± 1% +15.4% 6240 ± 0% aim7.time.system_time
>> >>>> 5066069 ± 0% +10.5% 5600256 ± 9% meminfo.DirectMap2M
>> >>>> 135538 ± 8% -41.9% 78738 ± 8% meminfo.Dirty
>> >>>> 980.67 ± 16% -67.8% 315.50 ± 12% meminfo.Writeback
>> >>>> 71322 ± 10% -44.0% 39953 ± 1% numa-meminfo.node0.Dirty
>> >>>> 11158 ± 18% -27.1% 8132 ± 0% numa-meminfo.node0.Mapped
>> >>>> 56776 ± 6% -32.5% 38309 ± 0% numa-meminfo.node1.Dirty
>> >>>> 9684 ± 22% +30.9% 12676 ± 0% numa-meminfo.node1.Mapped
>> >>>> 6069 ± 57% -78.1% 1328 ± 18% softirqs.NET_RX
>> >>>> 619333 ± 4% +8.0% 669152 ± 3% softirqs.RCU
>> >>>> 128030 ± 2% +33.3% 170724 ± 0% softirqs.SCHED
>> >>>> 2331994 ± 1% +15.3% 2688290 ± 0% softirqs.TIMER
>> >>>> 7701 ± 1% -35.7% 4948 ± 3% vmstat.io.bo
>> >>>> 64.67 ± 2% -39.7% 39.00 ± 2% vmstat.procs.b
>> >>>> 333.33 ± 7% -48.5% 171.50 ± 2% vmstat.procs.r
>> >>>> 17530 ± 1% -23.4% 13425 ± 1% vmstat.system.cs
>> >>>> 47642 ± 1% -5.3% 45100 ± 1% vmstat.system.in
>> >>>> 33522 ± 4% -43.1% 19068 ± 0% proc-vmstat.nr_dirty
>> >>>> 236.00 ± 14% -66.1% 80.00 ± 3% proc-vmstat.nr_writeback
>> >>>> 33907 ± 4% -43.3% 19222 ± 0% proc-vmstat.nr_zone_write_pending
>> >>>> 28194 ± 10% +10.4% 31131 ± 6% proc-vmstat.pgactivate
>> >>>> 746402 ± 2% +24.6% 929960 ± 3% proc-vmstat.pgfault
>> >>>> 153.78 ± 1% +50.6% 231.63 ± 0% time.elapsed_time
>> >>>> 153.78 ± 1% +50.6% 231.63 ± 0% time.elapsed_time.max
>> >>>> 805644 ± 3% +11.3% 896604 ± 0% time.involuntary_context_switches
>> >>>> 3524 ± 0% -23.4% 2701 ± 0% time.percent_of_cpu_this_job_got
>> >>>> 5408 ± 1% +15.4% 6240 ± 0% time.system_time
>> >>>> 12.19 ± 1% +36.7% 16.66 ± 0% time.user_time
>> >>>> 48260939 ± 3% +12.1% 54110616 ± 2% cpuidle.C1-IVT.time
>> >>>> 33149237 ± 5% +52.6% 50597349 ± 1% cpuidle.C1E-IVT.time
>> >>>> 89642 ± 4% +52.8% 136976 ± 0% cpuidle.C1E-IVT.usage
>> >>>> 13534795 ± 6% +276.3% 50934566 ± 55% cpuidle.C3-IVT.time
>> >>>> 42893 ± 6% +138.8% 102439 ± 30% cpuidle.C3-IVT.usage
>> >>>> 6.431e+08 ± 2% +390.1% 3.152e+09 ± 10% cpuidle.C6-IVT.time
>> >>>> 802009 ± 2% +375.3% 3811880 ± 10% cpuidle.C6-IVT.usage
>> >>>> 1535987 ± 4% +156.3% 3936830 ± 4% cpuidle.POLL.time
>> >>>> 88.14 ± 0% -24.9% 66.17 ± 3% turbostat.%Busy
>> >>>> 2659 ± 0% -44.7% 1471 ± 3% turbostat.Avg_MHz
>> >>>> 3016 ± 0% -26.3% 2224 ± 0% turbostat.Bzy_MHz
>> >>>> 5.20 ± 5% +127.0% 11.80 ± 2% turbostat.CPU%c1
>> >>>>
>> >>>>
>> >>>>
>> >>>> perf-stat.page-faults
>> >>>>
>> >>>> 1e+06 ++-----------------------------------------------------------------+
>> >>>> 900000 O+O O O O O O O O |
>> >>>> | O O O O O O O O O O |
>> >>>> 800000 ++ .*.*. .*. .*. .*.. |
>> >>>> 700000 ++*.*.*.*.*..*.* *.*.*.*.*.*..*.* * *.*.*.*.* *.*.*.* *
>> >>>> | : : |
>> >>>> 600000 ++: : |
>> >>>> 500000 ++ : :|
>> >>>> 400000 ++ : :|
>> >>>> |: : :|
>> >>>> 300000 ++ : :|
>> >>>> 200000 ++ : :|
>> >>>> | : |
>> >>>> 100000 ++ : |
>> >>>> 0 *+------------------------------------O-O------------------------*-+
>> >>>>
>> >>>>
>> >>>> perf-stat.minor-faults
>> >>>>
>> >>>> 1e+06 ++-----------------------------------------------------------------+
>> >>>> 900000 O+O O O O O O O O |
>> >>>> | O O O O O O O O O O |
>> >>>> 800000 ++ .*.*. .*. .*. .*.. |
>> >>>> 700000 ++*.*.*.*.*..*.* *.*.*.*.*.*..*.* * *.*.*.*.* *.*.*.* *
>> >>>> | : : |
>> >>>> 600000 ++: : |
>> >>>> 500000 ++ : :|
>> >>>> 400000 ++ : :|
>> >>>> |: : :|
>> >>>> 300000 ++ : :|
>> >>>> 200000 ++ : :|
>> >>>> | : |
>> >>>> 100000 ++ : |
>> >>>> 0 *+------------------------------------O-O------------------------*-+
>> >>>>
>> >>>>
>> >>>> aim7.jobs-per-min
>> >>>>
>> >>>> 140000 ++-----------------------------------------------------------------+
>> >>>> | *. .*.. .*.*.*.*.*.*.*..*.*.*.*.*.*. |
>> >>>> 120000 ++: *.*.* *.*.* *.*.*.*.*..*.*.*. *
>> >>>> | : * |
>> >>>> 100000 ++: : |
>> >>>> |: : |
>> >>>> 80000 O+O O O O O O O O O O O O O O O O O O : :|
>> >>>> |: : :|
>> >>>> 60000 ++ : :|
>> >>>> |: : :|
>> >>>> 40000 ++ : :|
>> >>>> | : :|
>> >>>> 20000 ++ : |
>> >>>> | : |
>> >>>> 0 *+------------------------------------O-O------------------------*-+
>> >>>>
>> >>>>
>> >>>>
>> >>>> [*] bisect-good sample
>> >>>> [O] bisect-bad sample
>> >>>>
>> >>>>
>> >>>> Disclaimer:
>> >>>> Results have been estimated based on internal Intel analysis and are provided
>> >>>> for informational purposes only. Any difference in system hardware or software
>> >>>> design or configuration may affect actual performance.
>> >>>>
>> >>>>
>> >>>> Thanks,
>> >>>> Xiaolong
>> >>>>
>> >>
>> >> .
>> >>
>> >