2023-04-14 02:10:50

by kernel test robot

[permalink] [raw]
Subject: [linus:master] [btrfs] 4ae2edf12d: fio.write_iops -11.9% regression

Hello,

kernel test robot noticed a -11.9% regression of fio.write_iops on:

commit: 4ae2edf12d49fdbaea2dfda0bb2ec06501bd3493 ("btrfs: simplify parameters of btrfs_lookup_bio_sums")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

testcase: fio-basic
test machine: 96 threads 2 sockets (Ice Lake) with 256G memory
parameters:

runtime: 300s
disk: 1HDD
fs: btrfs
nr_task: 100%
test_size: 128G
rw: write
bs: 4k
ioengine: io_uring
direct: direct
cpufreq_governor: performance

test-description: Fio is a tool that will spawn a number of threads or processes doing a particular type of I/O action as specified by the user.
test-url: https://github.com/axboe/fio


If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <[email protected]>
| Link: https://lore.kernel.org/oe-lkp/[email protected]


Details are as below:

=========================================================================================
bs/compiler/cpufreq_governor/direct/disk/fs/ioengine/kconfig/nr_task/rootfs/runtime/rw/tbox_group/test_size/testcase:
4k/gcc-11/performance/direct/1HDD/btrfs/io_uring/x86_64-rhel-8.3/100%/debian-11.1-x86_64-20220510.cgz/300s/write/lkp-icl-2sp1/128G/fio-basic

commit:
5fa356531e ("btrfs: remove the direct I/O read checksum lookup optimization")
4ae2edf12d ("btrfs: simplify parameters of btrfs_lookup_bio_sums")

5fa356531e33e7c7 4ae2edf12d49fdbaea2dfda0bb2
---------------- ---------------------------
%stddev %change %stddev
\ | \
1.99 ? 2% +0.1 2.09 fio.latency_1000ms%
0.85 ? 4% -0.3 0.56 ? 13% fio.latency_100ms%
3.65 +0.4 4.02 ? 2% fio.latency_2000ms%
68.99 -16.8 52.15 fio.latency_250ms%
19.81 ? 2% +15.7 35.54 ? 2% fio.latency_500ms%
3.23 ? 2% +0.5 3.70 ? 2% fio.latency_750ms%
1.44 +0.5 1.91 fio.latency_>=2000ms%
22375141 -11.8% 19728171 fio.time.file_system_outputs
745392 ? 3% -10.5% 667220 fio.time.voluntary_context_switches
2796892 -11.8% 2466021 fio.workload
36.37 -11.9% 32.05 fio.write_bw_MBps
5.187e+08 +14.0% 5.914e+08 fio.write_clat_90%_us
1.012e+09 +13.3% 1.147e+09 fio.write_clat_95%_us
2.298e+09 +12.4% 2.584e+09 fio.write_clat_99%_us
3.259e+08 +13.4% 3.697e+08 fio.write_clat_mean_us
4.139e+08 +12.8% 4.669e+08 fio.write_clat_stddev
9311 -11.9% 8204 fio.write_iops
3522924 +13.1% 3983287 fio.write_slat_mean_us
75849924 +12.7% 85515624 fio.write_slat_stddev
31697 ? 2% -13.0% 27571 ? 3% meminfo.Active
23825 ? 3% -16.6% 19877 ? 4% meminfo.Active(file)
61.50 ? 4% -35.0% 40.00 ? 3% turbostat.CoreTmp
61.50 ? 4% -33.1% 41.12 ? 2% turbostat.PkgTmp
37215 -11.9% 32794 vmstat.io.bo
27622 ? 5% -13.6% 23864 ? 7% vmstat.system.cs
22698 ? 13% -25.3% 16954 ? 12% numa-meminfo.node0.Active
20334 ? 14% -27.0% 14846 ? 14% numa-meminfo.node0.Active(file)
307020 ? 8% -13.9% 264475 ? 5% numa-meminfo.node0.SUnreclaim
5083 ? 14% -27.0% 3712 ? 14% numa-vmstat.node0.nr_active_file
76759 ? 8% -13.8% 66128 ? 5% numa-vmstat.node0.nr_slab_unreclaimable
5083 ? 14% -27.0% 3712 ? 14% numa-vmstat.node0.nr_zone_active_file
27796 ? 5% -13.6% 24004 ? 7% perf-stat.i.context-switches
182627 ? 3% +9.1% 199237 ? 2% perf-stat.overall.path-length
27704 ? 5% -13.6% 23924 ? 7% perf-stat.ps.context-switches
5953 ? 3% -16.6% 4967 ? 4% proc-vmstat.nr_active_file
23114 -10.3% 20736 ? 3% proc-vmstat.nr_dirtied
8817 -1.2% 8709 proc-vmstat.nr_shmem
113287 -5.0% 107581 proc-vmstat.nr_slab_unreclaimable
5953 ? 3% -16.6% 4967 ? 4% proc-vmstat.nr_zone_active_file
915807 -1.7% 899903 proc-vmstat.numa_hit
828456 -1.9% 812632 proc-vmstat.numa_local
45186 -10.8% 40306 ? 3% proc-vmstat.pgactivate
11313643 -11.9% 9971313 proc-vmstat.pgpgout
17.75 ? 11% -3.1 14.64 ? 23% perf-profile.calltrace.cycles-pp.ret_from_fork
17.75 ? 11% -3.1 14.64 ? 23% perf-profile.calltrace.cycles-pp.kthread.ret_from_fork
17.55 ? 11% -3.1 14.45 ? 23% perf-profile.calltrace.cycles-pp.worker_thread.kthread.ret_from_fork
17.16 ? 11% -3.0 14.16 ? 23% perf-profile.calltrace.cycles-pp.process_one_work.worker_thread.kthread.ret_from_fork
16.21 ? 12% -2.9 13.30 ? 25% perf-profile.calltrace.cycles-pp.btrfs_work_helper.process_one_work.worker_thread.kthread.ret_from_fork
16.19 ? 12% -2.9 13.28 ? 25% perf-profile.calltrace.cycles-pp.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work.worker_thread.kthread
10.25 ? 12% -2.3 7.98 ? 25% perf-profile.calltrace.cycles-pp.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work.worker_thread
8.24 ? 13% -1.9 6.35 ? 26% perf-profile.calltrace.cycles-pp.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
6.47 ? 15% -1.6 4.91 ? 28% perf-profile.calltrace.cycles-pp.btrfs_lock_root_node.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper
6.45 ? 15% -1.6 4.90 ? 28% perf-profile.calltrace.cycles-pp.__btrfs_tree_lock.btrfs_lock_root_node.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io
6.35 ? 15% -1.5 4.82 ? 28% perf-profile.calltrace.cycles-pp.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_lock_root_node.btrfs_search_slot
6.41 ? 15% -1.5 4.88 ? 28% perf-profile.calltrace.cycles-pp.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_lock_root_node.btrfs_search_slot.btrfs_mark_extent_written
4.50 ? 14% -1.1 3.38 ? 29% perf-profile.calltrace.cycles-pp.osq_lock.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_lock_root_node
3.55 ? 53% -0.7 2.86 ? 19% perf-profile.calltrace.cycles-pp.poll_idle.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
4.78 ? 18% -0.6 4.16 ? 17% perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.fio_ioring_commit
4.90 ? 18% -0.6 4.29 ? 17% perf-profile.calltrace.cycles-pp.fio_ioring_commit
4.82 ? 18% -0.6 4.21 ? 17% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.fio_ioring_commit
4.70 ? 18% -0.6 4.10 ? 17% perf-profile.calltrace.cycles-pp.__do_sys_io_uring_enter.do_syscall_64.entry_SYSCALL_64_after_hwframe.fio_ioring_commit
4.63 ? 18% -0.6 4.04 ? 17% perf-profile.calltrace.cycles-pp.io_submit_sqes.__do_sys_io_uring_enter.do_syscall_64.entry_SYSCALL_64_after_hwframe.fio_ioring_commit
4.52 ? 19% -0.6 3.97 ? 17% perf-profile.calltrace.cycles-pp.io_write.io_issue_sqe.io_submit_sqes.__do_sys_io_uring_enter.do_syscall_64
4.55 ? 19% -0.6 4.00 ? 17% perf-profile.calltrace.cycles-pp.io_issue_sqe.io_submit_sqes.__do_sys_io_uring_enter.do_syscall_64.entry_SYSCALL_64_after_hwframe
4.37 ? 18% -0.5 3.82 ? 18% perf-profile.calltrace.cycles-pp.__iomap_dio_rw.btrfs_dio_write.btrfs_direct_write.btrfs_do_write_iter.io_write
4.38 ? 18% -0.5 3.83 ? 18% perf-profile.calltrace.cycles-pp.btrfs_dio_write.btrfs_direct_write.btrfs_do_write_iter.io_write.io_issue_sqe
4.45 ? 18% -0.5 3.92 ? 17% perf-profile.calltrace.cycles-pp.btrfs_do_write_iter.io_write.io_issue_sqe.io_submit_sqes.__do_sys_io_uring_enter
4.43 ? 18% -0.5 3.89 ? 17% perf-profile.calltrace.cycles-pp.btrfs_direct_write.btrfs_do_write_iter.io_write.io_issue_sqe.io_submit_sqes
4.12 ? 19% -0.4 3.70 ? 31% perf-profile.calltrace.cycles-pp.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work.worker_thread
0.92 ? 36% -0.4 0.51 ? 95% perf-profile.calltrace.cycles-pp.rwsem_spin_on_owner.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot
0.74 ? 14% -0.4 0.33 ?101% perf-profile.calltrace.cycles-pp.setup_items_for_insert.btrfs_duplicate_item.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper
0.67 ? 16% -0.3 0.32 ?101% perf-profile.calltrace.cycles-pp.__irq_exit_rcu.common_interrupt.asm_common_interrupt.cpuidle_enter_state.cpuidle_enter
0.67 ? 16% -0.3 0.32 ?101% perf-profile.calltrace.cycles-pp.__do_softirq.__irq_exit_rcu.common_interrupt.asm_common_interrupt.cpuidle_enter_state
3.02 ? 19% -0.3 2.67 ? 19% perf-profile.calltrace.cycles-pp.iomap_iter.__iomap_dio_rw.btrfs_dio_write.btrfs_direct_write.btrfs_do_write_iter
0.66 ? 16% -0.3 0.32 ?101% perf-profile.calltrace.cycles-pp.blk_complete_reqs.__do_softirq.__irq_exit_rcu.common_interrupt.asm_common_interrupt
0.66 ? 17% -0.3 0.32 ?101% perf-profile.calltrace.cycles-pp.scsi_io_completion.blk_complete_reqs.__do_softirq.__irq_exit_rcu.common_interrupt
0.66 ? 17% -0.3 0.32 ?101% perf-profile.calltrace.cycles-pp.scsi_end_request.scsi_io_completion.blk_complete_reqs.__do_softirq.__irq_exit_rcu
1.46 ? 20% -0.3 1.12 ? 28% perf-profile.calltrace.cycles-pp.rwsem_spin_on_owner.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_lock_root_node
2.98 ? 19% -0.3 2.65 ? 19% perf-profile.calltrace.cycles-pp.btrfs_dio_iomap_begin.iomap_iter.__iomap_dio_rw.btrfs_dio_write.btrfs_direct_write
0.75 ? 15% -0.3 0.44 ? 78% perf-profile.calltrace.cycles-pp.asm_common_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
0.75 ? 15% -0.3 0.44 ? 78% perf-profile.calltrace.cycles-pp.common_interrupt.asm_common_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
0.74 ? 13% -0.3 0.43 ? 80% perf-profile.calltrace.cycles-pp.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io
0.74 ? 13% -0.3 0.43 ? 80% perf-profile.calltrace.cycles-pp.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_mark_extent_written
2.06 ? 20% -0.3 1.78 ? 36% perf-profile.calltrace.cycles-pp.btrfs_lookup_csum.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
0.78 ? 14% -0.3 0.50 ? 64% perf-profile.calltrace.cycles-pp.btrfs_duplicate_item.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
2.02 ? 20% -0.3 1.74 ? 36% perf-profile.calltrace.cycles-pp.btrfs_search_slot.btrfs_lookup_csum.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper
2.62 ? 20% -0.3 2.35 ? 19% perf-profile.calltrace.cycles-pp.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin.iomap_iter.__iomap_dio_rw.btrfs_dio_write
0.76 ? 14% -0.3 0.51 ? 62% perf-profile.calltrace.cycles-pp.__btrfs_tree_lock.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper
1.23 ? 27% -0.2 0.98 ? 61% perf-profile.calltrace.cycles-pp.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_lookup_csum.btrfs_csum_file_blocks
1.21 ? 26% -0.2 0.97 ? 61% perf-profile.calltrace.cycles-pp.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_lookup_csum
0.54 ? 48% -0.2 0.30 ?101% perf-profile.calltrace.cycles-pp.blk_update_request.scsi_end_request.scsi_io_completion.blk_complete_reqs.__do_softirq
0.60 ? 56% -0.2 0.36 ? 78% perf-profile.calltrace.cycles-pp.csum_exist_in_range.can_nocow_file_extent.can_nocow_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin
0.37 ? 70% -0.2 0.14 ?173% perf-profile.calltrace.cycles-pp.btrfs_read_lock_root_node.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper
1.29 ? 30% -0.2 1.07 ? 48% perf-profile.calltrace.cycles-pp.__btrfs_tree_lock.btrfs_search_slot.btrfs_lookup_csum.btrfs_csum_file_blocks.btrfs_finish_ordered_io
0.44 ? 73% -0.2 0.23 ?129% perf-profile.calltrace.cycles-pp.find_busiest_group.load_balance.rebalance_domains.__do_softirq.__irq_exit_rcu
0.49 ? 78% -0.2 0.30 ?100% perf-profile.calltrace.cycles-pp.btrfs_lookup_csums_list.csum_exist_in_range.can_nocow_file_extent.can_nocow_extent.btrfs_get_blocks_direct_write
1.25 ? 20% -0.2 1.06 ? 18% perf-profile.calltrace.cycles-pp.iomap_dio_bio_iter.__iomap_dio_rw.btrfs_dio_write.btrfs_direct_write.btrfs_do_write_iter
0.19 ?223% -0.2 0.00 perf-profile.calltrace.cycles-pp.intel_idle_irq.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
0.41 ? 73% -0.2 0.22 ?130% perf-profile.calltrace.cycles-pp.update_sd_lb_stats.find_busiest_group.load_balance.rebalance_domains.__do_softirq
0.60 ? 56% -0.2 0.42 ?112% perf-profile.calltrace.cycles-pp.osq_lock.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot
0.17 ?141% -0.2 0.00 perf-profile.calltrace.cycles-pp.memcpy_extent_buffer.setup_items_for_insert.btrfs_duplicate_item.btrfs_mark_extent_written.btrfs_finish_ordered_io
1.84 ? 22% -0.2 1.67 ? 22% perf-profile.calltrace.cycles-pp.can_nocow_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin.iomap_iter.__iomap_dio_rw
1.28 ? 24% -0.2 1.12 ? 19% perf-profile.calltrace.cycles-pp.can_nocow_file_extent.can_nocow_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin.iomap_iter
0.38 ? 71% -0.2 0.22 ?130% perf-profile.calltrace.cycles-pp.__intel_pmu_enable_all.perf_rotate_context.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt
1.03 ? 21% -0.2 0.87 ? 18% perf-profile.calltrace.cycles-pp.btrfs_submit_direct.iomap_dio_bio_iter.__iomap_dio_rw.btrfs_dio_write.btrfs_direct_write
0.80 ? 26% -0.2 0.64 ? 64% perf-profile.calltrace.cycles-pp.btrfs_search_slot.btrfs_insert_empty_items.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper
0.14 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.btrfs_search_slot.btrfs_lookup_csums_list.csum_exist_in_range.can_nocow_file_extent.can_nocow_extent
0.50 ? 46% -0.1 0.36 ?101% perf-profile.calltrace.cycles-pp.btrfs_extend_item.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
1.13 ? 23% -0.1 0.98 ? 47% perf-profile.calltrace.cycles-pp.btrfs_insert_empty_items.btrfs_csum_file_blocks.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
0.14 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.asm_sysvec_apic_timer_interrupt.mwait_idle_with_hints.intel_idle_irq.cpuidle_enter_state.cpuidle_enter
0.19 ?142% -0.1 0.06 ?264% perf-profile.calltrace.cycles-pp.btrfs_csum_one_bio.btrfs_submit_direct.iomap_dio_bio_iter.__iomap_dio_rw.btrfs_dio_write
0.12 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.__btrfs_tree_lock.btrfs_search_slot.btrfs_insert_empty_items.btrfs_csum_file_blocks.btrfs_finish_ordered_io
0.12 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_insert_empty_items.btrfs_csum_file_blocks
0.11 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.rwsem_optimistic_spin.rwsem_down_write_slowpath.__btrfs_tree_lock.btrfs_search_slot.btrfs_insert_empty_items
0.18 ?141% -0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.__btrfs_tree_read_lock.btrfs_read_lock_root_node.btrfs_search_slot.btrfs_mark_extent_written.btrfs_finish_ordered_io
0.11 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.btrfs_del_items.btrfs_mark_extent_written.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
0.10 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.update_sg_lb_stats.update_sd_lb_stats.find_busiest_group.load_balance.rebalance_domains
0.09 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.mwait_idle_with_hints.intel_idle_irq.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
0.09 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.btrfs_submit_bio.btrfs_submit_direct.iomap_dio_bio_iter.__iomap_dio_rw.btrfs_dio_write
0.08 ?223% -0.1 0.00 perf-profile.calltrace.cycles-pp.native_sched_clock.sched_clock_cpu.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
0.32 ?103% -0.1 0.24 ?130% perf-profile.calltrace.cycles-pp.btrfs_create_dio_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin.iomap_iter.__iomap_dio_rw
0.26 ?100% -0.1 0.21 ?129% perf-profile.calltrace.cycles-pp.update_rq_clock.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer
0.17 ?141% -0.0 0.13 ?173% perf-profile.calltrace.cycles-pp.hrtimer_update_next_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.19 ?141% -0.0 0.16 ?175% perf-profile.calltrace.cycles-pp.btrfs_cross_ref_exist.can_nocow_file_extent.can_nocow_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin
1.41 ? 11% -0.0 1.38 ? 9% perf-profile.calltrace.cycles-pp.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
0.89 ? 15% -0.0 0.87 ? 12% perf-profile.calltrace.cycles-pp.perf_rotate_context.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
0.78 ? 14% -0.0 0.75 ? 9% perf-profile.calltrace.cycles-pp.arch_scale_freq_tick.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer
0.09 ?223% -0.0 0.07 ?264% perf-profile.calltrace.cycles-pp.timerqueue_add.enqueue_hrtimer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
1.34 ? 51% -0.0 1.32 ? 25% perf-profile.calltrace.cycles-pp.ktime_get.clockevents_program_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
0.68 ? 53% -0.0 0.66 ? 42% perf-profile.calltrace.cycles-pp.load_balance.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.64 ? 17% -0.0 0.63 ? 38% perf-profile.calltrace.cycles-pp.get_next_timer_interrupt.tick_nohz_next_event.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call
1.10 ? 19% -0.0 1.10 ? 11% perf-profile.calltrace.cycles-pp.lapic_next_deadline.clockevents_program_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
2.56 ? 34% +0.0 2.57 ? 16% perf-profile.calltrace.cycles-pp.clockevents_program_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.30 ?100% +0.0 0.31 ?100% perf-profile.calltrace.cycles-pp.update_blocked_averages.run_rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
1.16 ? 22% +0.0 1.18 ? 13% perf-profile.calltrace.cycles-pp.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.31 ?100% +0.0 0.33 ?100% perf-profile.calltrace.cycles-pp.run_rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.19 ?141% +0.0 0.22 ?129% perf-profile.calltrace.cycles-pp.hrtimer_next_event_without.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle
1.98 ? 5% +0.0 2.01 ? 9% perf-profile.calltrace.cycles-pp.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues
0.41 ? 72% +0.0 0.45 ? 79% perf-profile.calltrace.cycles-pp.cpuidle_governor_latency_req.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry
0.73 ? 18% +0.1 0.79 ? 40% perf-profile.calltrace.cycles-pp.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry.rest_init
0.00 +0.1 0.06 ?264% perf-profile.calltrace.cycles-pp.drm_atomic_helper_commit_tail_rpm.ast_mode_config_helper_atomic_commit_tail.commit_tail.drm_atomic_helper_commit.drm_atomic_commit
0.00 +0.1 0.06 ?264% perf-profile.calltrace.cycles-pp.btrfs_update_inode.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work.worker_thread
0.00 +0.1 0.06 ?264% perf-profile.calltrace.cycles-pp._raw_spin_trylock.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.commit_tail.drm_atomic_helper_commit.drm_atomic_commit.drm_atomic_helper_dirtyfb.drm_fbdev_fb_dirty
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.ast_mode_config_helper_atomic_commit_tail.commit_tail.drm_atomic_helper_commit.drm_atomic_commit.drm_atomic_helper_dirtyfb
0.63 ? 46% +0.1 0.70 ? 8% perf-profile.calltrace.cycles-pp.native_apic_msr_eoi_write.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.drm_atomic_commit.drm_atomic_helper_dirtyfb.drm_fbdev_fb_dirty.drm_fb_helper_damage_work.process_one_work
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.drm_atomic_helper_commit.drm_atomic_commit.drm_atomic_helper_dirtyfb.drm_fbdev_fb_dirty.drm_fb_helper_damage_work
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.drm_atomic_helper_dirtyfb.drm_fbdev_fb_dirty.drm_fb_helper_damage_work.process_one_work.worker_thread
0.81 ? 18% +0.1 0.88 ? 41% perf-profile.calltrace.cycles-pp.cpuidle_idle_call.do_idle.cpu_startup_entry.rest_init.arch_call_rest_init
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.btrfs_replace_extent_map_range.create_io_em.btrfs_create_dio_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.btrfs_inode_safe_disk_i_size_write.btrfs_finish_ordered_io.btrfs_work_helper
0.82 ? 18% +0.1 0.89 ? 41% perf-profile.calltrace.cycles-pp.cpu_startup_entry.rest_init.arch_call_rest_init.start_kernel.secondary_startup_64_no_verify
0.82 ? 18% +0.1 0.89 ? 41% perf-profile.calltrace.cycles-pp.start_kernel.secondary_startup_64_no_verify
0.82 ? 18% +0.1 0.89 ? 41% perf-profile.calltrace.cycles-pp.arch_call_rest_init.start_kernel.secondary_startup_64_no_verify
0.82 ? 18% +0.1 0.89 ? 41% perf-profile.calltrace.cycles-pp.rest_init.arch_call_rest_init.start_kernel.secondary_startup_64_no_verify
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.asm_sysvec_irq_work.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.sysvec_irq_work.asm_sysvec_irq_work.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.__sysvec_irq_work.sysvec_irq_work.asm_sysvec_irq_work.__do_softirq.__irq_exit_rcu
0.00 +0.1 0.07 ?264% perf-profile.calltrace.cycles-pp.irq_work_run.__sysvec_irq_work.sysvec_irq_work.asm_sysvec_irq_work.__do_softirq
0.82 ? 18% +0.1 0.89 ? 41% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.rest_init.arch_call_rest_init.start_kernel
0.00 +0.1 0.08 ?264% perf-profile.calltrace.cycles-pp.create_io_em.btrfs_create_dio_extent.btrfs_get_blocks_direct_write.btrfs_dio_iomap_begin.iomap_iter
0.00 +0.1 0.08 ?264% perf-profile.calltrace.cycles-pp._raw_spin_lock.btrfs_inode_safe_disk_i_size_write.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work
0.32 ?102% +0.1 0.41 ? 78% perf-profile.calltrace.cycles-pp.rcu_pending.rcu_sched_clock_irq.update_process_times.tick_sched_handle.tick_sched_timer
0.00 +0.1 0.08 ?264% perf-profile.calltrace.cycles-pp.btrfs_inode_safe_disk_i_size_write.btrfs_finish_ordered_io.btrfs_work_helper.process_one_work.worker_thread
0.20 ?141% +0.1 0.29 ?100% perf-profile.calltrace.cycles-pp.enqueue_hrtimer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
0.11 ?223% +0.1 0.20 ?129% perf-profile.calltrace.cycles-pp.sched_clock_cpu.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
2.72 ? 12% +0.1 2.83 ? 12% perf-profile.calltrace.cycles-pp.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
3.53 ? 12% +0.1 3.65 ? 17% perf-profile.calltrace.cycles-pp.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt
3.38 ? 9% +0.1 3.50 ? 12% perf-profile.calltrace.cycles-pp.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
0.56 ? 79% +0.1 0.69 ? 50% perf-profile.calltrace.cycles-pp.ktime_get.tick_nohz_irq_exit.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
0.08 ?223% +0.1 0.22 ?130% perf-profile.calltrace.cycles-pp.asm_sysvec_irq_work.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
0.08 ?223% +0.1 0.22 ?130% perf-profile.calltrace.cycles-pp.sysvec_irq_work.asm_sysvec_irq_work.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
0.08 ?223% +0.1 0.22 ?130% perf-profile.calltrace.cycles-pp.__sysvec_irq_work.sysvec_irq_work.asm_sysvec_irq_work.cpuidle_enter_state.cpuidle_enter
0.08 ?223% +0.1 0.22 ?130% perf-profile.calltrace.cycles-pp.irq_work_run.__sysvec_irq_work.sysvec_irq_work.asm_sysvec_irq_work.cpuidle_enter_state
3.81 ? 16% +0.2 3.96 ? 21% perf-profile.calltrace.cycles-pp.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
0.10 ?223% +0.2 0.26 ?100% perf-profile.calltrace.cycles-pp.ct_idle_exit.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
0.68 ? 87% +0.2 0.86 ? 66% perf-profile.calltrace.cycles-pp.timekeeping_max_deferment.tick_nohz_next_event.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call
7.06 ? 14% +0.2 7.25 ? 19% perf-profile.calltrace.cycles-pp.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.09 ?223% +0.2 0.28 ?100% perf-profile.calltrace.cycles-pp.drm_fb_helper_damage_work.process_one_work.worker_thread.kthread.ret_from_fork
0.09 ?223% +0.2 0.28 ?100% perf-profile.calltrace.cycles-pp.drm_fbdev_fb_dirty.drm_fb_helper_damage_work.process_one_work.worker_thread.kthread
2.59 ? 16% +0.2 2.79 ? 14% perf-profile.calltrace.cycles-pp.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry
4.39 ? 12% +0.2 4.59 ? 18% perf-profile.calltrace.cycles-pp.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
0.00 +0.2 0.21 ?129% perf-profile.calltrace.cycles-pp.note_gp_changes.rcu_core.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.00 +0.2 0.21 ?129% perf-profile.calltrace.cycles-pp.wait_for_lsr.serial8250_console_write.console_emit_next_record.console_flush_all.console_unlock
0.58 ? 77% +0.2 0.79 ? 30% perf-profile.calltrace.cycles-pp.tick_nohz_irq_exit.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.irq_work_run_list.irq_work_run.__sysvec_irq_work.sysvec_irq_work.asm_sysvec_irq_work
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.irq_work_single.irq_work_run_list.irq_work_run.__sysvec_irq_work.sysvec_irq_work
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp._printk.irq_work_single.irq_work_run_list.irq_work_run.__sysvec_irq_work
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.vprintk_emit._printk.irq_work_single.irq_work_run_list.irq_work_run
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.console_unlock.vprintk_emit._printk.irq_work_single.irq_work_run_list
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.console_flush_all.console_unlock.vprintk_emit._printk.irq_work_single
0.08 ?223% +0.2 0.29 ?100% perf-profile.calltrace.cycles-pp.console_emit_next_record.console_flush_all.console_unlock.vprintk_emit._printk
1.88 ? 20% +0.2 2.08 ? 23% perf-profile.calltrace.cycles-pp.tick_nohz_next_event.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle
0.36 ? 70% +0.2 0.59 ? 9% perf-profile.calltrace.cycles-pp.rcu_core.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.00 +0.3 0.29 ?100% perf-profile.calltrace.cycles-pp.serial8250_console_write.console_emit_next_record.console_flush_all.console_unlock.vprintk_emit
0.40 ?101% +0.3 0.71 ? 22% perf-profile.calltrace.cycles-pp.rcu_sched_clock_irq.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues
1.00 ? 41% +0.3 1.33 ? 55% perf-profile.calltrace.cycles-pp.tick_irq_enter.irq_enter_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
12.19 ? 3% +0.3 12.53 ? 11% perf-profile.calltrace.cycles-pp.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
1.07 ? 36% +0.3 1.42 ? 51% perf-profile.calltrace.cycles-pp.irq_enter_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
11.16 ? 4% +0.3 11.50 ? 13% perf-profile.calltrace.cycles-pp.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
0.22 ?143% +0.4 0.63 ? 43% perf-profile.calltrace.cycles-pp.ktime_get_update_offsets_now.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.39 ?110% +0.4 0.84 ? 87% perf-profile.calltrace.cycles-pp.ktime_get.tick_irq_enter.irq_enter_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
5.64 ? 15% +0.5 6.10 ? 7% perf-profile.calltrace.cycles-pp.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary
18.26 ? 5% +0.9 19.15 ? 13% perf-profile.calltrace.cycles-pp.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
23.90 ? 4% +1.2 25.14 ? 9% perf-profile.calltrace.cycles-pp.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
33.70 ? 6% +3.2 36.86 ? 5% perf-profile.calltrace.cycles-pp.mwait_idle_with_hints.intel_idle.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
34.03 ? 6% +3.2 37.21 ? 5% perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
64.80 ? 3% +3.2 67.99 ? 5% perf-profile.calltrace.cycles-pp.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry
65.46 ? 3% +3.3 68.82 ? 5% perf-profile.calltrace.cycles-pp.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary
74.07 ? 4% +3.7 77.82 ? 5% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
74.23 ? 4% +3.8 78.00 ? 5% perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64_no_verify
74.22 ? 4% +3.8 78.00 ? 5% perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
72.46 ? 4% +3.8 76.27 ? 5% perf-profile.calltrace.cycles-pp.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
75.05 ? 4% +3.9 78.95 ? 5% perf-profile.calltrace.cycles-pp.secondary_startup_64_no_verify



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.


--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests


Attachments:
(No filename) (33.88 kB)
config-6.2.0-rc8-00054-g4ae2edf12d49 (158.72 kB)
job-script (8.26 kB)
job.yaml (6.02 kB)
reproduce (740.00 B)
Download all attachments

2023-04-14 05:28:16

by Christoph Hellwig

[permalink] [raw]
Subject: Re: [linus:master] [btrfs] 4ae2edf12d: fio.write_iops -11.9% regression

On Fri, Apr 14, 2023 at 10:01:51AM +0800, kernel test robot wrote:
> Hello,
>
> kernel test robot noticed a -11.9% regression of fio.write_iops on:
>
> commit: 4ae2edf12d49fdbaea2dfda0bb2ec06501bd3493 ("btrfs: simplify parameters of btrfs_lookup_bio_sums")
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

Can you revalidate this? The patch is purely a parameter passing
cleanup, so a large reduction in IOPS looks very suspicious.

2023-04-14 08:27:36

by kernel test robot

[permalink] [raw]
Subject: Re: [linus:master] [btrfs] 4ae2edf12d: fio.write_iops -11.9% regression

On Fri, Apr 14, 2023 at 07:24:58AM +0200, Christoph Hellwig wrote:
> On Fri, Apr 14, 2023 at 10:01:51AM +0800, kernel test robot wrote:
> > Hello,
> >
> > kernel test robot noticed a -11.9% regression of fio.write_iops on:
> >
> > commit: 4ae2edf12d49fdbaea2dfda0bb2ec06501bd3493 ("btrfs: simplify parameters of btrfs_lookup_bio_sums")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
>
> Can you revalidate this? The patch is purely a parameter passing
> cleanup, so a large reduction in IOPS looks very suspicious.

Sorry this is a false positive report.

The environment was inconsistent when testing this commit and its
parent. We've revalidated under same environment and confirmed there is
no regression:

=========================================================================================
bs/compiler/cpufreq_governor/direct/disk/fs/ioengine/kconfig/nr_task/rootfs/runtime/rw/tbox_group/test_size/testcase:
4k/gcc-11/performance/direct/1HDD/btrfs/io_uring/x86_64-rhel-8.3/100%/debian-11.1-x86_64-20220510.cgz/300s/write/lkp-icl-2sp1/128G/fio-basic

commit:
5fa356531e33e ("btrfs: remove the direct I/O read checksum lookup optimization")
4ae2edf12d49f ("btrfs: simplify parameters of btrfs_lookup_bio_sums")

5fa356531e33e7c7 4ae2edf12d49fdbaea2dfda0bb2
---------------- ---------------------------
%stddev %change %stddev
\ | \
9370 -0.7% 9309 fio.write_iops


Sorry again for the inconvenience. We will improve our workflow to
reduce false positives.

--
Best Regards,
Yujie