Re: [LKP] [lkp-robot] [iversion] c0cef30e4f: aim7.jobs-per-min -18.0% regression
From: kemi
Date: Tue Feb 27 2018 - 02:44:43 EST
On 2018å02æ26æ 20:33, Jeff Layton wrote:
> On Mon, 2018-02-26 at 06:43 -0500, Jeff Layton wrote:
>> On Mon, 2018-02-26 at 16:38 +0800, Ye Xiaolong wrote:
>>> On 02/25, Jeff Layton wrote:
>>>> On Sun, 2018-02-25 at 23:05 +0800, kernel test robot wrote:
>>>>> Greeting,
>>>>>
>>>>> FYI, we noticed a -18.0% regression of aim7.jobs-per-min due to commit:
>>>>>
>>>>>
>>>>> commit: c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e ("iversion: make inode_cmp_iversion{+raw} return bool instead of s64")
>>>>> 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: 4BRD_12G
>>>>> md: RAID0
>>>>> fs: xfs
>>>>> test: disk_src
>>>>> 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/
>>>>>
>>>>>
>>>>
>>>> I'm a bit suspicious of this result.
>>>>
>>>> This patch only changes inode_cmp_iversion{+raw} (since renamed to
>>>> inode_eq_iversion{+raw}), and that neither should ever be called from
>>>> xfs. The patch is fairly trivial too, and I wouldn't expect a big
>>>> performance hit.
>>>
>>> I tried to queue 4 more times test for both commit c0cef30e4f and its parent,
>>> the result seems quite stable.
>>>
>>> c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e:
>>> "aim7.jobs-per-min": [
>>> 32964.01,
>>> 32938.68,
>>> 33068.18,
>>> 32886.32,
>>> 32843.72,
>>> 32798.83,
>>> 32898.34,
>>> 32952.55
>>> ],
>>>
>>> 3da90b159b146672f830bcd2489dd3a1f4e9e089:
>>> "aim7.jobs-per-min": [
>>> 40239.65,
>>> 40163.33,
>>> 40353.32,
>>> 39976.9,
>>> 40185.75,
>>> 40411.3,
>>> 40213.58,
>>> 39900.69
>>> ],
>>>
>>> Any other test data you may need?
>>>
>>>>
>>>> Is IMA involved here at all? I didn't see any evidence of it, but the
>>>> kernel config did have it enabled.
>>>>
>>>
>>> Sorry, not quite familiar with IMA, could you tell more about how to check it?
>>>
>>
>> Thanks for retesting it, but I'm at a loss for why we're seeing this:
>>
>> IMA is the the integrity management subsystem. It will use the iversion
>> field to determine whether to remeasure files during remeasurement. It
>> looks like the kernel config has it enabled, but it doesn't look like
>> it's in use, based on the info in the initial report.
>>
>> This patch only affects two inlined functions inode_cmp_iversion and
>> inode_cmp_iversion_raw. The patch is pretty trivial (as Linus points
>> out). These functions are only called from IMA and fs-specific code
>> (usually in readdir implementations to detect directory changes).
>>
>> XFS does not call either of these functions however, so I'm a little
>> unclear on how this patch could slow anything down on this test. The
>> only thing I can think to do here would be to profile this and see what
>> stands out.
>>
>> Note that we do need to keep this in perspective too. This 18%
>> regression on this test follows around a ~230% improvement that occurred
>> when we merged the bulk of these patches. It's should still be quite a
>> bit faster than the v4.15 in this regard.
>>
>> Still, it'd be good to understand what's going on here.
>>
>>
>
> Could we see the dmesg from this boot? It'd be good to confirm that IMA
> is not involved here, as that's the only place that I can see that would
> call into this code at all here.
>
See attachment for info on dmesg/perf-profile/compare_result.
Feel free to let Xiaolong or me know if anything else you would like to check.
> Thanks,
> Jeff
>
>
>>> Thanks,
>>> Xiaolong
>>>>
>>>>>
>>>>> Details are as below:
>>>>> -------------------------------------------------------------------------------------------------->
>>>>>
>>>>>
>>>>> To reproduce:
>>>>>
>>>>> git clone https://github.com/intel/lkp-tests.git
>>>>> cd lkp-tests
>>>>> bin/lkp install job.yaml # job file is attached in this email
>>>>> bin/lkp run job.yaml
>>>>>
>>>>> =========================================================================================
>>>>> compiler/cpufreq_governor/disk/fs/kconfig/load/md/rootfs/tbox_group/test/testcase:
>>>>> gcc-7/performance/4BRD_12G/xfs/x86_64-rhel-7.2/3000/RAID0/debian-x86_64-2016-08-31.cgz/lkp-ivb-ep01/disk_src/aim7
>>>>>
>>>>> commit:
>>>>> 3da90b159b (" f2fs-for-4.16-rc1")
>>>>> c0cef30e4f ("iversion: make inode_cmp_iversion{+raw} return bool instead of s64")
>>>>>
>>>>> 3da90b159b146672 c0cef30e4ff0dc025f4a1660b8
>>>>> ---------------- --------------------------
>>>>> %stddev %change %stddev
>>>>> \ | \
>>>>> 40183 -18.0% 32964 aim7.jobs-per-min
>>>>> 448.60 +21.9% 546.68 aim7.time.elapsed_time
>>>>> 448.60 +21.9% 546.68 aim7.time.elapsed_time.max
>>>>> 5615 Â 5% +33.4% 7489 Â 4% aim7.time.involuntary_context_switches
>>>>> 3086 +14.0% 3518 aim7.time.system_time
>>>>> 19439782 -5.6% 18359474 aim7.time.voluntary_context_switches
>>>>> 199333 +14.3% 227794 Â 2% interrupts.CAL:Function_call_interrupts
>>>>> 0.59 -0.1 0.50 mpstat.cpu.usr%
>>>>> 2839401 +16.0% 3293688 softirqs.SCHED
>>>>> 7600068 +15.1% 8747820 softirqs.TIMER
>>>>> 118.00 Â 43% +98.7% 234.50 Â 15% vmstat.io.bo
>>>>> 87840 -22.4% 68154 vmstat.system.cs
>>>>> 552798 Â 6% +15.8% 640107 Â 4% numa-numastat.node0.local_node
>>>>> 557345 Â 6% +15.7% 644666 Â 4% numa-numastat.node0.numa_hit
>>>>> 528341 Â 7% +21.7% 642933 Â 4% numa-numastat.node1.local_node
>>>>> 531604 Â 7% +21.6% 646209 Â 4% numa-numastat.node1.numa_hit
>>>>> 2.147e+09 -12.4% 1.88e+09 cpuidle.C1.time
>>>>> 13702041 -14.7% 11683737 cpuidle.C1.usage
>>>>> 2.082e+08 Â 4% +28.1% 2.667e+08 Â 5% cpuidle.C1E.time
>>>>> 4.719e+08 Â 2% +23.1% 5.807e+08 Â 4% cpuidle.C3.time
>>>>> 1.141e+10 +31.0% 1.496e+10 cpuidle.C6.time
>>>>> 15672622 +27.8% 20031028 cpuidle.C6.usage
>>>>> 13520572 Â 3% +29.5% 17514398 Â 9% cpuidle.POLL.time
>>>>> 278.25 Â 5% -46.0% 150.25 Â 73% numa-vmstat.node0.nr_dirtied
>>>>> 3200 Â 14% -20.6% 2542 Â 19% numa-vmstat.node0.nr_mapped
>>>>> 277.75 Â 5% -46.2% 149.50 Â 73% numa-vmstat.node0.nr_written
>>>>> 28.50 Â 52% +448.2% 156.25 Â 70% numa-vmstat.node1.nr_dirtied
>>>>> 2577 Â 19% +26.3% 3255 Â 15% numa-vmstat.node1.nr_mapped
>>>>> 634338 Â 4% +7.8% 683959 Â 4% numa-vmstat.node1.numa_hit
>>>>> 457411 Â 6% +10.8% 506800 Â 5% numa-vmstat.node1.numa_local
>>>>> 3734 Â 8% -11.5% 3306 Â 6% proc-vmstat.numa_hint_faults_local
>>>>> 1114538 +18.3% 1318978 proc-vmstat.numa_hit
>>>>> 1106722 +18.5% 1311136 proc-vmstat.numa_local
>>>>> 22100 +7.5% 23753 Â 4% proc-vmstat.numa_pages_migrated
>>>>> 1174556 +18.0% 1386359 proc-vmstat.pgalloc_normal
>>>>> 1241445 +18.1% 1466086 proc-vmstat.pgfault
>>>>> 1138310 +19.3% 1358132 proc-vmstat.pgfree
>>>>> 22100 +7.5% 23753 Â 4% proc-vmstat.pgmigrate_success
>>>>> 53332 Â 43% +143.0% 129617 Â 14% proc-vmstat.pgpgout
>>>>> 1.42 Â 2% +1.7 3.07 perf-stat.branch-miss-rate%
>>>>> 1.064e+10 +123.3% 2.375e+10 perf-stat.branch-misses
>>>>> 10.79 +0.6 11.43 perf-stat.cache-miss-rate%
>>>>> 5.583e+09 +5.9% 5.915e+09 perf-stat.cache-misses
>>>>> 39652092 -5.0% 37662545 perf-stat.context-switches
>>>>> 1.29 +11.7% 1.44 perf-stat.cpi
>>>>> 4.637e+12 +12.8% 5.23e+12 perf-stat.cpu-cycles
>>>>> 8.653e+11 +9.8% 9.498e+11 Â 2% perf-stat.dTLB-loads
>>>>> 3.654e+11 +12.4% 4.109e+11 perf-stat.dTLB-stores
>>>>> 0.78 -10.5% 0.70 perf-stat.ipc
>>>>> 1214932 +17.9% 1432266 perf-stat.minor-faults
>>>>> 1.334e+09 -1.8% 1.31e+09 perf-stat.node-store-misses
>>>>> 1.651e+09 -1.8% 1.62e+09 perf-stat.node-stores
>>>>> 1214954 +17.9% 1432313 perf-stat.page-faults
>>>>> 256.75 -100.0% 0.00 turbostat.Avg_MHz
>>>>> 21.39 -21.4 0.00 turbostat.Busy%
>>>>> 1200 -100.0% 0.00 turbostat.Bzy_MHz
>>>>> 13695007 -100.0% 0.00 turbostat.C1
>>>>> 11.92 -11.9 0.00 turbostat.C1%
>>>>> 2116683 Â 2% -100.0% 0.00 turbostat.C1E
>>>>> 1.16 Â 4% -1.2 0.00 turbostat.C1E%
>>>>> 3112269 -100.0% 0.00 turbostat.C3
>>>>> 2.62 Â 2% -2.6 0.00 turbostat.C3%
>>>>> 15671277 -100.0% 0.00 turbostat.C6
>>>>> 63.38 -63.4 0.00 turbostat.C6%
>>>>> 49.46 -100.0% 0.00 turbostat.CPU%c1
>>>>> 1.42 Â 2% -100.0% 0.00 turbostat.CPU%c3
>>>>> 27.73 -100.0% 0.00 turbostat.CPU%c6
>>>>> 31.41 -100.0% 0.00 turbostat.CorWatt
>>>>> 63.25 -100.0% 0.00 turbostat.CoreTmp
>>>>> 18919351 -100.0% 0.00 turbostat.IRQ
>>>>> 1.21 Â 18% -100.0% 0.00 turbostat.Pkg%pc2
>>>>> 0.67 Â 31% -100.0% 0.00 turbostat.Pkg%pc6
>>>>> 63.25 -100.0% 0.00 turbostat.PkgTmp
>>>>> 57.63 -100.0% 0.00 turbostat.PkgWatt
>>>>> 30.73 -100.0% 0.00 turbostat.RAMWatt
>>>>> 36030 -100.0% 0.00 turbostat.SMI
>>>>> 3000 -100.0% 0.00 turbostat.TSC_MHz
>>>>>
>>>>>
>>>>> aim7.jobs-per-min
>>>>>
>>>>> 41000 +-+-----------------------------------------------------------------+
>>>>> | ..+....+.... ..+....+....+.... ..+....+....+...+.... |
>>>>> 40000 +-+ +. +.. + |
>>>>> 39000 +-+ |
>>>>> | |
>>>>> 38000 +-+ |
>>>>> 37000 +-+ |
>>>>> | |
>>>>> 36000 +-+ |
>>>>> 35000 +-+ |
>>>>> | |
>>>>> 34000 +-+ |
>>>>> 33000 +-+ O O |
>>>>> O O O O O O O O O O O O O
>>>>> 32000 +-+-----------------------------------------------------------------+
>>>>>
>>>>>
>>>>>
>>>>> [*] 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
>>>>
>>>> --
>>>> Jeff Layton <jlayton@xxxxxxxxxx>
>>
>>
>
=========================================================================================
compiler/cpufreq_governor/disk/fs/kconfig/load/md/rootfs/tbox_group/test/testcase:
gcc-7/performance/4BRD_12G/xfs/x86_64-rhel-7.2/3000/RAID0/debian-x86_64-2016-08-31.cgz/lkp-ivb-ep01/disk_src/aim7
commit:
3da90b159b146672f830bcd2489dd3a1f4e9e089
c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e
3da90b159b146672 c0cef30e4ff0dc025f4a1660b8
---------------- --------------------------
fail:runs %reproduction fail:runs
| | |
:8 12% 1:8 kmsg.igb#:#:#eth#:Reset_adapter
%stddev %change %stddev
\ | \
40180 -18.1% 32918 aim7.jobs-per-min
448.60 +22.0% 547.44 aim7.time.elapsed_time
448.60 +22.0% 547.44 aim7.time.elapsed_time.max
5595 Â 5% +36.2% 7622 Â 4% aim7.time.involuntary_context_switches
3097 +13.8% 3523 aim7.time.system_time
19522724 -5.9% 18370743 aim7.time.voluntary_context_switches
201836 Â 2% +13.1% 228344 interrupts.CAL:Function_call_interrupts
0.59 -0.1 0.50 mpstat.cpu.usr%
2710 Â 21% +25.2% 3392 Â 11% numa-vmstat.node1.nr_mapped
2847741 +16.1% 3307455 softirqs.SCHED
7624688 +15.3% 8792577 softirqs.TIMER
107.62 Â 37% +139.1% 257.38 Â 16% vmstat.io.bo
88187 -22.5% 68324 vmstat.system.cs
554670 Â 6% +16.5% 646113 Â 4% numa-numastat.node0.local_node
559882 Â 6% +16.2% 650671 Â 4% numa-numastat.node0.numa_hit
527564 Â 7% +19.6% 630973 Â 5% numa-numastat.node1.local_node
530184 Â 7% +19.6% 634248 Â 5% numa-numastat.node1.numa_hit
448.60 +22.0% 547.44 time.elapsed_time
448.60 +22.0% 547.44 time.elapsed_time.max
5595 Â 5% +36.2% 7622 Â 4% time.involuntary_context_switches
3097 +13.8% 3523 time.system_time
2.15e+09 -12.7% 1.877e+09 cpuidle.C1.time
13794376 -14.7% 11763584 cpuidle.C1.usage
2.177e+08 Â 7% +28.0% 2.786e+08 Â 7% cpuidle.C1E.time
2165926 Â 3% +11.0% 2403536 Â 3% cpuidle.C1E.usage
4.892e+08 Â 5% +23.8% 6.055e+08 Â 6% cpuidle.C3.time
3178141 Â 3% +11.4% 3539896 Â 4% cpuidle.C3.usage
1.137e+10 +30.7% 1.486e+10 cpuidle.C6.time
15679816 +27.8% 20040445 cpuidle.C6.usage
14899707 Â 16% +25.6% 18719127 Â 11% cpuidle.POLL.time
3770 Â 5% -12.6% 3296 Â 7% proc-vmstat.numa_hint_faults_local
1117601 +17.4% 1312158 proc-vmstat.numa_hit
1109761 +17.5% 1304316 proc-vmstat.numa_local
22084 +7.3% 23703 Â 5% proc-vmstat.numa_pages_migrated
1177178 +17.3% 1380361 proc-vmstat.pgalloc_normal
1243868 +17.6% 1462472 proc-vmstat.pgfault
1144605 +17.7% 1347219 proc-vmstat.pgfree
22084 +7.3% 23703 Â 5% proc-vmstat.pgmigrate_success
48740 Â 36% +191.4% 142047 Â 16% proc-vmstat.pgpgout
1.43 Â 2% +1.6 3.07 perf-stat.branch-miss-rate%
1.064e+10 +123.3% 2.376e+10 perf-stat.branch-misses
10.70 +0.6 11.34 perf-stat.cache-miss-rate%
5.566e+09 +5.6% 5.879e+09 perf-stat.cache-misses
39820560 -5.4% 37689303 perf-stat.context-switches
1.30 +10.9% 1.44 perf-stat.cpi
4.651e+12 +12.3% 5.223e+12 perf-stat.cpu-cycles
308740 Â 5% -9.0% 280970 Â 3% perf-stat.cpu-migrations
8.647e+11 Â 2% +9.2% 9.446e+11 Â 2% perf-stat.dTLB-loads
3.667e+11 +11.6% 4.092e+11 perf-stat.dTLB-stores
0.77 -9.9% 0.70 perf-stat.ipc
1215760 +17.6% 1429660 perf-stat.minor-faults
1.335e+09 -1.8% 1.31e+09 perf-stat.node-store-misses
1.651e+09 -2.0% 1.618e+09 perf-stat.node-stores
1215772 +17.6% 1429689 perf-stat.page-faults
258.12 -100.0% 0.00 turbostat.Avg_MHz
21.48 -21.5 0.00 turbostat.Busy%
1201 -100.0% 0.00 turbostat.Bzy_MHz
13786364 -100.0% 0.00 turbostat.C1
11.94 -11.9 0.00 turbostat.C1%
2165886 Â 3% -100.0% 0.00 turbostat.C1E
1.21 Â 7% -1.2 0.00 turbostat.C1E%
3178025 Â 3% -100.0% 0.00 turbostat.C3
2.72 Â 5% -2.7 0.00 turbostat.C3%
15678302 -100.0% 0.00 turbostat.C6
63.13 -63.1 0.00 turbostat.C6%
49.63 -100.0% 0.00 turbostat.CPU%c1
1.44 Â 3% -100.0% 0.00 turbostat.CPU%c3
27.45 -100.0% 0.00 turbostat.CPU%c6
31.80 -100.0% 0.00 turbostat.CorWatt
64.62 Â 2% -100.0% 0.00 turbostat.CoreTmp
19097866 -100.0% 0.00 turbostat.IRQ
1.27 Â 15% -100.0% 0.00 turbostat.Pkg%pc2
0.50 Â 55% -100.0% 0.00 turbostat.Pkg%pc6
64.62 Â 2% -100.0% 0.00 turbostat.PkgTmp
58.06 -100.0% 0.00 turbostat.PkgWatt
30.80 -100.0% 0.00 turbostat.RAMWatt
36030 -100.0% 0.00 turbostat.SMI
3000 -100.0% 0.00 turbostat.TSC_MHz
14367 Â222% -98.0% 281.25 Â 29% latency_stats.avg.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_lookup.nfs_lookup.lookup_slow.walk_component.path_lookupat.filename_lookup.vfs_statx
9308 Â241% -97.3% 254.00 Â 56% latency_stats.avg.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_access.nfs_do_access.nfs_permission.__inode_permission.link_path_walk.path_lookupat.filename_lookup
25181 Â134% -88.8% 2812 Â240% latency_stats.avg.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_getattr.__nfs_revalidate_inode.nfs_do_access.nfs_permission.__inode_permission.link_path_walk.path_lookupat
7401 Â256% +1407.6% 111580 Â222% latency_stats.avg.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_do_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
143297 Â 7% +2430.8% 3626504 Â124% latency_stats.avg.max
25018 Â215% +13573.8% 3420956 Â136% latency_stats.avg.io_schedule.nfs_lock_and_join_requests.nfs_updatepage.nfs_write_end.generic_perform_write.nfs_file_write.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
0.00 +Inf% 20831 Â187% latency_stats.avg.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_get_acl.get_acl.posix_acl_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open
14367 Â222% -98.0% 281.25 Â 29% latency_stats.max.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_lookup.nfs_lookup.lookup_slow.walk_component.path_lookupat.filename_lookup.vfs_statx
9308 Â241% -97.3% 254.00 Â 56% latency_stats.max.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_access.nfs_do_access.nfs_permission.__inode_permission.link_path_walk.path_lookupat.filename_lookup
2171 Â255% -90.3% 209.62 Â168% latency_stats.max.kthread_park.smpboot_update_cpumask_percpu_thread.lockup_detector_reconfigure.proc_watchdog_common.proc_sys_call_handler.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
7347 Â 61% -82.9% 1260 Â158% latency_stats.max.io_schedule.__lock_page.do_wp_page.__handle_mm_fault.handle_mm_fault.__do_page_fault.do_page_fault.page_fault
7774 Â 68% +238.2% 26291 Â 73% latency_stats.max.down.xfs_buf_lock.[xfs]._xfs_buf_find.[xfs].xfs_buf_get_map.[xfs].xfs_buf_read_map.[xfs].xfs_trans_read_buf_map.[xfs].xfs_read_agi.[xfs].xfs_ialloc_read_agi.[xfs].xfs_dialloc.[xfs].xfs_ialloc.[xfs].xfs_dir_ialloc.[xfs].xfs_create.[xfs]
1017093 +1152.1% 12735384 Â127% latency_stats.max.max
64.00 Â 31% +2367.4% 1579 Â254% latency_stats.max.down.xfs_buf_lock.[xfs]._xfs_buf_find.[xfs].xfs_buf_get_map.[xfs].xfs_buf_read_map.[xfs].xfs_trans_read_buf_map.[xfs].xfs_btree_read_buf_block.[xfs].xfs_btree_lookup_get_block.[xfs].xfs_btree_lookup.[xfs].xfs_check_agi_freecount.[xfs].xfs_dialloc_ag.[xfs].xfs_dialloc.[xfs]
7406 Â256% +2607.5% 200539 Â219% latency_stats.max.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_do_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
44.75 Â 17% +3313.7% 1527 Â255% latency_stats.max.down.xfs_buf_lock.[xfs]._xfs_buf_find.[xfs].xfs_buf_get_map.[xfs].xfs_buf_read_map.[xfs].xfs_trans_read_buf_map.[xfs].xfs_btree_read_buf_block.[xfs].xfs_btree_lookup_get_block.[xfs].xfs_btree_lookup.[xfs].xfs_check_agi_freecount.[xfs].xfs_difree_inobt.[xfs].xfs_difree.[xfs]
27397 Â194% +43598.3% 11972338 Â139% latency_stats.max.io_schedule.nfs_lock_and_join_requests.nfs_updatepage.nfs_write_end.generic_perform_write.nfs_file_write.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
0.00 +Inf% 20831 Â187% latency_stats.max.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_get_acl.get_acl.posix_acl_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open
25466 Â 55% -99.9% 21.00 Â 76% latency_stats.sum.call_rwsem_down_read_failed.page_lock_anon_vma_read.rmap_walk_anon.try_to_unmap.migrate_pages.migrate_misplaced_page.__handle_mm_fault.handle_mm_fault.__do_page_fault.do_page_fault.page_fault
26067 Â 49% -99.6% 109.62 Â 72% latency_stats.sum.call_rwsem_down_read_failed.rmap_walk_anon.remove_migration_ptes.migrate_pages.migrate_misplaced_page.__handle_mm_fault.handle_mm_fault.__do_page_fault.do_page_fault.page_fault
14367 Â222% -98.0% 281.25 Â 29% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_lookup.nfs_lookup.lookup_slow.walk_component.path_lookupat.filename_lookup.vfs_statx
9308 Â241% -97.3% 254.00 Â 56% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_access.nfs_do_access.nfs_permission.__inode_permission.link_path_walk.path_lookupat.filename_lookup
123480 Â 82% -91.4% 10665 Â153% latency_stats.sum.io_schedule.__lock_page.do_wp_page.__handle_mm_fault.handle_mm_fault.__do_page_fault.do_page_fault.page_fault
226641 Â134% -88.8% 25313 Â240% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_proc_getattr.__nfs_revalidate_inode.nfs_do_access.nfs_permission.__inode_permission.link_path_walk.path_lookupat
3523 Â164% -55.3% 1575 Â 41% latency_stats.sum.kthread_park.smpboot_update_cpumask_percpu_thread.lockup_detector_reconfigure.proc_watchdog_common.proc_sys_call_handler.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
7603 Â248% +2829.1% 222711 Â222% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_rpc_wrapper.nfs3_do_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
27942 Â189% +96489.5% 26989044 Â139% latency_stats.sum.io_schedule.nfs_lock_and_join_requests.nfs_updatepage.nfs_write_end.generic_perform_write.nfs_file_write.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
0.00 +Inf% 20831 Â187% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_run_task.rpc_call_sync.nfs3_get_acl.get_acl.posix_acl_create.nfs3_proc_create.nfs_create.path_openat.do_filp_open.do_sys_open
37007 +20.7% 44655 sched_debug.cfs_rq:/.exec_clock.avg
37944 +21.5% 46089 sched_debug.cfs_rq:/.exec_clock.max
36095 +19.5% 43131 sched_debug.cfs_rq:/.exec_clock.min
406.88 Â 10% +62.1% 659.58 Â 13% sched_debug.cfs_rq:/.exec_clock.stddev
337809 Â 2% +13.2% 382358 sched_debug.cfs_rq:/.min_vruntime.avg
324980 Â 3% +12.3% 365044 sched_debug.cfs_rq:/.min_vruntime.min
1.22 Â 6% +19.8% 1.46 Â 3% sched_debug.cfs_rq:/.nr_spread_over.avg
0.88 +20.0% 1.05 Â 10% sched_debug.cfs_rq:/.nr_spread_over.min
276.42 Â 2% -11.3% 245.18 Â 2% sched_debug.cfs_rq:/.util_avg.avg
83.11 Â 19% -27.7% 60.12 Â 9% sched_debug.cfs_rq:/.util_avg.min
356113 Â 3% +10.3% 392719 sched_debug.cpu.avg_idle.avg
237170 +25.5% 297572 sched_debug.cpu.clock.avg
237200 +25.5% 297604 sched_debug.cpu.clock.max
237139 +25.5% 297539 sched_debug.cpu.clock.min
237170 +25.5% 297572 sched_debug.cpu.clock_task.avg
237200 +25.5% 297604 sched_debug.cpu.clock_task.max
237139 +25.5% 297539 sched_debug.cpu.clock_task.min
102.44 Â 4% +9.3% 112.01 Â 4% sched_debug.cpu.cpu_load[2].max
16.33 Â 4% +9.8% 17.93 Â 4% sched_debug.cpu.cpu_load[3].stddev
89.55 Â 8% +13.4% 101.55 Â 4% sched_debug.cpu.cpu_load[4].max
14.80 Â 8% +12.6% 16.66 Â 3% sched_debug.cpu.cpu_load[4].stddev
9619 +16.4% 11192 sched_debug.cpu.curr->pid.max
188120 +24.1% 233473 sched_debug.cpu.nr_load_updates.avg
201745 Â 4% +26.2% 254665 Â 6% sched_debug.cpu.nr_load_updates.max
180770 +20.5% 217762 sched_debug.cpu.nr_load_updates.min
5567 Â 6% +28.4% 7145 Â 15% sched_debug.cpu.sched_count.stddev
2784 Â 6% +28.5% 3577 Â 15% sched_debug.cpu.sched_goidle.stddev
2953 Â 9% +27.1% 3755 Â 9% sched_debug.cpu.ttwu_count.stddev
1837 +31.1% 2409 sched_debug.cpu.ttwu_local.avg
3520 Â 2% +43.1% 5038 Â 4% sched_debug.cpu.ttwu_local.max
1302 Â 3% +34.8% 1755 Â 5% sched_debug.cpu.ttwu_local.min
378.49 Â 5% +41.4% 535.12 Â 6% sched_debug.cpu.ttwu_local.stddev
237137 +25.5% 297537 sched_debug.cpu_clk
237137 +25.5% 297537 sched_debug.ktime
0.00 -30.0% 0.00 Â 37% sched_debug.rt_rq:/.rt_nr_migratory.avg
0.12 -30.0% 0.09 Â 37% sched_debug.rt_rq:/.rt_nr_migratory.max
0.02 -30.0% 0.01 Â 37% sched_debug.rt_rq:/.rt_nr_migratory.stddev
0.00 -30.0% 0.00 Â 37% sched_debug.rt_rq:/.rt_nr_running.avg
0.12 -30.0% 0.09 Â 37% sched_debug.rt_rq:/.rt_nr_running.max
0.02 -30.0% 0.01 Â 37% sched_debug.rt_rq:/.rt_nr_running.stddev
237606 +25.4% 298008 sched_debug.sched_clk
10.67 Â 2% -0.7 9.96 perf-profile.calltrace.cycles-pp.xfs_generic_create.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
5.37 -0.7 4.68 Â 2% perf-profile.calltrace.cycles-pp.xfs_fs_destroy_inode.do_unlinkat.entry_SYSCALL_64_fastpath
5.26 -0.7 4.60 Â 2% perf-profile.calltrace.cycles-pp.xfs_inactive_ifree.xfs_inactive.xfs_fs_destroy_inode.do_unlinkat.entry_SYSCALL_64_fastpath
5.29 -0.7 4.64 Â 2% perf-profile.calltrace.cycles-pp.xfs_inactive.xfs_fs_destroy_inode.do_unlinkat.entry_SYSCALL_64_fastpath
10.26 Â 2% -0.7 9.61 perf-profile.calltrace.cycles-pp.xfs_create.xfs_generic_create.path_openat.do_filp_open.do_sys_open
44.30 -0.4 43.95 Â 2% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_fastpath
19.40 Â 2% -0.3 19.14 Â 3% perf-profile.calltrace.cycles-pp.do_sys_open.entry_SYSCALL_64_fastpath
19.17 Â 2% -0.2 18.93 Â 3% perf-profile.calltrace.cycles-pp.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
19.13 Â 2% -0.2 18.90 Â 3% perf-profile.calltrace.cycles-pp.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
48.98 -0.1 48.86 Â 2% perf-profile.calltrace.cycles-pp.secondary_startup_64
47.73 -0.1 47.62 Â 2% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
47.74 -0.1 47.63 Â 2% perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64
47.74 -0.1 47.63 Â 2% perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64
41.80 -0.1 41.74 Â 2% perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.do_idle.cpu_startup_entry.start_secondary
23.24 +0.1 23.34 perf-profile.calltrace.cycles-pp.do_unlinkat.entry_SYSCALL_64_fastpath
44.42 +0.1 44.56 Â 2% perf-profile.calltrace.cycles-pp.cpuidle_enter_state.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
7.25 Â 5% +0.3 7.51 Â 3% perf-profile.calltrace.cycles-pp.down_write.do_unlinkat.entry_SYSCALL_64_fastpath
7.22 Â 5% +0.3 7.49 Â 3% perf-profile.calltrace.cycles-pp.call_rwsem_down_write_failed.down_write.do_unlinkat.entry_SYSCALL_64_fastpath
7.22 Â 5% +0.3 7.49 Â 3% perf-profile.calltrace.cycles-pp.rwsem_down_write_failed.call_rwsem_down_write_failed.down_write.do_unlinkat.entry_SYSCALL_64_fastpath
4.95 Â 3% +0.3 5.23 Â 3% perf-profile.calltrace.cycles-pp.rwsem_spin_on_owner.rwsem_down_write_failed.call_rwsem_down_write_failed.down_write.do_unlinkat
6.42 Â 7% +0.4 6.86 Â 9% perf-profile.calltrace.cycles-pp.down_write.path_openat.do_filp_open.do_sys_open.entry_SYSCALL_64_fastpath
6.39 Â 7% +0.5 6.84 Â 9% perf-profile.calltrace.cycles-pp.rwsem_down_write_failed.call_rwsem_down_write_failed.down_write.path_openat.do_filp_open
6.39 Â 7% +0.5 6.84 Â 9% perf-profile.calltrace.cycles-pp.call_rwsem_down_write_failed.down_write.path_openat.do_filp_open.do_sys_open
8.98 +0.7 9.69 perf-profile.calltrace.cycles-pp.vfs_unlink.do_unlinkat.entry_SYSCALL_64_fastpath
8.71 +0.7 9.43 perf-profile.calltrace.cycles-pp.xfs_vn_unlink.vfs_unlink.do_unlinkat.entry_SYSCALL_64_fastpath
8.70 +0.7 9.42 perf-profile.calltrace.cycles-pp.xfs_remove.xfs_vn_unlink.vfs_unlink.do_unlinkat.entry_SYSCALL_64_fastpath
5.37 +1.1 6.51 perf-profile.calltrace.cycles-pp.xfs_dir_removename.xfs_remove.xfs_vn_unlink.vfs_unlink.do_unlinkat
7.34 Â 2% -1.0 6.37 Â 3% perf-profile.children.cycles-pp.xfs_log_commit_cil
7.52 Â 2% -1.0 6.57 Â 3% perf-profile.children.cycles-pp.__xfs_trans_commit
10.69 Â 2% -0.7 9.97 perf-profile.children.cycles-pp.xfs_generic_create
5.37 -0.7 4.68 Â 2% perf-profile.children.cycles-pp.xfs_fs_destroy_inode
5.27 -0.7 4.61 Â 2% perf-profile.children.cycles-pp.xfs_inactive_ifree
5.30 -0.7 4.64 Â 2% perf-profile.children.cycles-pp.xfs_inactive
10.28 Â 2% -0.6 9.63 perf-profile.children.cycles-pp.xfs_create
44.55 -0.3 44.20 Â 2% perf-profile.children.cycles-pp.entry_SYSCALL_64_fastpath
19.41 Â 2% -0.3 19.16 Â 3% perf-profile.children.cycles-pp.do_sys_open
19.17 Â 2% -0.2 18.92 Â 3% perf-profile.children.cycles-pp.path_openat
19.18 Â 2% -0.2 18.93 Â 3% perf-profile.children.cycles-pp.do_filp_open
49.02 -0.1 48.89 Â 2% perf-profile.children.cycles-pp.do_idle
48.98 -0.1 48.86 Â 2% perf-profile.children.cycles-pp.secondary_startup_64
48.99 -0.1 48.87 Â 2% perf-profile.children.cycles-pp.cpu_startup_entry
47.74 -0.1 47.63 Â 2% perf-profile.children.cycles-pp.start_secondary
42.89 -0.1 42.83 Â 2% perf-profile.children.cycles-pp.intel_idle
23.25 +0.1 23.35 perf-profile.children.cycles-pp.do_unlinkat
45.72 +0.1 45.86 Â 2% perf-profile.children.cycles-pp.cpuidle_enter_state
8.63 Â 4% +0.7 9.32 Â 3% perf-profile.children.cycles-pp.rwsem_spin_on_owner
13.78 Â 5% +0.7 14.48 Â 5% perf-profile.children.cycles-pp.down_write
8.99 +0.7 9.70 perf-profile.children.cycles-pp.vfs_unlink
13.62 Â 5% +0.7 14.33 Â 5% perf-profile.children.cycles-pp.rwsem_down_write_failed
13.62 Â 5% +0.7 14.34 Â 5% perf-profile.children.cycles-pp.call_rwsem_down_write_failed
8.71 Â 2% +0.7 9.43 perf-profile.children.cycles-pp.xfs_remove
8.71 +0.7 9.44 perf-profile.children.cycles-pp.xfs_vn_unlink
5.38 +1.1 6.51 perf-profile.children.cycles-pp.xfs_dir_removename
5.71 Â 3% +1.6 7.35 Â 3% perf-profile.children.cycles-pp.__xfs_dir3_data_check
42.88 -0.1 42.83 Â 2% perf-profile.self.cycles-pp.intel_idle
8.46 Â 4% +0.7 9.16 Â 3% perf-profile.self.cycles-pp.rwsem_spin_on_owner
Attachment:
3da90b159b146672f830bcd2489dd3a1f4e9e089_dmesg.xz
Description: application/xz
Attachment:
3da90b159b146672f830bcd2489dd3a1f4e9e089_perf-profile.gz
Description: application/gzip
Attachment:
c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e_dmesg.xz
Description: application/xz
Attachment:
c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e_perf-profile.gz
Description: application/gzip