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 <jlay...@redhat.com> >> >> >
=========================================================================================
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
3da90b159b146672f830bcd2489dd3a1f4e9e089_dmesg.xz
Description: application/xz
3da90b159b146672f830bcd2489dd3a1f4e9e089_perf-profile.gz
Description: application/gzip
c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e_dmesg.xz
Description: application/xz
c0cef30e4ff0dc025f4a1660b8f0ba43ed58426e_perf-profile.gz
Description: application/gzip
