[xfs] 79b54d9bfc: aim7.jobs-per-min -2.8% regression
by kernel test robot
Greeting,
FYI, we noticed a -2.8% regression of aim7.jobs-per-min due to commit:
commit: 79b54d9bfcdcd0a431bb3501013885f8f00cdb43 ("xfs: use bios directly to write log buffers")
https://kernel.googlesource.com/pub/scm/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: RAID1
fs: xfs
test: sync_disk_rw
load: 300
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/
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen(a)intel.com>
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.6/300/RAID1/debian-x86_64-2019-05-14.cgz/lkp-ivb-ep01/sync_disk_rw/aim7
commit:
2d15d2c0e0 ("xfs: make use of the l_targ field in struct xlog")
79b54d9bfc ("xfs: use bios directly to write log buffers")
2d15d2c0e0f7ecd6 79b54d9bfcdcd0a431bb3501013
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
3:4 -75% :4 dmesg.WARNING:at#for_ip_interrupt_entry/0x
%stddev %change %stddev
\ | \
3210 -2.8% 3120 aim7.jobs-per-min
560.76 +2.9% 576.86 aim7.time.elapsed_time
560.76 +2.9% 576.86 aim7.time.elapsed_time.max
4185708 -36.5% 2656308 aim7.time.involuntary_context_switches
44779 +13.8% 50970 ± 4% aim7.time.minor_page_faults
8008 +21.7% 9746 aim7.time.system_time
54284549 +1.5% 55104076 aim7.time.voluntary_context_switches
6546944 ± 8% -20.1% 5228544 ± 8% meminfo.DirectMap2M
1203 ± 32% +57.4% 1893 meminfo.Mlocked
656.50 ± 39% +55.1% 1018 ± 12% numa-meminfo.node0.Mlocked
545.00 ± 28% +60.5% 874.75 ± 14% numa-meminfo.node1.Mlocked
163.75 ± 39% +55.3% 254.25 ± 12% numa-vmstat.node0.nr_mlock
135.75 ± 28% +60.8% 218.25 ± 13% numa-vmstat.node1.nr_mlock
2880 ± 3% +8.9% 3135 ± 2% slabinfo.Acpi-Namespace.active_objs
2880 ± 3% +8.9% 3135 ± 2% slabinfo.Acpi-Namespace.num_objs
7.87 +1.3 9.17 ± 8% mpstat.cpu.all.idle%
52.24 -7.8 44.43 mpstat.cpu.all.iowait%
39.47 +6.5 45.98 mpstat.cpu.all.sys%
51.50 -15.5% 43.50 vmstat.cpu.wa
121621 -3.3% 117644 vmstat.io.bo
152.00 ± 2% -32.9% 102.00 ± 2% vmstat.procs.b
166223 -12.8% 144884 vmstat.system.cs
8.17 +15.8% 9.46 ± 8% iostat.cpu.idle
52.06 -14.9% 44.28 iostat.cpu.iowait
39.35 +16.5% 45.84 iostat.cpu.system
56478 -3.2% 54670 iostat.md0.w/s
121621 -3.3% 117591 iostat.md0.wkB/s
7.705e+09 -33.2% 5.143e+09 ± 15% cpuidle.C1.time
37185864 -38.0% 23064840 ± 15% cpuidle.C1.usage
3.847e+09 ± 2% +38.3% 5.319e+09 ± 11% cpuidle.C1E.time
13506915 +25.9% 16999001 ± 4% cpuidle.C1E.usage
6.22e+08 ± 16% +42.8% 8.885e+08 ± 17% cpuidle.C6.time
1502731 ± 30% +49.0% 2238626 ± 5% cpuidle.C6.usage
14436 -2.4% 14096 proc-vmstat.nr_kernel_stack
300.00 ± 33% +57.8% 473.25 proc-vmstat.nr_mlock
8177 +2.1% 8350 proc-vmstat.nr_zone_write_pending
28750 +21.4% 34895 ± 5% proc-vmstat.numa_hint_faults
19128 +18.0% 22570 ± 8% proc-vmstat.numa_hint_faults_local
5515 ± 8% +40.7% 7758 ± 17% proc-vmstat.numa_pages_migrated
31200 ± 6% +49.3% 46570 ± 31% proc-vmstat.numa_pte_updates
5829999 -3.9% 5599986 proc-vmstat.pgalloc_normal
1453272 +3.7% 1506462 proc-vmstat.pgfault
5598375 -4.3% 5355258 proc-vmstat.pgfree
5515 ± 8% +40.7% 7758 ± 17% proc-vmstat.pgmigrate_success
519.25 +13.1% 587.25 turbostat.Avg_MHz
43.24 +5.6 48.87 turbostat.Busy%
37178210 -38.0% 23057179 ± 15% turbostat.C1
34.26 -12.1 22.11 ± 15% turbostat.C1%
13506740 +25.9% 16998768 ± 4% turbostat.C1E
17.10 +5.8 22.91 ± 12% turbostat.C1E%
1498986 ± 31% +49.1% 2234353 ± 5% turbostat.C6
2.76 ± 16% +1.1 3.82 ± 18% turbostat.C6%
55.25 -11.1% 49.13 turbostat.CPU%c1
0.94 ± 7% +51.6% 1.42 ± 26% turbostat.CPU%c6
57.75 ± 2% +3.9% 60.00 ± 3% turbostat.PkgTmp
15.66 ± 2% -6.2% 14.69 ± 3% perf-stat.i.MPKI
1.312e+09 +7.3% 1.408e+09 perf-stat.i.branch-instructions
85566446 -2.1% 83741795 perf-stat.i.cache-references
166943 -12.9% 145469 perf-stat.i.context-switches
3.62 +6.5% 3.85 perf-stat.i.cpi
2.037e+10 +13.2% 2.306e+10 perf-stat.i.cpu-cycles
14929 +13.3% 16911 perf-stat.i.cpu-migrations
1151 +15.9% 1334 perf-stat.i.cycles-between-cache-misses
1.516e+09 +6.1% 1.609e+09 perf-stat.i.dTLB-loads
5.031e+08 -4.5% 4.807e+08 perf-stat.i.dTLB-stores
446380 -7.5% 413106 ± 2% perf-stat.i.iTLB-loads
5.724e+09 +6.5% 6.098e+09 perf-stat.i.instructions
1814 +8.6% 1970 ± 2% perf-stat.i.instructions-per-iTLB-miss
0.28 -5.6% 0.26 perf-stat.i.ipc
6126990 -4.1% 5875615 perf-stat.i.node-load-misses
7052743 -3.9% 6776675 perf-stat.i.node-loads
14.95 -8.1% 13.73 perf-stat.overall.MPKI
3.56 +6.2% 3.78 perf-stat.overall.cpi
1151 +15.6% 1331 perf-stat.overall.cycles-between-cache-misses
1812 +7.8% 1953 ± 2% perf-stat.overall.instructions-per-iTLB-miss
0.28 -5.9% 0.26 perf-stat.overall.ipc
1.31e+09 +7.3% 1.405e+09 perf-stat.ps.branch-instructions
85412963 -2.1% 83596915 perf-stat.ps.cache-references
166644 -12.9% 145217 perf-stat.ps.context-switches
2.033e+10 +13.2% 2.302e+10 perf-stat.ps.cpu-cycles
14902 +13.3% 16882 perf-stat.ps.cpu-migrations
1.513e+09 +6.1% 1.606e+09 perf-stat.ps.dTLB-loads
5.022e+08 -4.5% 4.798e+08 perf-stat.ps.dTLB-stores
445580 -7.4% 412389 ± 2% perf-stat.ps.iTLB-loads
5.714e+09 +6.6% 6.088e+09 perf-stat.ps.instructions
6116017 -4.1% 5865466 perf-stat.ps.node-load-misses
7040111 -3.9% 6764971 perf-stat.ps.node-loads
3.208e+12 +10.1% 3.53e+12 perf-stat.total.instructions
106009 +16.2% 123235 sched_debug.cfs_rq:/.exec_clock.avg
107819 +17.6% 126771 sched_debug.cfs_rq:/.exec_clock.max
105443 +16.4% 122706 sched_debug.cfs_rq:/.exec_clock.min
406.56 ± 30% +51.5% 616.03 ± 8% sched_debug.cfs_rq:/.exec_clock.stddev
667.46 ± 4% +32.9% 887.07 ± 3% sched_debug.cfs_rq:/.load_avg.avg
5478 ± 12% +30.0% 7120 ± 4% sched_debug.cfs_rq:/.load_avg.max
1231 ± 11% +30.1% 1603 ± 4% sched_debug.cfs_rq:/.load_avg.stddev
2240608 +24.6% 2791499 sched_debug.cfs_rq:/.min_vruntime.avg
2276805 +24.4% 2831917 sched_debug.cfs_rq:/.min_vruntime.max
2211580 +25.0% 2763664 sched_debug.cfs_rq:/.min_vruntime.min
0.35 ± 4% +20.3% 0.42 ± 7% sched_debug.cfs_rq:/.nr_running.avg
0.65 ± 12% +23.3% 0.80 ± 7% sched_debug.cfs_rq:/.nr_spread_over.avg
0.02 ± 82% -88.9% 0.00 ±173% sched_debug.cfs_rq:/.spread.avg
0.65 ± 82% -88.9% 0.07 ±173% sched_debug.cfs_rq:/.spread.max
0.10 ± 82% -88.9% 0.01 ±173% sched_debug.cfs_rq:/.spread.stddev
453.33 +13.1% 512.68 sched_debug.cfs_rq:/.util_avg.avg
54.96 ± 12% +28.7% 70.71 ± 10% sched_debug.cfs_rq:/.util_est_enqueued.avg
133762 ± 27% +67.3% 223845 ± 7% sched_debug.cpu.avg_idle.min
176517 ± 5% -27.7% 127615 ± 6% sched_debug.cpu.avg_idle.stddev
45.82 ± 20% +48.7% 68.15 ± 17% sched_debug.cpu.cpu_load[1].avg
0.08 ± 57% +766.7% 0.65 ± 41% sched_debug.cpu.cpu_load[1].min
180.41 ± 21% +42.2% 256.56 ± 19% sched_debug.cpu.cpu_load[1].stddev
50.85 ± 17% +47.1% 74.78 ± 11% sched_debug.cpu.cpu_load[2].avg
1064 ± 15% +40.8% 1499 ± 13% sched_debug.cpu.cpu_load[2].max
0.95 ± 36% +286.8% 3.67 ± 12% sched_debug.cpu.cpu_load[2].min
182.31 ± 16% +43.2% 261.03 ± 14% sched_debug.cpu.cpu_load[2].stddev
54.75 ± 14% +37.4% 75.24 ± 8% sched_debug.cpu.cpu_load[3].avg
2.70 ± 2% +147.2% 6.67 sched_debug.cpu.cpu_load[3].min
172.59 ± 15% +32.8% 229.19 ± 13% sched_debug.cpu.cpu_load[3].stddev
55.56 ± 11% +34.3% 74.62 ± 5% sched_debug.cpu.cpu_load[4].avg
818.43 ± 15% +25.5% 1027 ± 9% sched_debug.cpu.cpu_load[4].max
3.68 ± 16% +149.0% 9.15 ± 4% sched_debug.cpu.cpu_load[4].min
149.46 ± 14% +27.7% 190.91 ± 7% sched_debug.cpu.cpu_load[4].stddev
786.26 ± 6% +22.5% 963.52 ± 6% sched_debug.cpu.curr->pid.avg
0.58 ± 9% +36.8% 0.80 ± 10% sched_debug.cpu.nr_running.avg
1.07 ± 6% +17.7% 1.26 ± 8% sched_debug.cpu.nr_running.stddev
1109136 -12.7% 968119 sched_debug.cpu.nr_switches.avg
1136593 -12.5% 995035 sched_debug.cpu.nr_switches.max
1084891 -13.2% 941961 sched_debug.cpu.nr_switches.min
1108298 -12.7% 966993 sched_debug.cpu.sched_count.avg
1134353 -12.7% 990115 sched_debug.cpu.sched_count.max
1084183 -13.1% 941989 sched_debug.cpu.sched_count.min
363169 -26.0% 268783 sched_debug.cpu.sched_goidle.avg
370264 -25.8% 274814 sched_debug.cpu.sched_goidle.max
356698 -26.4% 262531 sched_debug.cpu.sched_goidle.min
54790 -31.1% 37767 sched_debug.cpu.ttwu_local.avg
58890 -30.2% 41086 sched_debug.cpu.ttwu_local.max
50991 -32.5% 34406 sched_debug.cpu.ttwu_local.min
2893 ± 3% -23.4% 2216 ± 7% sched_debug.cpu.ttwu_local.stddev
614.75 ± 5% -33.4% 409.25 ± 24% interrupts.40:IR-PCI-MSI.524290-edge.eth0-TxRx-1
202670 ± 2% +4.0% 210754 ± 2% interrupts.CAL:Function_call_interrupts
1180 ± 66% -78.4% 255.25 ±167% interrupts.CPU0.NMI:Non-maskable_interrupts
1180 ± 66% -78.4% 255.25 ±167% interrupts.CPU0.PMI:Performance_monitoring_interrupts
280939 +33.1% 373920 interrupts.CPU0.RES:Rescheduling_interrupts
276566 +29.8% 358849 interrupts.CPU1.RES:Rescheduling_interrupts
4780 ± 6% +17.2% 5603 ± 3% interrupts.CPU10.CAL:Function_call_interrupts
280074 +33.1% 372754 interrupts.CPU10.RES:Rescheduling_interrupts
275727 +29.6% 357377 interrupts.CPU11.RES:Rescheduling_interrupts
279558 +33.0% 371728 interrupts.CPU12.RES:Rescheduling_interrupts
4951 ± 5% +15.8% 5733 ± 5% interrupts.CPU13.CAL:Function_call_interrupts
228.75 ±172% +540.0% 1464 ± 32% interrupts.CPU13.NMI:Non-maskable_interrupts
228.75 ±172% +540.0% 1464 ± 32% interrupts.CPU13.PMI:Performance_monitoring_interrupts
274475 +29.7% 356099 interrupts.CPU13.RES:Rescheduling_interrupts
279541 +33.3% 372530 interrupts.CPU14.RES:Rescheduling_interrupts
274190 +30.1% 356589 interrupts.CPU15.RES:Rescheduling_interrupts
161.00 ± 6% +18.8% 191.25 ± 2% interrupts.CPU15.TLB:TLB_shootdowns
280230 +32.8% 372098 interrupts.CPU16.RES:Rescheduling_interrupts
274564 +29.9% 356548 interrupts.CPU17.RES:Rescheduling_interrupts
4726 ± 4% +15.0% 5433 ± 7% interrupts.CPU18.CAL:Function_call_interrupts
281353 +32.5% 372837 interrupts.CPU18.RES:Rescheduling_interrupts
275881 +29.8% 358162 interrupts.CPU19.RES:Rescheduling_interrupts
279855 +33.4% 373407 interrupts.CPU2.RES:Rescheduling_interrupts
279868 +33.2% 372868 interrupts.CPU20.RES:Rescheduling_interrupts
275194 +29.9% 357364 interrupts.CPU21.RES:Rescheduling_interrupts
279996 +33.1% 372750 interrupts.CPU22.RES:Rescheduling_interrupts
4813 ± 3% +11.0% 5343 ± 5% interrupts.CPU23.CAL:Function_call_interrupts
274267 +30.1% 356824 interrupts.CPU23.RES:Rescheduling_interrupts
147.25 ± 6% +23.1% 181.25 ± 12% interrupts.CPU23.TLB:TLB_shootdowns
280417 +32.8% 372408 interrupts.CPU24.RES:Rescheduling_interrupts
274998 +29.7% 356596 interrupts.CPU25.RES:Rescheduling_interrupts
279837 +33.1% 372572 interrupts.CPU26.RES:Rescheduling_interrupts
274653 +29.9% 356815 interrupts.CPU27.RES:Rescheduling_interrupts
280411 +33.5% 374295 interrupts.CPU28.RES:Rescheduling_interrupts
1346 ± 32% -81.5% 249.25 ±172% interrupts.CPU29.NMI:Non-maskable_interrupts
1346 ± 32% -81.5% 249.25 ±172% interrupts.CPU29.PMI:Performance_monitoring_interrupts
275415 +30.1% 358211 interrupts.CPU29.RES:Rescheduling_interrupts
275415 +29.8% 357414 interrupts.CPU3.RES:Rescheduling_interrupts
280591 +33.4% 374339 interrupts.CPU30.RES:Rescheduling_interrupts
275173 +30.1% 357888 interrupts.CPU31.RES:Rescheduling_interrupts
614.75 ± 5% -33.4% 409.25 ± 24% interrupts.CPU32.40:IR-PCI-MSI.524290-edge.eth0-TxRx-1
279946 +33.2% 373008 interrupts.CPU32.RES:Rescheduling_interrupts
183.50 ± 6% -12.9% 159.75 ± 8% interrupts.CPU32.TLB:TLB_shootdowns
274555 +30.1% 357231 interrupts.CPU33.RES:Rescheduling_interrupts
279591 +33.4% 372975 interrupts.CPU34.RES:Rescheduling_interrupts
274826 +29.7% 356522 interrupts.CPU35.RES:Rescheduling_interrupts
279964 +33.1% 372728 interrupts.CPU36.RES:Rescheduling_interrupts
274751 +30.0% 357304 interrupts.CPU37.RES:Rescheduling_interrupts
280687 +33.4% 374361 interrupts.CPU38.RES:Rescheduling_interrupts
275349 +29.9% 357769 interrupts.CPU39.RES:Rescheduling_interrupts
279879 +33.3% 372946 interrupts.CPU4.RES:Rescheduling_interrupts
275474 +29.2% 356034 interrupts.CPU5.RES:Rescheduling_interrupts
279870 +33.4% 373364 interrupts.CPU6.RES:Rescheduling_interrupts
275249 +29.9% 357679 interrupts.CPU7.RES:Rescheduling_interrupts
280669 +33.2% 373808 interrupts.CPU8.RES:Rescheduling_interrupts
4951 ± 8% +12.1% 5552 ± 7% interrupts.CPU9.CAL:Function_call_interrupts
232.25 ±173% +423.8% 1216 ± 65% interrupts.CPU9.NMI:Non-maskable_interrupts
232.25 ±173% +423.8% 1216 ± 65% interrupts.CPU9.PMI:Performance_monitoring_interrupts
275277 +30.0% 357736 interrupts.CPU9.RES:Rescheduling_interrupts
11105289 +31.5% 14606722 interrupts.RES:Rescheduling_interrupts
19.07 -9.6 9.44 perf-profile.calltrace.cycles-pp.file_write_and_wait_range.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write.vfs_write
17.30 -9.2 8.05 perf-profile.calltrace.cycles-pp.__filemap_fdatawrite_range.file_write_and_wait_range.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
17.26 -9.2 8.02 perf-profile.calltrace.cycles-pp.do_writepages.__filemap_fdatawrite_range.file_write_and_wait_range.xfs_file_fsync.xfs_file_buffered_aio_write
17.24 -9.2 8.01 perf-profile.calltrace.cycles-pp.xfs_vm_writepages.do_writepages.__filemap_fdatawrite_range.file_write_and_wait_range.xfs_file_fsync
34.15 -9.2 24.92 perf-profile.calltrace.cycles-pp.raid1_make_request.md_handle_request.md_make_request.generic_make_request.submit_bio
16.31 -9.1 7.18 perf-profile.calltrace.cycles-pp.xfs_submit_ioend.xfs_vm_writepages.do_writepages.__filemap_fdatawrite_range.file_write_and_wait_range
16.18 -9.1 7.05 perf-profile.calltrace.cycles-pp.md_make_request.generic_make_request.submit_bio.xfs_submit_ioend.xfs_vm_writepages
16.29 -9.1 7.16 perf-profile.calltrace.cycles-pp.generic_make_request.submit_bio.xfs_submit_ioend.xfs_vm_writepages.do_writepages
16.29 -9.1 7.17 perf-profile.calltrace.cycles-pp.submit_bio.xfs_submit_ioend.xfs_vm_writepages.do_writepages.__filemap_fdatawrite_range
16.09 -9.1 6.98 perf-profile.calltrace.cycles-pp.md_handle_request.md_make_request.generic_make_request.submit_bio.xfs_submit_ioend
15.94 -9.1 6.85 perf-profile.calltrace.cycles-pp.raid1_write_request.raid1_make_request.md_handle_request.md_make_request.generic_make_request
7.56 -7.6 0.00 perf-profile.calltrace.cycles-pp.prepare_to_wait_event.raid1_write_request.raid1_make_request.md_handle_request.md_make_request
7.40 -7.4 0.00 perf-profile.calltrace.cycles-pp._raw_spin_lock_irqsave.prepare_to_wait_event.raid1_write_request.raid1_make_request.md_handle_request
7.38 -7.4 0.00 perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock_irqsave.prepare_to_wait_event.raid1_write_request.raid1_make_request
22.34 -7.1 15.21 ± 3% perf-profile.calltrace.cycles-pp.secondary_startup_64
21.41 ± 3% -6.4 15.06 ± 4% perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64
21.41 ± 3% -6.4 15.06 ± 4% perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64
21.39 ± 3% -6.4 15.04 ± 4% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
17.70 ± 3% -5.5 12.23 ± 3% perf-profile.calltrace.cycles-pp.cpuidle_enter.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
17.55 ± 3% -5.4 12.13 ± 4% perf-profile.calltrace.cycles-pp.cpuidle_enter_state.cpuidle_enter.do_idle.cpu_startup_entry.start_secondary
15.22 -5.2 10.05 perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.cpuidle_enter.do_idle.cpu_startup_entry
17.28 -3.0 14.30 perf-profile.calltrace.cycles-pp.__xfs_log_force_lsn.xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
17.62 -3.0 14.67 perf-profile.calltrace.cycles-pp.xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write.vfs_write
14.99 -2.5 12.45 ± 2% perf-profile.calltrace.cycles-pp._raw_spin_lock_irqsave.remove_wait_queue.__xfs_log_force_lsn.xfs_log_force_lsn.xfs_file_fsync
14.95 -2.5 12.41 ± 2% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock_irqsave.remove_wait_queue.__xfs_log_force_lsn.xfs_log_force_lsn
15.04 -2.5 12.51 ± 2% perf-profile.calltrace.cycles-pp.remove_wait_queue.__xfs_log_force_lsn.xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write
3.66 ± 3% -0.6 3.07 ± 6% perf-profile.calltrace.cycles-pp.raid1d.md_thread.kthread.ret_from_fork
3.65 ± 3% -0.6 3.07 ± 6% perf-profile.calltrace.cycles-pp.flush_pending_writes.raid1d.md_thread.kthread.ret_from_fork
3.65 ± 3% -0.6 3.07 ± 6% perf-profile.calltrace.cycles-pp.flush_bio_list.flush_pending_writes.raid1d.md_thread.kthread
3.66 ± 3% -0.6 3.08 ± 6% perf-profile.calltrace.cycles-pp.md_thread.kthread.ret_from_fork
6.76 ± 4% -0.6 6.20 ± 2% perf-profile.calltrace.cycles-pp.ret_from_fork
6.76 ± 4% -0.6 6.20 ± 2% perf-profile.calltrace.cycles-pp.kthread.ret_from_fork
3.52 ± 3% -0.6 2.97 ± 6% perf-profile.calltrace.cycles-pp.generic_make_request.flush_bio_list.flush_pending_writes.raid1d.md_thread
3.35 ± 3% -0.5 2.81 ± 6% perf-profile.calltrace.cycles-pp.brd_make_request.generic_make_request.flush_bio_list.flush_pending_writes.raid1d
1.85 ± 5% -0.5 1.34 ± 8% perf-profile.calltrace.cycles-pp.raid1_end_write_request.brd_make_request.generic_make_request.flush_bio_list.flush_pending_writes
1.51 ± 6% -0.5 1.03 ± 10% perf-profile.calltrace.cycles-pp.raid_end_bio_io.raid1_end_write_request.brd_make_request.generic_make_request.flush_bio_list
5.27 ± 2% -0.5 4.79 ± 2% perf-profile.calltrace.cycles-pp._raw_spin_lock_irqsave.raid1_write_request.raid1_make_request.md_handle_request.md_make_request
5.11 ± 2% -0.4 4.66 perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock_irqsave.raid1_write_request.raid1_make_request.md_handle_request
1.69 ± 5% -0.4 1.28 ± 10% perf-profile.calltrace.cycles-pp.apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.do_idle.cpu_startup_entry
1.68 ± 6% -0.4 1.31 ± 4% perf-profile.calltrace.cycles-pp.__filemap_fdatawait_range.file_write_and_wait_range.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
1.55 ± 6% -0.4 1.19 ± 9% perf-profile.calltrace.cycles-pp.smp_apic_timer_interrupt.apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.do_idle
1.54 ± 7% -0.3 1.20 ± 4% perf-profile.calltrace.cycles-pp.wait_on_page_bit.__filemap_fdatawait_range.file_write_and_wait_range.xfs_file_fsync.xfs_file_buffered_aio_write
1.11 ± 6% -0.3 0.79 ± 8% perf-profile.calltrace.cycles-pp.menu_select.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
1.42 ± 8% -0.3 1.11 ± 5% perf-profile.calltrace.cycles-pp.io_schedule.wait_on_page_bit.__filemap_fdatawait_range.file_write_and_wait_range.xfs_file_fsync
1.40 ± 8% -0.3 1.10 ± 5% perf-profile.calltrace.cycles-pp.schedule.io_schedule.wait_on_page_bit.__filemap_fdatawait_range.file_write_and_wait_range
1.39 ± 8% -0.3 1.09 ± 5% perf-profile.calltrace.cycles-pp.__schedule.schedule.io_schedule.wait_on_page_bit.__filemap_fdatawait_range
1.28 ± 8% -0.3 1.02 ± 4% perf-profile.calltrace.cycles-pp.sched_ttwu_pending.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
1.12 ± 11% -0.2 0.88 ± 4% perf-profile.calltrace.cycles-pp.activate_task.ttwu_do_activate.sched_ttwu_pending.do_idle.cpu_startup_entry
1.12 ± 11% -0.2 0.88 ± 4% perf-profile.calltrace.cycles-pp.enqueue_task_fair.activate_task.ttwu_do_activate.sched_ttwu_pending.do_idle
1.12 ± 11% -0.2 0.88 ± 4% perf-profile.calltrace.cycles-pp.ttwu_do_activate.sched_ttwu_pending.do_idle.cpu_startup_entry.start_secondary
0.94 ± 6% -0.2 0.69 ± 14% perf-profile.calltrace.cycles-pp.hrtimer_interrupt.smp_apic_timer_interrupt.apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
1.07 ± 11% -0.2 0.83 ± 4% perf-profile.calltrace.cycles-pp.enqueue_entity.enqueue_task_fair.activate_task.ttwu_do_activate.sched_ttwu_pending
0.64 ± 2% -0.2 0.41 ± 58% perf-profile.calltrace.cycles-pp.try_to_wake_up.autoremove_wake_function.__wake_up_common.__wake_up_common_lock.md_submit_flush_data
0.77 ± 12% -0.2 0.56 ± 7% perf-profile.calltrace.cycles-pp.__account_scheduler_latency.enqueue_entity.enqueue_task_fair.activate_task.ttwu_do_activate
0.71 ± 5% -0.1 0.56 ± 5% perf-profile.calltrace.cycles-pp.schedule_idle.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
0.69 ± 5% -0.1 0.55 ± 5% perf-profile.calltrace.cycles-pp.__schedule.schedule_idle.do_idle.cpu_startup_entry.start_secondary
0.68 ± 5% -0.1 0.56 ± 5% perf-profile.calltrace.cycles-pp.schedule.md_flush_request.raid1_make_request.md_handle_request.md_make_request
0.67 ± 5% -0.1 0.55 ± 5% perf-profile.calltrace.cycles-pp.__schedule.schedule.md_flush_request.raid1_make_request.md_handle_request
0.68 ± 2% -0.1 0.56 ± 5% perf-profile.calltrace.cycles-pp.__wake_up_common.__wake_up_common_lock.md_submit_flush_data.process_one_work.worker_thread
0.67 ± 2% -0.1 0.55 ± 6% perf-profile.calltrace.cycles-pp.autoremove_wake_function.__wake_up_common.__wake_up_common_lock.md_submit_flush_data.process_one_work
0.82 ± 2% -0.1 0.71 ± 6% perf-profile.calltrace.cycles-pp.md_submit_flush_data.process_one_work.worker_thread.kthread.ret_from_fork
0.82 ± 3% -0.1 0.71 ± 6% perf-profile.calltrace.cycles-pp.__wake_up_common_lock.md_submit_flush_data.process_one_work.worker_thread.kthread
0.00 +0.5 0.54 ± 4% perf-profile.calltrace.cycles-pp.__wake_up_common_lock.xlog_state_done_syncing.xlog_ioend_work.process_one_work.worker_thread
0.00 +0.6 0.60 ± 9% perf-profile.calltrace.cycles-pp.pick_next_task_fair.__schedule.schedule.__xfs_log_force_lsn.xfs_file_fsync
0.00 +0.7 0.73 ± 3% perf-profile.calltrace.cycles-pp.try_to_wake_up.__wake_up_common.__wake_up_common_lock.xlog_state_do_callback.xlog_ioend_work
0.00 +0.8 0.76 ± 2% perf-profile.calltrace.cycles-pp.__wake_up_common.__wake_up_common_lock.xlog_state_do_callback.xlog_ioend_work.process_one_work
0.00 +0.8 0.78 ± 6% perf-profile.calltrace.cycles-pp.xlog_state_done_syncing.xlog_ioend_work.process_one_work.worker_thread.kthread
0.00 +0.8 0.78 ± 2% perf-profile.calltrace.cycles-pp.__wake_up_common_lock.xlog_state_do_callback.xlog_ioend_work.process_one_work.worker_thread
0.00 +1.0 0.97 perf-profile.calltrace.cycles-pp.xlog_state_do_callback.xlog_ioend_work.process_one_work.worker_thread.kthread
0.00 +1.0 0.99 ± 6% perf-profile.calltrace.cycles-pp.__schedule.schedule.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write
0.00 +1.0 1.00 ± 6% perf-profile.calltrace.cycles-pp.schedule.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
0.00 +1.7 1.75 ± 2% perf-profile.calltrace.cycles-pp.xlog_ioend_work.process_one_work.worker_thread.kthread.ret_from_fork
3.68 ± 8% +6.7 10.38 ± 4% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock_irqsave.remove_wait_queue.__xfs_log_force_lsn.xfs_file_fsync
3.69 ± 8% +6.7 10.40 ± 4% perf-profile.calltrace.cycles-pp._raw_spin_lock_irqsave.remove_wait_queue.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write
3.71 ± 8% +6.7 10.44 ± 4% perf-profile.calltrace.cycles-pp.remove_wait_queue.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
69.70 +7.7 77.37 perf-profile.calltrace.cycles-pp.write
69.14 +7.7 76.85 perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.write
69.12 +7.7 76.83 perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.write
68.92 +7.7 76.64 perf-profile.calltrace.cycles-pp.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe.write
68.89 +7.7 76.61 perf-profile.calltrace.cycles-pp.vfs_write.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe.write
68.67 +7.7 76.41 perf-profile.calltrace.cycles-pp.new_sync_write.vfs_write.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe
68.54 +7.7 76.28 perf-profile.calltrace.cycles-pp.xfs_file_buffered_aio_write.new_sync_write.vfs_write.ksys_write.do_syscall_64
65.52 +8.0 73.49 perf-profile.calltrace.cycles-pp.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write.vfs_write.ksys_write
5.67 ± 3% +13.1 18.75 ± 3% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write
5.69 ± 3% +13.1 18.80 ± 3% perf-profile.calltrace.cycles-pp._raw_spin_lock.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write
9.94 +20.8 30.78 ± 3% perf-profile.calltrace.cycles-pp.__xfs_log_force_lsn.xfs_file_fsync.xfs_file_buffered_aio_write.new_sync_write.vfs_write
38.37 -10.0 28.40 perf-profile.children.cycles-pp.generic_make_request
19.07 -9.6 9.45 perf-profile.children.cycles-pp.file_write_and_wait_range
34.80 -9.4 25.44 perf-profile.children.cycles-pp.submit_bio
34.55 -9.3 25.20 perf-profile.children.cycles-pp.md_make_request
34.42 -9.3 25.09 perf-profile.children.cycles-pp.md_handle_request
34.31 -9.3 25.00 perf-profile.children.cycles-pp.raid1_make_request
17.30 -9.2 8.05 perf-profile.children.cycles-pp.__filemap_fdatawrite_range
17.26 -9.2 8.03 perf-profile.children.cycles-pp.do_writepages
17.24 -9.2 8.01 perf-profile.children.cycles-pp.xfs_vm_writepages
16.01 -9.1 6.88 perf-profile.children.cycles-pp.raid1_write_request
16.31 -9.1 7.18 perf-profile.children.cycles-pp.xfs_submit_ioend
8.13 -7.7 0.45 ± 8% perf-profile.children.cycles-pp.prepare_to_wait_event
22.35 -7.1 15.21 ± 3% perf-profile.children.cycles-pp.do_idle
22.34 -7.1 15.21 ± 3% perf-profile.children.cycles-pp.secondary_startup_64
22.34 -7.1 15.21 ± 3% perf-profile.children.cycles-pp.cpu_startup_entry
21.41 ± 3% -6.4 15.06 ± 4% perf-profile.children.cycles-pp.start_secondary
18.46 -6.1 12.34 ± 3% perf-profile.children.cycles-pp.cpuidle_enter
18.45 -6.1 12.34 ± 3% perf-profile.children.cycles-pp.cpuidle_enter_state
15.35 -5.2 10.15 perf-profile.children.cycles-pp.intel_idle
33.52 -4.4 29.15 perf-profile.children.cycles-pp._raw_spin_lock_irqsave
17.62 -3.0 14.67 perf-profile.children.cycles-pp.xfs_log_force_lsn
3.72 ± 3% -0.7 3.07 ± 6% perf-profile.children.cycles-pp.flush_bio_list
3.41 ± 3% -0.6 2.81 ± 6% perf-profile.children.cycles-pp.brd_make_request
3.66 ± 3% -0.6 3.07 ± 6% perf-profile.children.cycles-pp.raid1d
1.79 ± 5% -0.6 1.20 ± 4% perf-profile.children.cycles-pp.autoremove_wake_function
3.65 ± 3% -0.6 3.07 ± 6% perf-profile.children.cycles-pp.flush_pending_writes
3.66 ± 3% -0.6 3.08 ± 6% perf-profile.children.cycles-pp.md_thread
6.76 ± 4% -0.6 6.20 ± 2% perf-profile.children.cycles-pp.kthread
6.76 ± 4% -0.6 6.21 ± 2% perf-profile.children.cycles-pp.ret_from_fork
1.86 ± 5% -0.5 1.34 ± 8% perf-profile.children.cycles-pp.raid1_end_write_request
1.52 ± 6% -0.5 1.03 ± 10% perf-profile.children.cycles-pp.raid_end_bio_io
2.65 ± 3% -0.4 2.23 ± 5% perf-profile.children.cycles-pp.__wake_up_common_lock
2.83 -0.4 2.43 ± 2% perf-profile.children.cycles-pp.apic_timer_interrupt
0.67 ± 5% -0.4 0.28 ± 11% perf-profile.children.cycles-pp.finish_wait
4.44 ± 3% -0.4 4.04 ± 2% perf-profile.children.cycles-pp.__schedule
1.68 ± 6% -0.4 1.32 ± 3% perf-profile.children.cycles-pp.__filemap_fdatawait_range
1.17 ± 7% -0.4 0.81 ± 8% perf-profile.children.cycles-pp.menu_select
1.54 ± 7% -0.3 1.20 ± 4% perf-profile.children.cycles-pp.wait_on_page_bit
2.57 ± 2% -0.3 2.24 ± 3% perf-profile.children.cycles-pp.smp_apic_timer_interrupt
1.42 ± 8% -0.3 1.11 ± 5% perf-profile.children.cycles-pp.io_schedule
2.91 ± 3% -0.3 2.64 ± 2% perf-profile.children.cycles-pp.try_to_wake_up
1.37 ± 10% -0.2 1.13 ± 3% perf-profile.children.cycles-pp._raw_spin_unlock_irqrestore
2.87 ± 3% -0.2 2.63 ± 2% perf-profile.children.cycles-pp.__wake_up_common
1.70 -0.2 1.52 ± 6% perf-profile.children.cycles-pp.hrtimer_interrupt
0.74 ± 3% -0.2 0.57 ± 5% perf-profile.children.cycles-pp.schedule_idle
0.55 ± 7% -0.2 0.39 ± 10% perf-profile.children.cycles-pp.tick_nohz_get_sleep_length
1.28 ± 4% -0.1 1.13 ± 5% perf-profile.children.cycles-pp.unwind_next_frame
2.01 ± 4% -0.1 1.87 ± 3% perf-profile.children.cycles-pp.arch_stack_walk
0.55 ± 11% -0.1 0.41 ± 7% perf-profile.children.cycles-pp.ktime_get
0.27 ± 38% -0.1 0.14 ± 18% perf-profile.children.cycles-pp.finish_task_switch
0.25 ± 5% -0.1 0.12 ± 23% perf-profile.children.cycles-pp.xlog_state_release_iclog
0.73 ± 9% -0.1 0.61 ± 4% perf-profile.children.cycles-pp.dequeue_entity
0.82 ± 2% -0.1 0.71 ± 6% perf-profile.children.cycles-pp.md_submit_flush_data
0.40 ± 12% -0.1 0.29 ± 6% perf-profile.children.cycles-pp.tick_nohz_next_event
1.11 ± 2% -0.1 1.01 ± 6% perf-profile.children.cycles-pp.__hrtimer_run_queues
0.51 ± 6% -0.1 0.40 ± 5% perf-profile.children.cycles-pp.bio_alloc_bioset
0.21 ± 10% -0.1 0.11 ± 13% perf-profile.children.cycles-pp.queue_work_on
0.20 ± 12% -0.1 0.11 ± 14% perf-profile.children.cycles-pp.__queue_work
0.32 ± 15% -0.1 0.23 ± 5% perf-profile.children.cycles-pp.get_next_timer_interrupt
0.44 ± 4% -0.1 0.35 ± 8% perf-profile.children.cycles-pp.__orc_find
0.69 ± 6% -0.1 0.60 ± 9% perf-profile.children.cycles-pp.irq_exit
0.49 ± 8% -0.1 0.41 ± 5% perf-profile.children.cycles-pp.orc_find
0.39 ± 7% -0.1 0.31 ± 12% perf-profile.children.cycles-pp.clockevents_program_event
0.33 ± 8% -0.1 0.25 ± 12% perf-profile.children.cycles-pp.update_rq_clock
0.30 ± 9% -0.1 0.23 ± 14% perf-profile.children.cycles-pp.read_tsc
0.24 ± 9% -0.1 0.17 ± 2% perf-profile.children.cycles-pp.__test_set_page_writeback
0.21 ± 10% -0.1 0.14 ± 13% perf-profile.children.cycles-pp._cond_resched
0.22 ± 14% -0.1 0.16 ± 13% perf-profile.children.cycles-pp.__next_timer_interrupt
0.12 ± 17% -0.1 0.06 ± 65% perf-profile.children.cycles-pp.irq_enter
0.25 ± 11% -0.1 0.19 ± 8% perf-profile.children.cycles-pp.sched_clock
0.12 ± 6% -0.1 0.07 ± 17% perf-profile.children.cycles-pp.submit_flushes
0.28 ± 9% -0.1 0.22 ± 11% perf-profile.children.cycles-pp.sched_clock_cpu
0.22 ± 8% -0.1 0.17 ± 8% perf-profile.children.cycles-pp.__list_del_entry_valid
0.27 ± 10% -0.1 0.22 ± 3% perf-profile.children.cycles-pp.iomap_write_end
0.23 ± 7% -0.0 0.19 ± 9% perf-profile.children.cycles-pp.native_sched_clock
0.14 ± 6% -0.0 0.09 ± 23% perf-profile.children.cycles-pp.xfs_ilock
0.11 ± 12% -0.0 0.07 ± 19% perf-profile.children.cycles-pp.preempt_schedule_common
0.10 ± 8% -0.0 0.07 ± 16% perf-profile.children.cycles-pp.wait_for_completion_io
0.09 ± 13% -0.0 0.06 ± 9% perf-profile.children.cycles-pp.tick_nohz_idle_exit
0.09 ± 14% -0.0 0.06 ± 6% perf-profile.children.cycles-pp.sb_mark_inode_writeback
0.23 ± 7% -0.0 0.20 ± 2% perf-profile.children.cycles-pp.update_blocked_averages
0.10 ± 10% -0.0 0.08 ± 8% perf-profile.children.cycles-pp.bio_endio
0.15 ± 4% -0.0 0.13 ± 6% perf-profile.children.cycles-pp.__switch_to
0.08 ± 10% -0.0 0.06 ± 11% perf-profile.children.cycles-pp.timerqueue_del
0.14 ± 11% +0.0 0.18 ± 8% perf-profile.children.cycles-pp.task_tick_fair
0.43 ± 8% +0.0 0.48 ± 4% perf-profile.children.cycles-pp.select_idle_sibling
0.31 +0.0 0.35 ± 6% perf-profile.children.cycles-pp.__kernel_text_address
0.34 +0.1 0.39 ± 5% perf-profile.children.cycles-pp.unwind_get_return_address
0.04 ± 57% +0.1 0.10 ± 17% perf-profile.children.cycles-pp.add_wait_queue_exclusive
1.05 ± 6% +0.3 1.33 perf-profile.children.cycles-pp.scheduler_ipi
1.12 ± 6% +0.3 1.41 ± 2% perf-profile.children.cycles-pp.reschedule_interrupt
0.45 ± 8% +0.3 0.78 ± 6% perf-profile.children.cycles-pp.xlog_state_done_syncing
0.00 +1.7 1.75 ± 2% perf-profile.children.cycles-pp.xlog_ioend_work
18.75 +4.2 22.95 perf-profile.children.cycles-pp.remove_wait_queue
69.75 +7.7 77.41 perf-profile.children.cycles-pp.write
68.92 +7.7 76.64 perf-profile.children.cycles-pp.ksys_write
68.89 +7.7 76.61 perf-profile.children.cycles-pp.vfs_write
68.67 +7.7 76.41 perf-profile.children.cycles-pp.new_sync_write
68.54 +7.7 76.29 perf-profile.children.cycles-pp.xfs_file_buffered_aio_write
69.66 +7.9 77.53 perf-profile.children.cycles-pp.entry_SYSCALL_64_after_hwframe
69.63 +7.9 77.50 perf-profile.children.cycles-pp.do_syscall_64
65.52 +8.0 73.49 perf-profile.children.cycles-pp.xfs_file_fsync
55.57 +9.0 64.55 perf-profile.children.cycles-pp.native_queued_spin_lock_slowpath
7.55 ± 4% +13.0 20.57 ± 3% perf-profile.children.cycles-pp._raw_spin_lock
27.21 +17.9 45.08 perf-profile.children.cycles-pp.__xfs_log_force_lsn
15.33 -5.2 10.12 perf-profile.self.cycles-pp.intel_idle
0.80 ± 8% -0.2 0.64 ± 6% perf-profile.self.cycles-pp._raw_spin_lock_irqsave
0.50 ± 8% -0.2 0.35 ± 9% perf-profile.self.cycles-pp.menu_select
0.44 ± 4% -0.1 0.35 ± 7% perf-profile.self.cycles-pp.__orc_find
0.29 ± 6% -0.1 0.21 ± 11% perf-profile.self.cycles-pp._raw_spin_unlock_irqrestore
0.29 ± 9% -0.1 0.21 ± 23% perf-profile.self.cycles-pp.try_to_wake_up
0.29 ± 11% -0.1 0.22 ± 15% perf-profile.self.cycles-pp.read_tsc
0.22 ± 15% -0.1 0.16 ± 20% perf-profile.self.cycles-pp.cpuidle_enter_state
0.09 ± 10% -0.1 0.03 ±100% perf-profile.self.cycles-pp.finish_task_switch
0.22 ± 8% -0.1 0.16 ± 9% perf-profile.self.cycles-pp.update_rq_clock
0.13 ± 14% -0.1 0.07 ± 24% perf-profile.self.cycles-pp.dequeue_entity
0.23 ± 6% -0.1 0.17 ± 8% perf-profile.self.cycles-pp.native_sched_clock
0.17 ± 12% -0.1 0.12 ± 9% perf-profile.self.cycles-pp.do_idle
0.21 ± 10% -0.0 0.17 ± 10% perf-profile.self.cycles-pp.__list_del_entry_valid
0.20 ± 8% -0.0 0.15 ± 14% perf-profile.self.cycles-pp._raw_spin_lock_irq
0.17 ± 11% -0.0 0.12 ± 12% perf-profile.self.cycles-pp.bio_alloc_bioset
0.15 ± 7% -0.0 0.10 ± 25% perf-profile.self.cycles-pp.brd_lookup_page
0.11 ± 15% -0.0 0.07 ± 22% perf-profile.self.cycles-pp.md_flush_request
0.07 ± 6% -0.0 0.03 ±100% perf-profile.self.cycles-pp.bio_associate_blkg_from_css
0.09 ± 24% -0.0 0.06 ± 26% perf-profile.self.cycles-pp.md_make_request
0.07 ± 6% -0.0 0.04 ± 58% perf-profile.self.cycles-pp.stack_access_ok
0.10 ± 15% -0.0 0.08 ± 14% perf-profile.self.cycles-pp.write
0.15 ± 8% -0.0 0.13 ± 10% perf-profile.self.cycles-pp.orc_find
0.15 ± 5% -0.0 0.12 ± 6% perf-profile.self.cycles-pp.__switch_to
0.08 ± 10% -0.0 0.06 ± 11% perf-profile.self.cycles-pp.flush_bio_list
0.05 ± 62% +0.0 0.09 ± 12% perf-profile.self.cycles-pp.xlog_cil_force_lsn
0.01 ±173% +0.0 0.06 ± 9% perf-profile.self.cycles-pp.check_preempt_curr
55.36 +8.6 63.92 perf-profile.self.cycles-pp.native_queued_spin_lock_slowpath
aim7.jobs-per-min
3500 +-+------------------------------------------------------------------+
| +..+.+ +..+.O.+.+.+..+.+.+.+..+.O.+.O..+.+.+.+.O..O.+.+.+..+.+.|
3000 +-O O O O O O O O O O O O O O O O O O O O O |
| : : : |
2500 +-+ : : : |
|: : : : |
2000 +-+: : : |
|: : : : |
1500 +-+: : : |
|: : : : |
1000 +-+: : : |
| : : |
500 +-+ : |
| : : |
0 O-+------------------------------------------------O-----------------+
aim7.time.system_time
10000 +-+----O-O-O-O-O--O-O-O-O-O--O-O-O-O-O-O--O-O-O-O----O-O-O-O--------+
9000 +-O O |
| |
8000 +-+ +..+.+ +.+..+.+.+.+.+..+.+.+.+.+.+..+.+.+.+.+..+.+.+.+.+..+.+.|
7000 +-+ : : : |
| : : : |
6000 +-+: : : |
5000 +-+: : : |
4000 +-+: : : |
|: : : : |
3000 +-+: : : |
2000 +-+: : : |
| : : |
1000 +-+ : |
0 O-+-----------------------------------------------O-----------------+
aim7.time.involuntary_context_switches
4.5e+06 +-+---------------------------------------------------------------+
| +.+..+ +.+.+.+.+.+..+.+.+.+.+.+.+.+..+.+.+.+.+.+.+.+..+.+.+.|
4e+06 +-+ : : : |
3.5e+06 +-+ : : : |
| : : : |
3e+06 +-+: : : |
2.5e+06 +-O:O O O:O:O O O O O O O O O O O O O O O O O O O O O |
|: : : : |
2e+06 +-+: : : |
1.5e+06 +-+: : : |
|: : : : |
1e+06 +-+ : |
500000 +-+ : |
| : : |
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,
Rong Chen
1 year, 4 months
[KVM] 323d73a8ec: kernel_selftests.kvm.vmx_set_nested_state_test.fail
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: 323d73a8ecad22bf3284f11112a7cce576ade6af ("KVM: nVMX: Change KVM_STATE_NESTED_EVMCS to signal vmcs12 is copied from eVMCS")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/torvalds/linux.git master
in testcase: kernel_selftests
with following parameters:
group: kselftests-01
test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
test-url: https://www.kernel.org/doc/Documentation/kselftest.txt
on test machine: 8 threads Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz with 16G memory
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen(a)intel.com>
# selftests: kvm: vmx_set_nested_state_test
# ==== Test Assertion Failure ====
# lib/kvm_util.c:1277: ret == 0
# pid=12810 tid=12810 - Invalid argument
# 1 0x0000000000403624: vcpu_nested_state_set at kvm_util.c:1275
# 2 0x0000000000401197: test_nested_state at vmx_set_nested_state_test.c:32
# 3 0x0000000000401562: test_vmx_nested_state at vmx_set_nested_state_test.c:151
# 4 0x000000000040100f: main at vmx_set_nested_state_test.c:283
# 5 0x00007efdc57f409a: ?? ??:0
# 6 0x0000000000401099: _start at ??:?
# KVM_SET_NESTED_STATE failed, ret: -1 errno: 22
not ok 12 selftests: kvm: vmx_set_nested_state_test
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
Thanks,
Rong Chen
1 year, 4 months
[printk] 6d74d467b2: BUG:sleeping_function_called_from_invalid_context_at_kernel/printk/printk.c
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: 6d74d467b29ceae9bc6cb6625b38029b53dc4fe2 ("printk: redirect emit/store to new ringbuffer")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/bigeasy/staging.git next-RT
in testcase: rcutorture
with following parameters:
runtime: 300s
test: cpuhotplug
torture_type: srcud
test-description: rcutorture is rcutorture kernel module load/unload test.
test-url: https://www.kernel.org/doc/Documentation/RCU/torture.txt
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-----------------------------------------------------------------------------+------------+------------+
| | 706ce957bb | 6d74d467b2 |
+-----------------------------------------------------------------------------+------------+------------+
| boot_successes | 14 | 0 |
| boot_failures | 0 | 16 |
| BUG:sleeping_function_called_from_invalid_context_at_kernel/printk/printk.c | 0 | 16 |
+-----------------------------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <lkp(a)intel.com>
[ 10.034125] BUG: sleeping function called from invalid context at kernel/printk/printk.c:2312
[ 10.034128] in_atomic(): 1, irqs_disabled(): 0, pid: 176, name: printk
[ 10.034131] CPU: 1 PID: 176 Comm: printk Tainted: G E 5.3.0-rc4-next-20190814-00010-g6d74d467b29ce #1
[ 10.034134] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 10.034135] Call Trace:
[ 10.034187] dump_stack+0x5c/0x7b
[ 10.034198] ___might_sleep+0xf1/0x110
[ 10.034205] console_conditional_schedule+0x24/0x30
[ 10.034210] fbcon_redraw+0x96/0x1c0
[ 10.034216] ? fbcon_cursor+0x100/0x190
[ 10.034219] fbcon_scroll+0x556/0xd70
[ 10.034221] con_scroll+0x147/0x1e0
[ 10.034225] lf+0x9e/0xb0
[ 10.034228] vt_console_print+0x253/0x3d0
[ 10.034231] printk_kthread_func+0x1d5/0x3b0
[ 10.034239] ? register_console+0x370/0x370
[ 10.034241] kthread+0x11e/0x140
[ 10.034252] ? kthread_park+0xa0/0xa0
[ 10.034255] ret_from_fork+0x35/0x40
[ 10.034410] srcud-torture: Creating rcu_torture_fakewriter task
[ 10.034448] srcud-torture: rcu_torture_fakewriter task started
[ 10.034462] srcud-torture: Creating rcu_torture_fakewriter task
[ 10.034486] srcud-torture: rcu_torture_fakewriter task started
[ 10.034499] srcud-torture: Creating rcu_torture_reader task
[ 10.034524] srcud-torture: rcu_torture_fakewriter task started
[ 10.034535] srcud-torture: Creating rcu_torture_stats task
[ 10.034559] srcud-torture: rcu_torture_reader task started
[ 10.035276] srcud-torture: Creating torture_shuffle task
[ 10.035305] srcud-torture: rcu_torture_stats task started
[ 10.035317] srcud-torture: Creating torture_stutter task
[ 10.035343] srcud-torture: torture_shuffle task started
[ 10.035354] srcud-torture: Creating torture_onoff task
[ 10.035375] srcud-torture: torture_stutter task started
[ 10.035746] srcud-torture: torture_onoff task started
[ 10.035748] srcud-torture: torture_onoff begin holdoff
[ 10.580020] 2019-08-17 14:30:20 modprobe rcutorture onoff_interval=3 onoff_holdoff=30 torture_type=srcud
[ 10.580020] 2019-08-17 14:30:20 sleep 300
Linux version 5.3.0-rc4-next-20190814-00010-g6d74d467b29ce #1
Command line: ip=::::vm-snb-4G-b8323c36aad9::dhcp root=/dev/ram0 user=lkp job=/lkp/jobs/scheduled/vm-snb-4G-b8323c36aad9/rcutorture-300s-cpuhotplug-srcud-yocto-minimal-i386-2019-05-20.cgz-6-20190817-3200-1ve3ns3-1.yaml ARCH=x86_64 kconfig=x86_64-fedora-25 branch=bigeasy-staging/next-RT commit=6d74d467b29ceae9bc6cb6625b38029b53dc4fe2 BOOT_IMAGE=/pkg/linux/x86_64-fedora-25/gcc-7/6d74d467b29ceae9bc6cb6625b38029b53dc4fe2/vmlinuz-5.3.0-rc4-next-20190814-00010-g6d74d467b29ce rcutorture.fwd_progress=0 max_uptime=1500 RESULT_ROOT=/result/rcutorture/300s-cpuhotplug-srcud/vm-snb-4G/yocto-minimal-i386-2019-05-20.cgz/x86_64-fedora-25/gcc-7/6d74d467b29ceae9bc6cb6625b38029b53dc4fe2/3 LKP_SERVER=inn debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 net.ifnames=0 printk.devkmsg=on panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 drbd.minor_count=8 systemd.log_level=err ignore_loglevel console=tty0 earlyprintk=ttyS0,115200 console=ttyS0,115200 vga=normal rw rcuperf.shutdown=0
Elapsed time: 20
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-0 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-1 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-2 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-3 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-4 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-5 256G
qemu-img create -f qcow2 disk-vm-snb-4G-b8323c36aad9-6 256G
kvm=(
qemu-system-x86_64
-enable-kvm
-cpu SandyBridge
-kernel $kernel
-initrd initrd-vm-snb-4G-b8323c36aad9
-m 4096
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0,hostfwd=tcp::32032-:22
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-drive file=disk-vm-snb-4G-b8323c36aad9-0,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-1,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-2,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-3,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-4,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-5,media=disk,if=virtio
-drive file=disk-vm-snb-4G-b8323c36aad9-6,media=disk,if=virtio
-serial stdio
-display none
-monitor null
)
append=(
ip=::::vm-snb-4G-b8323c36aad9::dhcp
root=/dev/ram0
user=lkp
job=/job-script
ARCH=x86_64
kconfig=x86_64-fedora-25
branch=bigeasy-staging/next-RT
commit=6d74d467b29ceae9bc6cb6625b38029b53dc4fe2
BOOT_IMAGE=/pkg/linux/x86_64-fedora-25/gcc-7/6d74d467b29ceae9bc6cb6625b38029b53dc4fe2/vmlinuz-5.3.0-rc4-next-20190814-00010-g6d74d467b29ce
rcutorture.fwd_progress=0
max_uptime=1500
RESULT_ROOT=/result/rcutorture/300s-cpuhotplug-srcud/vm-snb-4G/yocto-minimal-i386-2019-05-20.cgz/x86_64-fedora-25/gcc-7/6d74d467b29ceae9bc6cb6625b38029b53dc4fe2/3
result_service=tmpfs
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
To reproduce:
# build kernel
cd linux
cp config-5.3.0-rc4-next-20190814-00010-g6d74d467b29ce .config
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
lkp
1 year, 4 months
[x86/speculation] a17888154c: will-it-scale.per_thread_ops 26.3% improvement
by kernel test robot
Greeting,
FYI, we noticed a 26.3% improvement of will-it-scale.per_thread_ops due to commit:
commit: a17888154cf202ccf05d2efb71ed0f632f2d8897 ("x86/speculation: Prepare for conditional IBPB in switch_mm()")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/stable/linux-sta... linux-4.19.y
in testcase: will-it-scale
on test machine: 288 threads Intel(R) Xeon Phi(TM) CPU 7295 @ 1.50GHz with 80G memory
with following parameters:
nr_task: 100%
mode: thread
test: lock1
cpufreq_governor: performance
test-description: Will It Scale takes a testcase and runs it from 1 through to n parallel copies to see if the testcase will scale. It builds both a process and threads based test in order to see any differences between the two.
test-url: https://github.com/antonblanchard/will-it-scale
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/kconfig/mode/nr_task/rootfs/tbox_group/test/testcase:
gcc-7/performance/x86_64-rhel-7.6/thread/100%/debian-x86_64-2019-05-14.cgz/lkp-knm01/lock1/will-it-scale
commit:
dd73e15ea2 ("x86/speculation: Avoid __switch_to_xtra() calls")
a17888154c ("x86/speculation: Prepare for conditional IBPB in switch_mm()")
dd73e15ea21307f5 a17888154cf202ccf05d2efb71e
---------------- ---------------------------
%stddev %change %stddev
\ | \
4087 ± 2% +26.3% 5163 will-it-scale.per_thread_ops
473.30 ± 8% +43.5% 679.18 ± 5% will-it-scale.time.user_time
1177292 ± 2% +26.3% 1487098 will-it-scale.workload
286106 ± 30% +45.8% 417095 ± 8% cpuidle.C6.usage
0.00 ± 22% +0.0 0.00 ± 7% mpstat.cpu.all.soft%
0.65 ± 8% +0.2 0.89 ± 5% mpstat.cpu.all.usr%
129743 ± 57% +119.2% 284405 ± 9% turbostat.C6
1.90 ± 2% +29.7% 2.46 turbostat.RAMWatt
53407 ± 49% -35.2% 34627 ± 36% sched_debug.cfs_rq:/.MIN_vruntime.avg
15380679 ± 49% -47.9% 8016795 ± 3% sched_debug.cfs_rq:/.MIN_vruntime.max
904763 ± 49% -42.9% 516186 ± 18% sched_debug.cfs_rq:/.MIN_vruntime.stddev
1480 ± 10% -30.2% 1033 ± 6% sched_debug.cfs_rq:/.exec_clock.stddev
53407 ± 49% -35.2% 34627 ± 36% sched_debug.cfs_rq:/.max_vruntime.avg
15380679 ± 49% -47.9% 8016795 ± 3% sched_debug.cfs_rq:/.max_vruntime.max
904763 ± 49% -42.9% 516186 ± 18% sched_debug.cfs_rq:/.max_vruntime.stddev
790547 ± 2% -19.2% 638979 ± 4% sched_debug.cfs_rq:/.min_vruntime.stddev
317232 ± 19% +83.0% 580571 ± 39% sched_debug.cfs_rq:/.spread0.avg
614655 ± 8% +42.9% 878296 ± 26% sched_debug.cfs_rq:/.spread0.max
972.20 ± 9% -16.5% 811.40 ± 12% sched_debug.cfs_rq:/.util_est_enqueued.max
1300 ± 11% -38.9% 794.23 ± 2% sched_debug.cpu.clock.stddev
1300 ± 11% -38.9% 794.23 ± 2% sched_debug.cpu.clock_task.stddev
415370 ± 19% -28.5% 296908 ± 24% sched_debug.cpu.load.max
0.00 ± 11% -39.0% 0.00 ± 2% sched_debug.cpu.next_balance.stddev
87.20 ± 3% -9.7% 78.75 sched_debug.cpu.sched_count.min
0.96 ± 2% +0.1 1.08 perf-stat.i.branch-miss-rate%
81540515 ± 3% +16.3% 94797570 perf-stat.i.branch-misses
38822692 +4.9% 40736129 perf-stat.i.cache-misses
1.735e+08 ± 2% +6.8% 1.853e+08 perf-stat.i.cache-references
11306 -4.6% 10789 perf-stat.i.cycles-between-cache-misses
0.20 ± 5% +0.0 0.22 perf-stat.i.iTLB-load-miss-rate%
68601028 ± 6% +15.2% 79001841 perf-stat.i.iTLB-load-misses
510.28 ± 5% -10.9% 454.52 perf-stat.i.instructions-per-iTLB-miss
0.96 ± 2% +0.1 1.08 perf-stat.overall.branch-miss-rate%
11294 -4.5% 10782 perf-stat.overall.cycles-between-cache-misses
0.20 ± 5% +0.0 0.22 perf-stat.overall.iTLB-load-miss-rate%
510.16 ± 5% -10.9% 454.48 perf-stat.overall.instructions-per-iTLB-miss
8926043 ± 2% -18.4% 7286569 perf-stat.overall.path-length
81245950 ± 3% +16.3% 94455444 perf-stat.ps.branch-misses
38684989 +4.9% 40592042 perf-stat.ps.cache-misses
1.729e+08 ± 2% +6.8% 1.847e+08 perf-stat.ps.cache-references
68352742 ± 6% +15.2% 78716460 perf-stat.ps.iTLB-load-misses
135356 ± 10% -18.5% 110367 ± 9% softirqs.CPU103.TIMER
131702 ± 10% -15.2% 111681 ± 8% softirqs.CPU113.TIMER
131026 ± 14% -14.4% 112100 ± 7% softirqs.CPU116.TIMER
123745 ± 10% -10.9% 110198 ± 6% softirqs.CPU121.TIMER
133939 ± 14% -14.1% 115090 ± 7% softirqs.CPU124.TIMER
134228 ± 9% -12.2% 117851 ± 4% softirqs.CPU130.TIMER
129713 ± 12% -15.4% 109742 ± 10% softirqs.CPU139.TIMER
130778 ± 11% -14.6% 111633 ± 8% softirqs.CPU142.TIMER
137792 ± 7% -13.3% 119519 ± 12% softirqs.CPU145.TIMER
141170 ± 14% -23.2% 108480 ± 6% softirqs.CPU146.TIMER
127476 ± 16% -17.7% 104892 ± 4% softirqs.CPU148.TIMER
137275 ± 12% -14.4% 117489 ± 8% softirqs.CPU151.TIMER
129712 ± 12% -14.4% 111075 ± 9% softirqs.CPU155.TIMER
132127 ± 9% -11.7% 116693 ± 8% softirqs.CPU158.TIMER
134777 ± 12% -14.3% 115516 ± 8% softirqs.CPU164.TIMER
132913 ± 11% -14.2% 114070 ± 9% softirqs.CPU165.TIMER
131646 ± 8% -15.6% 111099 ± 10% softirqs.CPU171.TIMER
136165 ± 9% -13.9% 117217 ± 8% softirqs.CPU174.TIMER
147401 ± 13% -20.9% 116578 ± 5% softirqs.CPU178.TIMER
123830 ± 12% -11.4% 109655 ± 8% softirqs.CPU187.TIMER
133199 ± 7% -10.7% 118914 ± 5% softirqs.CPU192.TIMER
124858 ± 6% -7.7% 115234 ± 4% softirqs.CPU195.TIMER
129571 ± 8% -12.3% 113597 ± 6% softirqs.CPU200.TIMER
133620 ± 7% -11.7% 117993 ± 7% softirqs.CPU218.TIMER
136197 ± 10% -13.6% 117731 ± 9% softirqs.CPU219.TIMER
136701 ± 9% -14.3% 117127 ± 4% softirqs.CPU220.TIMER
133887 ± 8% -15.7% 112900 ± 6% softirqs.CPU222.TIMER
129124 ± 7% -14.5% 110385 ± 4% softirqs.CPU235.TIMER
136383 ± 8% -16.5% 113834 ± 8% softirqs.CPU242.TIMER
132180 ± 9% -12.5% 115706 ± 5% softirqs.CPU243.TIMER
130946 ± 12% -14.4% 112121 ± 7% softirqs.CPU246.TIMER
130677 ± 9% -13.3% 113233 ± 9% softirqs.CPU251.TIMER
129249 ± 10% -11.7% 114064 ± 8% softirqs.CPU257.TIMER
132340 ± 8% -13.3% 114727 ± 6% softirqs.CPU264.TIMER
138405 ± 9% -17.9% 113609 ± 9% softirqs.CPU268.TIMER
136635 ± 9% -14.6% 116621 ± 9% softirqs.CPU270.TIMER
128757 ± 17% -24.1% 97715 ± 2% softirqs.CPU30.TIMER
127524 ± 10% -11.2% 113182 ± 8% softirqs.CPU82.TIMER
133218 ± 10% -11.7% 117674 ± 8% softirqs.CPU89.TIMER
130174 ± 11% -15.1% 110526 ± 7% softirqs.CPU91.TIMER
139469 ± 11% -17.4% 115196 ± 10% softirqs.CPU93.TIMER
95.69 -1.0 94.69 perf-profile.calltrace.cycles-pp._raw_spin_lock.fcntl_setlk.do_fcntl.__x64_sys_fcntl.do_syscall_64
95.80 -1.0 94.84 perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.fcntl_setlk.do_fcntl.__x64_sys_fcntl
97.76 -0.4 97.37 perf-profile.calltrace.cycles-pp.fcntl_setlk.do_fcntl.__x64_sys_fcntl.do_syscall_64.entry_SYSCALL_64_after_hwframe
98.02 -0.3 97.70 perf-profile.calltrace.cycles-pp.do_fcntl.__x64_sys_fcntl.do_syscall_64.entry_SYSCALL_64_after_hwframe.do_fcntl
0.80 ± 2% +0.2 1.00 perf-profile.calltrace.cycles-pp.posix_lock_inode.do_lock_file_wait.fcntl_setlk.do_fcntl.__x64_sys_fcntl
0.96 ± 2% +0.2 1.19 perf-profile.calltrace.cycles-pp.do_lock_file_wait.fcntl_setlk.do_fcntl.__x64_sys_fcntl.do_syscall_64
96.04 -0.9 95.12 perf-profile.children.cycles-pp.native_queued_spin_lock_slowpath
96.16 -0.9 95.29 perf-profile.children.cycles-pp._raw_spin_lock
97.83 -0.4 97.47 perf-profile.children.cycles-pp.fcntl_setlk
99.03 -0.1 98.91 perf-profile.children.cycles-pp.do_syscall_64
99.09 -0.1 98.98 perf-profile.children.cycles-pp.entry_SYSCALL_64_after_hwframe
0.11 +0.0 0.12 perf-profile.children.cycles-pp.security_file_lock
0.13 ± 3% +0.0 0.14 perf-profile.children.cycles-pp.memset_erms
0.11 ± 8% +0.0 0.12 ± 6% perf-profile.children.cycles-pp.___might_sleep
0.24 +0.0 0.26 ± 3% perf-profile.children.cycles-pp.syscall_return_via_sysret
0.07 ± 17% +0.0 0.09 ± 11% perf-profile.children.cycles-pp.account_system_index_time
0.07 ± 6% +0.0 0.11 ± 4% perf-profile.children.cycles-pp.__might_fault
0.07 ± 5% +0.0 0.12 ± 3% perf-profile.children.cycles-pp._cond_resched
0.15 ± 5% +0.0 0.19 ± 2% perf-profile.children.cycles-pp._copy_from_user
0.00 +0.1 0.05 perf-profile.children.cycles-pp.locks_release_private
0.00 +0.1 0.05 perf-profile.children.cycles-pp.inode_has_perm
0.00 +0.1 0.05 ± 8% perf-profile.children.cycles-pp.__pthread_disable_asynccancel
0.04 ± 60% +0.1 0.10 ± 11% perf-profile.children.cycles-pp._raw_spin_unlock_irqrestore
0.20 ± 7% +0.1 0.27 perf-profile.children.cycles-pp.locks_free_lock
0.00 +0.1 0.08 perf-profile.children.cycles-pp.rcu_all_qs
0.46 ± 3% +0.1 0.57 perf-profile.children.cycles-pp.kmem_cache_alloc
0.56 ± 2% +0.1 0.67 perf-profile.children.cycles-pp.locks_alloc_lock
0.11 ± 6% +0.1 0.22 ± 3% perf-profile.children.cycles-pp.avc_has_perm
0.31 ± 3% +0.1 0.43 perf-profile.children.cycles-pp.file_has_perm
0.29 ± 5% +0.1 0.41 perf-profile.children.cycles-pp.security_file_fcntl
0.16 ± 2% +0.1 0.28 ± 2% perf-profile.children.cycles-pp.kmem_cache_free
0.38 ± 9% +0.2 0.56 ± 17% perf-profile.children.cycles-pp.rcu_check_callbacks
0.81 ± 2% +0.2 1.02 perf-profile.children.cycles-pp.posix_lock_inode
0.97 ± 2% +0.2 1.19 perf-profile.children.cycles-pp.do_lock_file_wait
89.30 -1.6 87.70 perf-profile.self.cycles-pp.native_queued_spin_lock_slowpath
0.11 +0.0 0.12 ± 4% perf-profile.self.cycles-pp.memset_erms
0.24 +0.0 0.26 ± 2% perf-profile.self.cycles-pp.syscall_return_via_sysret
0.09 ± 7% +0.0 0.11 perf-profile.self.cycles-pp.locks_free_lock
0.17 ± 4% +0.0 0.20 ± 2% perf-profile.self.cycles-pp.kmem_cache_alloc
0.04 ± 60% +0.0 0.08 ± 14% perf-profile.self.cycles-pp.account_system_index_time
0.11 ± 4% +0.0 0.15 ± 5% perf-profile.self.cycles-pp.do_syscall_64
0.00 +0.1 0.05 perf-profile.self.cycles-pp.__pthread_disable_asynccancel
0.00 +0.1 0.05 ± 8% perf-profile.self.cycles-pp.__might_fault
0.04 ± 60% +0.1 0.10 ± 11% perf-profile.self.cycles-pp._raw_spin_unlock_irqrestore
0.04 ± 63% +0.1 0.10 ± 7% perf-profile.self.cycles-pp.scheduler_tick
0.00 +0.1 0.06 ± 15% perf-profile.self.cycles-pp.testcase
0.00 +0.1 0.07 perf-profile.self.cycles-pp.rcu_all_qs
0.12 +0.1 0.21 ± 5% perf-profile.self.cycles-pp.posix_lock_inode
0.10 ± 7% +0.1 0.20 ± 4% perf-profile.self.cycles-pp.avc_has_perm
0.15 ± 2% +0.1 0.26 perf-profile.self.cycles-pp.kmem_cache_free
0.32 ± 2% +0.1 0.44 ± 10% perf-profile.self.cycles-pp.fcntl_setlk
0.27 ± 10% +0.2 0.44 ± 18% perf-profile.self.cycles-pp.rcu_check_callbacks
2299970 ± 5% +11.6% 2566488 ± 6% interrupts.CAL:Function_call_interrupts
8020 ± 5% +11.1% 8914 ± 6% interrupts.CPU0.CAL:Function_call_interrupts
8069 ± 6% +12.1% 9049 ± 5% interrupts.CPU1.CAL:Function_call_interrupts
7975 ± 5% +11.2% 8871 ± 5% interrupts.CPU10.CAL:Function_call_interrupts
451.25 ± 41% -50.7% 222.25 ± 17% interrupts.CPU10.RES:Rescheduling_interrupts
8029 ± 6% +11.6% 8962 ± 6% interrupts.CPU100.CAL:Function_call_interrupts
8025 ± 5% +11.6% 8957 ± 6% interrupts.CPU101.CAL:Function_call_interrupts
7975 ± 5% +12.6% 8980 ± 6% interrupts.CPU102.CAL:Function_call_interrupts
8010 ± 6% +12.0% 8974 ± 6% interrupts.CPU104.CAL:Function_call_interrupts
7943 ± 6% +12.5% 8939 ± 6% interrupts.CPU105.CAL:Function_call_interrupts
8015 ± 6% +12.2% 8993 ± 6% interrupts.CPU106.CAL:Function_call_interrupts
8048 ± 6% +11.4% 8968 ± 6% interrupts.CPU107.CAL:Function_call_interrupts
7996 ± 5% +11.4% 8910 ± 6% interrupts.CPU11.CAL:Function_call_interrupts
7993 ± 6% +12.5% 8989 ± 6% interrupts.CPU110.CAL:Function_call_interrupts
8026 ± 6% +11.6% 8960 ± 6% interrupts.CPU111.CAL:Function_call_interrupts
8072 ± 5% +11.5% 9003 ± 6% interrupts.CPU117.CAL:Function_call_interrupts
8041 ± 5% +11.7% 8981 ± 6% interrupts.CPU118.CAL:Function_call_interrupts
8058 ± 5% +11.6% 8996 ± 6% interrupts.CPU119.CAL:Function_call_interrupts
7985 ± 5% +11.2% 8883 ± 5% interrupts.CPU12.CAL:Function_call_interrupts
7992 ± 5% +12.5% 8988 ± 6% interrupts.CPU120.CAL:Function_call_interrupts
7885 ± 6% +13.9% 8981 ± 6% interrupts.CPU121.CAL:Function_call_interrupts
7917 ± 5% +13.3% 8971 ± 6% interrupts.CPU122.CAL:Function_call_interrupts
8008 ± 5% +11.9% 8965 ± 6% interrupts.CPU123.CAL:Function_call_interrupts
8046 ± 5% +11.5% 8973 ± 6% interrupts.CPU124.CAL:Function_call_interrupts
8001 ± 6% +12.3% 8985 ± 6% interrupts.CPU125.CAL:Function_call_interrupts
8031 ± 5% +11.9% 8985 ± 6% interrupts.CPU127.CAL:Function_call_interrupts
8042 ± 5% +11.9% 9001 ± 6% interrupts.CPU128.CAL:Function_call_interrupts
7889 ± 5% +12.8% 8899 ± 5% interrupts.CPU13.CAL:Function_call_interrupts
8050 ± 6% +11.3% 8958 ± 6% interrupts.CPU131.CAL:Function_call_interrupts
8041 ± 6% +10.4% 8876 ± 5% interrupts.CPU132.CAL:Function_call_interrupts
19.00 ± 35% +261.8% 68.75 ± 67% interrupts.CPU132.RES:Rescheduling_interrupts
7995 ± 6% +12.2% 8969 ± 6% interrupts.CPU134.CAL:Function_call_interrupts
3612 ± 2% +50.6% 5439 ± 31% interrupts.CPU134.NMI:Non-maskable_interrupts
3612 ± 2% +50.6% 5439 ± 31% interrupts.CPU134.PMI:Performance_monitoring_interrupts
7999 ± 6% +12.1% 8966 ± 6% interrupts.CPU135.CAL:Function_call_interrupts
8028 ± 7% +11.5% 8954 ± 6% interrupts.CPU136.CAL:Function_call_interrupts
7993 ± 7% +12.3% 8975 ± 6% interrupts.CPU138.CAL:Function_call_interrupts
444.50 ± 40% -52.7% 210.25 ± 15% interrupts.CPU14.RES:Rescheduling_interrupts
7961 ± 6% +12.5% 8953 ± 6% interrupts.CPU142.CAL:Function_call_interrupts
8004 ± 6% +11.5% 8926 ± 5% interrupts.CPU145.CAL:Function_call_interrupts
7874 ± 6% +13.5% 8940 ± 5% interrupts.CPU146.CAL:Function_call_interrupts
7949 ± 6% +11.9% 8899 ± 6% interrupts.CPU147.CAL:Function_call_interrupts
7959 ± 7% +12.0% 8917 ± 6% interrupts.CPU148.CAL:Function_call_interrupts
7906 ± 8% +12.3% 8883 ± 5% interrupts.CPU149.CAL:Function_call_interrupts
8017 ± 6% +10.8% 8884 ± 5% interrupts.CPU152.CAL:Function_call_interrupts
8073 ± 7% +10.5% 8922 ± 6% interrupts.CPU153.CAL:Function_call_interrupts
8017 ± 7% +11.2% 8915 ± 5% interrupts.CPU154.CAL:Function_call_interrupts
8006 ± 6% +11.5% 8923 ± 6% interrupts.CPU155.CAL:Function_call_interrupts
8002 ± 6% +11.4% 8915 ± 6% interrupts.CPU156.CAL:Function_call_interrupts
8023 ± 5% +11.2% 8918 ± 5% interrupts.CPU157.CAL:Function_call_interrupts
7935 ± 5% +12.3% 8908 ± 6% interrupts.CPU16.CAL:Function_call_interrupts
8051 ± 5% +11.3% 8964 ± 6% interrupts.CPU160.CAL:Function_call_interrupts
8039 ± 6% +11.6% 8971 ± 6% interrupts.CPU161.CAL:Function_call_interrupts
8005 ± 6% +11.8% 8949 ± 6% interrupts.CPU162.CAL:Function_call_interrupts
8064 ± 5% +11.2% 8968 ± 6% interrupts.CPU163.CAL:Function_call_interrupts
8075 ± 5% +10.5% 8924 ± 6% interrupts.CPU165.CAL:Function_call_interrupts
8061 ± 5% +10.6% 8914 ± 6% interrupts.CPU166.CAL:Function_call_interrupts
8078 ± 5% +10.2% 8905 ± 5% interrupts.CPU167.CAL:Function_call_interrupts
7967 ± 6% +11.1% 8855 ± 5% interrupts.CPU170.CAL:Function_call_interrupts
8019 ± 6% +11.1% 8907 ± 5% interrupts.CPU173.CAL:Function_call_interrupts
7961 ± 6% +11.9% 8907 ± 5% interrupts.CPU174.CAL:Function_call_interrupts
7917 ± 6% +12.8% 8930 ± 5% interrupts.CPU175.CAL:Function_call_interrupts
7970 ± 6% +12.1% 8936 ± 5% interrupts.CPU176.CAL:Function_call_interrupts
7881 ± 6% +13.3% 8927 ± 5% interrupts.CPU177.CAL:Function_call_interrupts
7962 ± 6% +12.2% 8938 ± 5% interrupts.CPU178.CAL:Function_call_interrupts
8009 ± 5% +11.2% 8904 ± 6% interrupts.CPU18.CAL:Function_call_interrupts
6369 ± 22% -28.5% 4555 ± 34% interrupts.CPU180.NMI:Non-maskable_interrupts
6369 ± 22% -28.5% 4555 ± 34% interrupts.CPU180.PMI:Performance_monitoring_interrupts
8023 ± 6% +11.5% 8943 ± 5% interrupts.CPU181.CAL:Function_call_interrupts
8057 ± 5% +11.4% 8972 ± 6% interrupts.CPU182.CAL:Function_call_interrupts
8042 ± 6% +11.2% 8945 ± 5% interrupts.CPU183.CAL:Function_call_interrupts
8058 ± 5% +11.0% 8946 ± 6% interrupts.CPU184.CAL:Function_call_interrupts
8002 ± 6% +11.8% 8946 ± 5% interrupts.CPU185.CAL:Function_call_interrupts
7994 ± 5% +11.8% 8935 ± 5% interrupts.CPU187.CAL:Function_call_interrupts
8018 ± 5% +11.9% 8969 ± 6% interrupts.CPU188.CAL:Function_call_interrupts
7982 ± 5% +11.9% 8928 ± 7% interrupts.CPU189.CAL:Function_call_interrupts
7982 ± 5% +12.0% 8942 ± 6% interrupts.CPU190.CAL:Function_call_interrupts
7965 ± 5% +12.1% 8925 ± 5% interrupts.CPU191.CAL:Function_call_interrupts
7935 ± 5% +12.3% 8915 ± 6% interrupts.CPU192.CAL:Function_call_interrupts
7990 ± 5% +11.7% 8921 ± 5% interrupts.CPU193.CAL:Function_call_interrupts
7881 ± 5% +12.9% 8901 ± 6% interrupts.CPU194.CAL:Function_call_interrupts
7976 ± 5% +11.5% 8893 ± 5% interrupts.CPU195.CAL:Function_call_interrupts
7965 ± 5% +11.9% 8916 ± 6% interrupts.CPU196.CAL:Function_call_interrupts
7946 ± 4% +12.2% 8918 ± 5% interrupts.CPU197.CAL:Function_call_interrupts
7931 ± 4% +12.2% 8901 ± 5% interrupts.CPU198.CAL:Function_call_interrupts
6408 ± 23% -28.8% 4563 ± 32% interrupts.CPU198.NMI:Non-maskable_interrupts
6408 ± 23% -28.8% 4563 ± 32% interrupts.CPU198.PMI:Performance_monitoring_interrupts
7745 ± 8% +15.8% 8965 ± 6% interrupts.CPU199.CAL:Function_call_interrupts
6338 ± 23% -29.1% 4491 ± 30% interrupts.CPU199.NMI:Non-maskable_interrupts
6338 ± 23% -29.1% 4491 ± 30% interrupts.CPU199.PMI:Performance_monitoring_interrupts
7950 ± 5% +12.7% 8959 ± 6% interrupts.CPU2.CAL:Function_call_interrupts
7893 ± 5% +13.2% 8931 ± 5% interrupts.CPU200.CAL:Function_call_interrupts
7910 ± 4% +13.6% 8982 ± 6% interrupts.CPU201.CAL:Function_call_interrupts
8008 ± 5% +11.8% 8955 ± 6% interrupts.CPU202.CAL:Function_call_interrupts
8024 ± 5% +11.6% 8952 ± 6% interrupts.CPU203.CAL:Function_call_interrupts
8002 ± 5% +10.9% 8877 ± 6% interrupts.CPU204.CAL:Function_call_interrupts
7994 ± 5% +12.2% 8967 ± 5% interrupts.CPU209.CAL:Function_call_interrupts
5391 ± 30% -32.5% 3639 ± 2% interrupts.CPU209.NMI:Non-maskable_interrupts
5391 ± 30% -32.5% 3639 ± 2% interrupts.CPU209.PMI:Performance_monitoring_interrupts
8015 ± 5% +12.1% 8984 ± 6% interrupts.CPU210.CAL:Function_call_interrupts
7804 ± 9% +15.0% 8973 ± 6% interrupts.CPU211.CAL:Function_call_interrupts
8035 ± 6% +11.2% 8933 ± 6% interrupts.CPU213.CAL:Function_call_interrupts
7934 ± 4% +12.3% 8911 ± 6% interrupts.CPU214.CAL:Function_call_interrupts
7988 ± 5% +11.8% 8927 ± 6% interrupts.CPU215.CAL:Function_call_interrupts
8001 ± 5% +12.1% 8968 ± 6% interrupts.CPU216.CAL:Function_call_interrupts
8007 ± 5% +11.5% 8924 ± 6% interrupts.CPU217.CAL:Function_call_interrupts
7844 ± 5% +13.6% 8912 ± 6% interrupts.CPU218.CAL:Function_call_interrupts
7737 ± 8% +15.1% 8905 ± 6% interrupts.CPU219.CAL:Function_call_interrupts
7996 ± 6% +11.5% 8916 ± 6% interrupts.CPU22.CAL:Function_call_interrupts
7933 ± 6% +11.9% 8880 ± 6% interrupts.CPU220.CAL:Function_call_interrupts
7870 ± 6% +12.8% 8880 ± 6% interrupts.CPU221.CAL:Function_call_interrupts
6511 ± 24% -30.9% 4502 ± 31% interrupts.CPU222.NMI:Non-maskable_interrupts
6511 ± 24% -30.9% 4502 ± 31% interrupts.CPU222.PMI:Performance_monitoring_interrupts
7776 ± 6% +14.6% 8911 ± 6% interrupts.CPU224.CAL:Function_call_interrupts
6538 ± 23% -30.8% 4525 ± 32% interrupts.CPU224.NMI:Non-maskable_interrupts
6538 ± 23% -30.8% 4525 ± 32% interrupts.CPU224.PMI:Performance_monitoring_interrupts
7964 ± 5% +12.1% 8928 ± 6% interrupts.CPU225.CAL:Function_call_interrupts
5541 ± 31% -32.8% 3723 interrupts.CPU225.NMI:Non-maskable_interrupts
5541 ± 31% -32.8% 3723 interrupts.CPU225.PMI:Performance_monitoring_interrupts
7953 ± 5% +11.0% 8830 ± 6% interrupts.CPU226.CAL:Function_call_interrupts
7974 ± 5% +11.0% 8852 ± 7% interrupts.CPU228.CAL:Function_call_interrupts
7952 ± 5% +11.7% 8879 ± 7% interrupts.CPU229.CAL:Function_call_interrupts
7951 ± 5% +12.1% 8917 ± 6% interrupts.CPU23.CAL:Function_call_interrupts
7978 ± 5% +12.2% 8955 ± 6% interrupts.CPU232.CAL:Function_call_interrupts
7981 ± 5% +12.0% 8943 ± 6% interrupts.CPU233.CAL:Function_call_interrupts
7974 ± 5% +12.4% 8964 ± 6% interrupts.CPU234.CAL:Function_call_interrupts
7971 ± 5% +12.9% 8998 ± 6% interrupts.CPU235.CAL:Function_call_interrupts
7968 ± 5% +12.6% 8974 ± 6% interrupts.CPU236.CAL:Function_call_interrupts
8020 ± 5% +11.9% 8971 ± 6% interrupts.CPU237.CAL:Function_call_interrupts
8016 ± 5% +12.0% 8979 ± 6% interrupts.CPU238.CAL:Function_call_interrupts
8036 ± 5% +12.0% 9003 ± 6% interrupts.CPU239.CAL:Function_call_interrupts
6388 ± 22% -28.5% 4567 ± 33% interrupts.CPU243.NMI:Non-maskable_interrupts
6388 ± 22% -28.5% 4567 ± 33% interrupts.CPU243.PMI:Performance_monitoring_interrupts
10.50 ± 38% +292.9% 41.25 ±109% interrupts.CPU244.RES:Rescheduling_interrupts
6268 ± 22% -27.8% 4526 ± 32% interrupts.CPU245.NMI:Non-maskable_interrupts
6268 ± 22% -27.8% 4526 ± 32% interrupts.CPU245.PMI:Performance_monitoring_interrupts
6366 ± 23% -28.7% 4537 ± 33% interrupts.CPU246.NMI:Non-maskable_interrupts
6366 ± 23% -28.7% 4537 ± 33% interrupts.CPU246.PMI:Performance_monitoring_interrupts
5596 ± 32% -18.7% 4548 ± 33% interrupts.CPU248.NMI:Non-maskable_interrupts
5596 ± 32% -18.7% 4548 ± 33% interrupts.CPU248.PMI:Performance_monitoring_interrupts
5564 ± 30% -33.8% 3681 ± 2% interrupts.CPU252.NMI:Non-maskable_interrupts
5564 ± 30% -33.8% 3681 ± 2% interrupts.CPU252.PMI:Performance_monitoring_interrupts
7987 ± 5% +12.1% 8953 ± 7% interrupts.CPU260.CAL:Function_call_interrupts
5387 ± 29% -32.3% 3648 ± 2% interrupts.CPU260.NMI:Non-maskable_interrupts
5387 ± 29% -32.3% 3648 ± 2% interrupts.CPU260.PMI:Performance_monitoring_interrupts
8007 ± 5% +11.7% 8942 ± 6% interrupts.CPU261.CAL:Function_call_interrupts
8014 ± 5% +12.1% 8986 ± 6% interrupts.CPU262.CAL:Function_call_interrupts
8039 ± 6% +11.6% 8975 ± 6% interrupts.CPU263.CAL:Function_call_interrupts
3632 +50.4% 5464 ± 31% interrupts.CPU263.NMI:Non-maskable_interrupts
3632 +50.4% 5464 ± 31% interrupts.CPU263.PMI:Performance_monitoring_interrupts
7885 ± 5% +14.0% 8987 ± 6% interrupts.CPU264.CAL:Function_call_interrupts
8016 ± 6% +12.5% 9018 ± 6% interrupts.CPU265.CAL:Function_call_interrupts
7945 ± 5% +13.2% 8991 ± 6% interrupts.CPU266.CAL:Function_call_interrupts
7966 ± 5% +13.0% 9000 ± 6% interrupts.CPU267.CAL:Function_call_interrupts
8050 ± 6% +12.0% 9012 ± 6% interrupts.CPU269.CAL:Function_call_interrupts
8050 ± 6% +11.5% 8976 ± 6% interrupts.CPU270.CAL:Function_call_interrupts
8048 ± 6% +11.7% 8986 ± 6% interrupts.CPU271.CAL:Function_call_interrupts
8033 ± 6% +12.0% 8994 ± 6% interrupts.CPU272.CAL:Function_call_interrupts
8061 ± 6% +11.8% 9008 ± 6% interrupts.CPU273.CAL:Function_call_interrupts
8028 ± 6% +10.9% 8904 ± 5% interrupts.CPU276.CAL:Function_call_interrupts
8053 ± 6% +10.8% 8925 ± 6% interrupts.CPU277.CAL:Function_call_interrupts
8007 ± 6% +12.3% 8990 ± 6% interrupts.CPU278.CAL:Function_call_interrupts
8027 ± 6% +12.2% 9005 ± 6% interrupts.CPU279.CAL:Function_call_interrupts
7969 ± 5% +11.4% 8875 ± 5% interrupts.CPU28.CAL:Function_call_interrupts
8019 ± 6% +12.6% 9028 ± 6% interrupts.CPU280.CAL:Function_call_interrupts
8027 ± 7% +12.1% 9001 ± 6% interrupts.CPU281.CAL:Function_call_interrupts
8016 ± 6% +12.3% 9005 ± 7% interrupts.CPU282.CAL:Function_call_interrupts
8006 ± 7% +12.0% 8963 ± 6% interrupts.CPU283.CAL:Function_call_interrupts
8025 ± 5% +12.1% 8997 ± 6% interrupts.CPU286.CAL:Function_call_interrupts
8062 ± 5% +11.6% 8999 ± 6% interrupts.CPU287.CAL:Function_call_interrupts
7827 ± 5% +14.0% 8922 ± 6% interrupts.CPU29.CAL:Function_call_interrupts
7963 ± 5% +12.0% 8919 ± 5% interrupts.CPU3.CAL:Function_call_interrupts
7896 ± 5% +12.8% 8910 ± 6% interrupts.CPU30.CAL:Function_call_interrupts
7871 ± 5% +13.9% 8964 ± 6% interrupts.CPU31.CAL:Function_call_interrupts
7895 ± 5% +13.5% 8964 ± 6% interrupts.CPU32.CAL:Function_call_interrupts
7834 ± 4% +14.3% 8952 ± 6% interrupts.CPU33.CAL:Function_call_interrupts
7888 ± 5% +13.1% 8919 ± 7% interrupts.CPU34.CAL:Function_call_interrupts
7942 ± 5% +12.9% 8964 ± 6% interrupts.CPU35.CAL:Function_call_interrupts
7950 ± 5% +11.6% 8875 ± 6% interrupts.CPU36.CAL:Function_call_interrupts
7902 ± 5% +13.1% 8940 ± 6% interrupts.CPU37.CAL:Function_call_interrupts
7957 ± 5% +12.3% 8940 ± 6% interrupts.CPU38.CAL:Function_call_interrupts
105.75 ± 14% +91.0% 202.00 ± 18% interrupts.CPU39.RES:Rescheduling_interrupts
7910 ± 8% +13.6% 8988 ± 5% interrupts.CPU4.CAL:Function_call_interrupts
7927 ± 5% +12.1% 8887 ± 5% interrupts.CPU40.CAL:Function_call_interrupts
7940 ± 5% +11.9% 8884 ± 6% interrupts.CPU41.CAL:Function_call_interrupts
7957 ± 5% +11.7% 8886 ± 6% interrupts.CPU42.CAL:Function_call_interrupts
7990 ± 5% +11.3% 8894 ± 5% interrupts.CPU43.CAL:Function_call_interrupts
7929 ± 4% +12.2% 8896 ± 6% interrupts.CPU44.CAL:Function_call_interrupts
230.75 ± 11% +38.4% 319.25 ± 11% interrupts.CPU44.RES:Rescheduling_interrupts
7998 ± 5% +11.7% 8933 ± 6% interrupts.CPU46.CAL:Function_call_interrupts
192.50 ± 13% +55.3% 299.00 ± 27% interrupts.CPU46.RES:Rescheduling_interrupts
7955 ± 5% +12.0% 8910 ± 6% interrupts.CPU47.CAL:Function_call_interrupts
7788 ± 5% +14.2% 8893 ± 6% interrupts.CPU48.CAL:Function_call_interrupts
7836 ± 5% +13.7% 8910 ± 6% interrupts.CPU49.CAL:Function_call_interrupts
7776 ± 5% +14.8% 8925 ± 6% interrupts.CPU50.CAL:Function_call_interrupts
7862 ± 5% +14.0% 8963 ± 6% interrupts.CPU51.CAL:Function_call_interrupts
7984 ± 5% +12.1% 8951 ± 6% interrupts.CPU52.CAL:Function_call_interrupts
7992 ± 5% +12.0% 8953 ± 6% interrupts.CPU53.CAL:Function_call_interrupts
7986 ± 5% +11.0% 8867 ± 5% interrupts.CPU54.CAL:Function_call_interrupts
8012 ± 5% +11.7% 8951 ± 6% interrupts.CPU55.CAL:Function_call_interrupts
8021 ± 5% +11.0% 8902 ± 5% interrupts.CPU56.CAL:Function_call_interrupts
7995 ± 5% +11.3% 8901 ± 5% interrupts.CPU57.CAL:Function_call_interrupts
7982 ± 5% +11.4% 8895 ± 5% interrupts.CPU58.CAL:Function_call_interrupts
7967 ± 5% +12.6% 8971 ± 6% interrupts.CPU59.CAL:Function_call_interrupts
7953 ± 5% +11.1% 8832 ± 5% interrupts.CPU61.CAL:Function_call_interrupts
7853 ± 5% +13.7% 8929 ± 6% interrupts.CPU62.CAL:Function_call_interrupts
7940 ± 5% +12.3% 8913 ± 6% interrupts.CPU63.CAL:Function_call_interrupts
7931 ± 5% +12.2% 8896 ± 6% interrupts.CPU64.CAL:Function_call_interrupts
7893 ± 5% +13.1% 8923 ± 6% interrupts.CPU65.CAL:Function_call_interrupts
7872 ± 5% +12.9% 8886 ± 6% interrupts.CPU66.CAL:Function_call_interrupts
7877 ± 7% +12.3% 8844 ± 6% interrupts.CPU67.CAL:Function_call_interrupts
7970 ± 5% +11.9% 8919 ± 6% interrupts.CPU72.CAL:Function_call_interrupts
7964 ± 5% +11.8% 8901 ± 7% interrupts.CPU73.CAL:Function_call_interrupts
7891 ± 5% +12.7% 8896 ± 5% interrupts.CPU8.CAL:Function_call_interrupts
7973 ± 5% +11.6% 8896 ± 6% interrupts.CPU9.CAL:Function_call_interrupts
8029 ± 5% +11.4% 8946 ± 6% interrupts.CPU93.CAL:Function_call_interrupts
8005 ± 5% +11.7% 8945 ± 6% interrupts.CPU94.CAL:Function_call_interrupts
will-it-scale.per_thread_ops
5400 +-+------------------------------------------------------------------+
| O O
5200 +-+ O O O O O O O O O O O O O |
5000 +-+ O O O |
O O |
4800 +-+O O O |
| |
4600 +-+ |
| |
4400 +-+ ..+.. |
4200 +-+ .+. +.. |
| +..+. +..+..+.. .+..+... .. +.. |
4000 +-+ +. + + |
| |
3800 +-+------------------------------------------------------------------+
[*] 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,
Rong Chen
1 year, 5 months
780a16e323: WARNING:at_lib/vsprintf.c:#format_decode
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: 780a16e323917b78004645d94400296a5e0826f3 ("Patch to do key type autoloading v2")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/mbroz/linux.git dm-cryptsetup
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+----------------------------------------------------+----------+------------+
| | v5.3-rc4 | 780a16e323 |
+----------------------------------------------------+----------+------------+
| boot_successes | 3374 | 13 |
| boot_failures | 50 | 18 |
| invoked_oom-killer:gfp_mask=0x | 26 | 1 |
| Mem-Info | 26 | 1 |
| RIP:copy_user_generic_string | 5 | |
| kernel_BUG_at_security/keys/keyring.c | 12 | |
| invalid_opcode:#[##] | 12 | |
| RIP:__key_link_begin | 12 | |
| Kernel_panic-not_syncing:Fatal_exception | 12 | 1 |
| BUG:soft_lockup-CPU##stuck_for#s | 2 | |
| RIP:clear_page_rep | 1 | |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 2 | |
| BUG:kernel_hang_in_boot_stage | 8 | |
| RIP:__memcpy | 1 | |
| BUG:kernel_hang_in_boot-around-mounting-root_stage | 1 | |
| BUG:kernel_reboot-without-warning_in_test_stage | 1 | |
| WARNING:at_lib/vsprintf.c:#format_decode | 0 | 16 |
| RIP:format_decode | 0 | 16 |
| general_protection_fault:#[##] | 0 | 1 |
| RIP:string_nocheck | 0 | 1 |
+----------------------------------------------------+----------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen(a)intel.com>
[ 96.204959] WARNING: CPU: 1 PID: 2265 at lib/vsprintf.c:2359 format_decode+0x3dd/0x3f0
[ 96.214488] Modules linked in: ieee802154_socket ieee802154 bridge stp llc sr_mod cdrom intel_rapl_msr sg ppdev af_key hidp cmtp kernelcapi bnep rfcomm bluetooth ecdh_generic ecc rfkill can_bcm can_raw can pptp gre l2tp_ppp l2tp_netlink l2tp_core ip6_udp_tunnel udp_tunnel pppoe pppox ppp_generic slhc intel_rapl_common crct10dif_pclmul crypto_user crc32_pclmul nfnetlink ghash_clmulni_intel scsi_transport_iscsi dccp_ipv6 atm aesni_intel sctp libcrc32c crypto_simd crc32c_intel dccp_ipv4 cryptd dccp glue_helper joydev pcspkr serio_raw bochs_drm parport_pc drm_vram_helper ttm parport drm_kms_helper floppy syscopyarea sysfillrect sysimgblt fb_sys_fops ata_generic pata_acpi drm i2c_piix4 ata_piix libata ip_tables
[ 96.279994] CPU: 1 PID: 2265 Comm: trinity-c2 Not tainted 5.3.0-rc4-00001-g780a16e323917 #1
[ 96.294201] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 96.305126] RIP: 0010:format_decode+0x3dd/0x3f0
[ 96.312620] Code: ff ff 48 8d 42 02 b9 4c 00 00 00 48 89 04 24 e9 db fc ff ff 0f be f2 48 c7 c7 80 15 fc b3 c6 05 1b b5 d9 00 01 e8 63 e8 63 ff <0f> 0b 48 8b 04 24 e9 04 ff ff ff 0f 1f 84 00 00 00 00 00 89 f0 c1
[ 96.331681] RSP: 0018:ffffbe4b0058fd48 EFLAGS: 00010282
[ 96.337426] RAX: 0000000000000000 RBX: ffffbe4b0058fd78 RCX: 0000000000000000
[ 96.343707] RDX: ffff9a49ffd27200 RSI: ffff9a49ffd17778 RDI: ffff9a49ffd17778
[ 96.349607] RBP: ffff9a493aaa142c R08: 0000000000000322 R09: 0000000000aaaaaa
[ 96.355159] R10: ffffbe4b0058fec0 R11: ffff9a4950ae2070 R12: ffffbe4b0058fe48
[ 96.361237] R13: 0000000000000038 R14: ffffbe4b0058fdf8 R15: ffff9a493aaa142c
[ 96.367489] FS: 00007fc509049740(0000) GS:ffff9a49ffd00000(0000) knlGS:0000000000000000
[ 96.373905] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 96.378953] CR2: 0000000000000000 CR3: 000000007a442000 CR4: 00000000000406e0
[ 96.384394] Call Trace:
[ 96.388238] vsnprintf+0x65/0x4d0
[ 96.392840] __request_module+0xb7/0x450
[ 96.396968] ? kasprintf+0x49/0x70
[ 96.400972] key_type_lookup+0xba/0x110
[ 96.406382] __x64_sys_request_key+0xcf/0x190
[ 96.411046] do_syscall_64+0x5b/0x1f0
[ 96.415363] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 96.419802] RIP: 0033:0x7fc5089561c9
[ 96.424822] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 dc 2c 00 f7 d8 64 89 01 48
[ 96.439124] RSP: 002b:00007fffc6696be8 EFLAGS: 00000246 ORIG_RAX: 00000000000000f9
[ 96.453973] RAX: ffffffffffffffda RBX: 00000000000000f9 RCX: 00007fc5089561c9
[ 96.464762] RDX: 00007fc506b5700c RSI: 00007fc506b57004 RDI: 00007fc506b57000
[ 96.477464] RBP: 00007fc509034000 R08: 0000000004000000 R09: 0000000000000000
[ 96.491136] R10: fffffffffffffffd R11: 0000000000000246 R12: 00007fc509034058
[ 96.504153] R13: 00007fc5090496b0 R14: 0000000000000000 R15: 00007fc509034000
[ 96.509849] ---[ end trace 79467a168956abee ]---
To reproduce:
# build kernel
cd linux
cp config-5.3.0-rc4-00001-g780a16e323917 .config
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Rong Chen
1 year, 5 months
[sched/fair] 6b8fd01b21: INFO:rcu_sched_detected_stalls_on_CPUs/tasks
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: 6b8fd01b21f5f2701b407a7118f236ba4c41226d ("sched/fair: Use rq_lock/unlock in online_fair_sched_group")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/peterz/queue.git sched/core
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+----------------------------------------------------+------------+------------+
| | 5c3ceef9ad | 6b8fd01b21 |
+----------------------------------------------------+------------+------------+
| boot_successes | 39 | 391 |
| boot_failures | 0 | 87 |
| BUG:kernel_hang_in_test_stage | 0 | 68 |
| BUG:kernel_hang_in_boot-around-mounting-root_stage | 0 | 7 |
| BUG:soft_lockup-CPU##stuck_for#s | 0 | 12 |
| RIP:smp_call_function_single | 0 | 8 |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 0 | 12 |
| RIP:native_queued_spin_lock_slowpath | 0 | 6 |
| INFO:rcu_sched_detected_stalls_on_CPUs/tasks | 0 | 5 |
| RIP:propagate_entity_cfs_rq | 0 | 2 |
| RIP:native_safe_halt | 0 | 3 |
| RIP:console_unlock | 0 | 1 |
+----------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <lkp(a)intel.com>
[ 343.745182] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 343.753425] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 343.757282] (detected by 1, t=100002 jiffies, g=378081, q=193)
[ 343.759684] Sending NMI from CPU 1 to CPUs 0:
[ 343.762288] NMI backtrace for cpu 0
[ 343.762289] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 343.762290] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 343.762290] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 343.762291] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 343.762291] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 343.762292] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 343.762293] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 343.762293] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 343.762294] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 343.762294] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 343.762294] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 343.762295] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 343.762295] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 343.762296] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 343.762296] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 343.762296] Call Trace:
[ 343.762297] <IRQ>
[ 343.762297] _raw_spin_lock_irqsave+0x37/0x40
[ 343.762297] sched_ttwu_pending+0x45/0xe0
[ 343.762298] scheduler_ipi+0xa9/0x130
[ 343.762298] reschedule_interrupt+0xf/0x20
[ 343.762298] </IRQ>
[ 343.762299] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 343.762300] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 343.762300] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 343.762301] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 343.762301] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 343.762302] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 343.762302] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 343.762303] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 343.762303] online_fair_sched_group+0x5e/0x110
[ 343.762303] sched_autogroup_create_attach+0xbb/0x170
[ 343.762304] ksys_setsid+0xf2/0x110
[ 343.762304] __ia32_sys_setsid+0xa/0x10
[ 343.762304] do_fast_syscall_32+0xa9/0x340
[ 343.762305] entry_SYSENTER_compat+0x7f/0x91
[ 343.762314] rcu: rcu_sched kthread starved for 100002 jiffies! g378081 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=0
[ 343.831714] rcu: RCU grace-period kthread stack dump:
[ 343.833255] rcu_sched I 0 10 2 0x90004000
[ 343.834788] Call Trace:
[ 343.835652] ? __schedule+0x252/0x6b0
[ 343.836792] schedule+0x34/0xb0
[ 343.837807] schedule_timeout+0x16b/0x310
[ 343.839021] ? __next_timer_interrupt+0xc0/0xc0
[ 343.840353] rcu_gp_kthread+0x643/0xac0
[ 343.841524] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 343.842946] kthread+0x11e/0x140
[ 343.843980] ? kthread_park+0xa0/0xa0
[ 343.845118] ret_from_fork+0x35/0x40
[ 643.750180] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 643.756145] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 643.759476] (detected by 1, t=400007 jiffies, g=378081, q=204)
[ 643.761127] Sending NMI from CPU 1 to CPUs 0:
[ 643.763438] NMI backtrace for cpu 0
[ 643.763439] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 643.763440] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 643.763440] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 643.763441] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 643.763441] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 643.763442] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 643.763443] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 643.763443] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 643.763444] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 643.763444] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 643.763445] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 643.763445] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 643.763445] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 643.763446] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 643.763446] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 643.763447] Call Trace:
[ 643.763447] <IRQ>
[ 643.763447] _raw_spin_lock_irqsave+0x37/0x40
[ 643.763448] sched_ttwu_pending+0x45/0xe0
[ 643.763448] scheduler_ipi+0xa9/0x130
[ 643.763448] reschedule_interrupt+0xf/0x20
[ 643.763449] </IRQ>
[ 643.763449] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 643.763450] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 643.763450] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 643.763451] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 643.763451] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 643.763452] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 643.763452] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 643.763453] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 643.763453] online_fair_sched_group+0x5e/0x110
[ 643.763453] sched_autogroup_create_attach+0xbb/0x170
[ 643.763454] ksys_setsid+0xf2/0x110
[ 643.763454] __ia32_sys_setsid+0xa/0x10
[ 643.763454] do_fast_syscall_32+0xa9/0x340
[ 643.763455] entry_SYSENTER_compat+0x7f/0x91
[ 643.763457] rcu: rcu_sched kthread starved for 400007 jiffies! g378081 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[ 643.833220] rcu: RCU grace-period kthread stack dump:
[ 643.834689] rcu_sched R 0 10 2 0x90004000
[ 643.836245] Call Trace:
[ 643.837118] ? __schedule+0x252/0x6b0
[ 643.838275] schedule+0x34/0xb0
[ 643.839300] schedule_timeout+0x16b/0x310
[ 643.840525] ? __next_timer_interrupt+0xc0/0xc0
[ 643.841872] rcu_gp_kthread+0x643/0xac0
[ 643.843066] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 643.844502] kthread+0x11e/0x140
[ 643.845556] ? kthread_park+0xa0/0xa0
[ 643.846704] ret_from_fork+0x35/0x40
[ 943.755175] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 943.764934] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 943.768354] (detected by 1, t=700012 jiffies, g=378081, q=204)
[ 943.770485] Sending NMI from CPU 1 to CPUs 0:
[ 943.772976] NMI backtrace for cpu 0
[ 943.772977] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 943.772977] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 943.772978] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 943.772978] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 943.772979] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 943.772980] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 943.772980] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 943.772981] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 943.772981] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 943.772982] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 943.772982] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 943.772982] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 943.772983] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 943.772983] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 943.772984] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 943.772984] Call Trace:
[ 943.772984] <IRQ>
[ 943.772985] _raw_spin_lock_irqsave+0x37/0x40
[ 943.772985] sched_ttwu_pending+0x45/0xe0
[ 943.772985] scheduler_ipi+0xa9/0x130
[ 943.772986] reschedule_interrupt+0xf/0x20
[ 943.772986] </IRQ>
[ 943.772986] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 943.772987] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 943.772988] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 943.772988] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 943.772989] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 943.772989] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 943.772990] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 943.772990] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 943.772990] online_fair_sched_group+0x5e/0x110
[ 943.772991] sched_autogroup_create_attach+0xbb/0x170
[ 943.772991] ksys_setsid+0xf2/0x110
[ 943.772991] __ia32_sys_setsid+0xa/0x10
[ 943.772992] do_fast_syscall_32+0xa9/0x340
[ 943.772992] entry_SYSENTER_compat+0x7f/0x91
[ 943.772995] rcu: rcu_sched kthread starved for 700012 jiffies! g378081 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[ 943.845807] rcu: RCU grace-period kthread stack dump:
[ 943.847283] rcu_sched R 0 10 2 0x90004000
[ 943.848843] Call Trace:
[ 943.849720] ? __schedule+0x252/0x6b0
[ 943.850873] schedule+0x34/0xb0
[ 943.851923] schedule_timeout+0x16b/0x310
[ 943.853149] ? __next_timer_interrupt+0xc0/0xc0
[ 943.854489] rcu_gp_kthread+0x643/0xac0
[ 943.855711] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 943.857152] kthread+0x11e/0x140
[ 943.858228] ? kthread_park+0xa0/0xa0
[ 943.859415] ret_from_fork+0x35/0x40
[ 1243.760147] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 1243.765939] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 1243.769537] (detected by 1, t=1000017 jiffies, g=378081, q=204)
[ 1243.771822] Sending NMI from CPU 1 to CPUs 0:
[ 1243.774628] NMI backtrace for cpu 0
[ 1243.774630] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 1243.774630] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 1243.774631] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 1243.774632] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 1243.774632] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 1243.774634] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 1243.774634] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 1243.774635] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 1243.774635] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 1243.774636] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1243.774637] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 1243.774637] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 1243.774638] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 1243.774638] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1243.774639] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1243.774639] Call Trace:
[ 1243.774640] <IRQ>
[ 1243.774640] _raw_spin_lock_irqsave+0x37/0x40
[ 1243.774641] sched_ttwu_pending+0x45/0xe0
[ 1243.774641] scheduler_ipi+0xa9/0x130
[ 1243.774642] reschedule_interrupt+0xf/0x20
[ 1243.774642] </IRQ>
[ 1243.774642] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 1243.774644] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 1243.774644] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 1243.774645] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 1243.774646] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 1243.774646] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 1243.774647] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 1243.774647] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 1243.774648] online_fair_sched_group+0x5e/0x110
[ 1243.774648] sched_autogroup_create_attach+0xbb/0x170
[ 1243.774649] ksys_setsid+0xf2/0x110
[ 1243.774649] __ia32_sys_setsid+0xa/0x10
[ 1243.774650] do_fast_syscall_32+0xa9/0x340
[ 1243.774650] entry_SYSENTER_compat+0x7f/0x91
[ 1243.774654] rcu: rcu_sched kthread starved for 1000017 jiffies! g378081 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[ 1243.844719] rcu: RCU grace-period kthread stack dump:
[ 1243.846166] rcu_sched R 0 10 2 0x90004000
[ 1243.847732] Call Trace:
[ 1243.848614] ? __schedule+0x252/0x6b0
[ 1243.849778] schedule+0x34/0xb0
[ 1243.850798] schedule_timeout+0x16b/0x310
[ 1243.852053] ? __next_timer_interrupt+0xc0/0xc0
[ 1243.853400] rcu_gp_kthread+0x643/0xac0
[ 1243.854568] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 1243.856000] kthread+0x11e/0x140
[ 1243.857063] ? kthread_park+0xa0/0xa0
[ 1243.858194] ret_from_fork+0x35/0x40
[ 1543.765186] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 1543.774595] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 1543.778676] (detected by 1, t=1300022 jiffies, g=378081, q=204)
[ 1543.780360] Sending NMI from CPU 1 to CPUs 0:
[ 1543.782720] NMI backtrace for cpu 0
[ 1543.782721] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 1543.782721] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 1543.782722] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 1543.782722] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 1543.782723] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 1543.782724] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 1543.782724] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 1543.782725] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 1543.782725] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 1543.782725] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1543.782726] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 1543.782726] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 1543.782727] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 1543.782727] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1543.782728] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1543.782728] Call Trace:
[ 1543.782728] <IRQ>
[ 1543.782728] _raw_spin_lock_irqsave+0x37/0x40
[ 1543.782729] sched_ttwu_pending+0x45/0xe0
[ 1543.782729] scheduler_ipi+0xa9/0x130
[ 1543.782729] reschedule_interrupt+0xf/0x20
[ 1543.782730] </IRQ>
[ 1543.782730] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 1543.782731] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 1543.782731] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 1543.782732] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 1543.782733] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 1543.782733] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 1543.782734] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 1543.782734] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 1543.782735] online_fair_sched_group+0x5e/0x110
[ 1543.782735] sched_autogroup_create_attach+0xbb/0x170
[ 1543.782735] ksys_setsid+0xf2/0x110
[ 1543.782736] __ia32_sys_setsid+0xa/0x10
[ 1543.782736] do_fast_syscall_32+0xa9/0x340
[ 1543.782736] entry_SYSENTER_compat+0x7f/0x91
[ 1543.782739] rcu: rcu_sched kthread starved for 1300022 jiffies! g378081 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[ 1543.853291] rcu: RCU grace-period kthread stack dump:
[ 1543.854765] rcu_sched R 0 10 2 0x90004000
[ 1543.856316] Call Trace:
[ 1543.857191] ? __schedule+0x252/0x6b0
[ 1543.858386] schedule+0x34/0xb0
[ 1543.859409] schedule_timeout+0x16b/0x310
[ 1543.860658] ? __next_timer_interrupt+0xc0/0xc0
[ 1543.862018] rcu_gp_kthread+0x643/0xac0
[ 1543.863209] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 1543.864647] kthread+0x11e/0x140
[ 1543.865702] ? kthread_park+0xa0/0xa0
[ 1543.866859] ret_from_fork+0x35/0x40
[ 1843.770181] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 1843.777403] rcu: 0-...!: (0 ticks this GP) idle=a8a/1/0x4000000000000002 softirq=192259/192259 fqs=0
[ 1843.780727] (detected by 1, t=1600027 jiffies, g=378081, q=204)
[ 1843.782434] Sending NMI from CPU 1 to CPUs 0:
[ 1843.784771] NMI backtrace for cpu 0
[ 1843.784772] CPU: 0 PID: 15242 Comm: trinity-c0 Not tainted 5.3.0-rc1-00092-g6b8fd01b21f5f #5
[ 1843.784772] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 1843.784773] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1e0
[ 1843.784773] Code: c5 ff ff ff 5e 5a c3 66 90 66 66 66 66 90 66 66 66 66 90 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 ab 00 00 00 81 e6 00 ff ff ff 75 44
[ 1843.784774] RSP: 0018:ffffc90000003f90 EFLAGS: 00000002
[ 1843.784775] RAX: 0000000000000001 RBX: 0000000000000086 RCX: 0000000000000002
[ 1843.784775] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88813fc2b180
[ 1843.784776] RBP: ffffc90000003fd0 R08: 0000000000000000 R09: 0000000000000000
[ 1843.784776] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88813fc2b180
[ 1843.784777] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1843.784777] FS: 0000000000000000(0000) GS:ffff88813fc00000(0063) knlGS:00000000f7e28900
[ 1843.784777] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033
[ 1843.784778] CR2: 00000000c0100220 CR3: 000000007f114000 CR4: 00000000000406f0
[ 1843.784778] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1843.784779] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1843.784779] Call Trace:
[ 1843.784779] <IRQ>
[ 1843.784780] _raw_spin_lock_irqsave+0x37/0x40
[ 1843.784780] sched_ttwu_pending+0x45/0xe0
[ 1843.784780] scheduler_ipi+0xa9/0x130
[ 1843.784781] reschedule_interrupt+0xf/0x20
[ 1843.784781] </IRQ>
[ 1843.784781] RIP: 0010:propagate_entity_cfs_rq+0x5cb/0x5f0
[ 1843.784782] Code: c1 ea 0a 48 85 d2 74 0f 48 8b 81 88 00 00 00 48 63 f2 48 99 48 f7 fe 48 8b b5 88 01 00 00 48 39 c6 48 0f 46 c6 e9 4c fb ff ff <f3> c3 80 3d b7 6c 73 01 00 75 8b 48 89 3c 24 e8 21 bd ff ff 48 8b
[ 1843.784782] RSP: 0018:ffffc900007efe98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 1843.784783] RAX: ffff88813fc17810 RBX: ffff88813fc2b180 RCX: 0000000000000400
[ 1843.784784] RDX: 0000000000000000 RSI: ffffffff82f8ff00 RDI: 0000000000000000
[ 1843.784784] RBP: 0000000000000000 R08: 00000000000001c1 R09: ffff88812ec03500
[ 1843.784796] R10: ffffc900007efe48 R11: 0000000000000000 R12: ffff88807fbaa400
[ 1843.784796] R13: 000000000002b180 R14: 0000000000000000 R15: ffff88807ec44c00
[ 1843.784796] online_fair_sched_group+0x5e/0x110
[ 1843.784797] sched_autogroup_create_attach+0xbb/0x170
[ 1843.784797] ksys_setsid+0xf2/0x110
[ 1843.784798] __ia32_sys_setsid+0xa/0x10
[ 1843.784798] do_fast_syscall_32+0xa9/0x340
[ 1843.784798] entry_SYSENTER_compat+0x7f/0x91
[ 1843.784801] rcu: rcu_sched kthread starved for 1600027 jiffies! g378081 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[ 1843.858031] rcu: RCU grace-period kthread stack dump:
[ 1843.859519] rcu_sched R 0 10 2 0x90004000
[ 1843.861094] Call Trace:
[ 1843.861972] ? __schedule+0x252/0x6b0
[ 1843.863151] schedule+0x34/0xb0
[ 1843.864205] schedule_timeout+0x16b/0x310
[ 1843.865464] ? __next_timer_interrupt+0xc0/0xc0
[ 1843.866860] rcu_gp_kthread+0x643/0xac0
[ 1843.868048] ? rcu_accelerate_cbs_unlocked+0x70/0x70
[ 1843.869506] kthread+0x11e/0x140
[ 1843.870561] ? kthread_park+0xa0/0xa0
[ 1843.871745] ret_from_fork+0x35/0x40
BUG: kernel hang in test stage
Elapsed time: 2130
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-0 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-1 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-2 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-3 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-4 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-5 256G
qemu-img create -f qcow2 disk-vm-snb-4G-9bcbf29744f9-6 256G
kvm=(
qemu-system-x86_64
-enable-kvm
-cpu SandyBridge
-kernel $kernel
-initrd initrd-vm-snb-4G-9bcbf29744f9
-m 4096
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0,hostfwd=tcp::32032-:22
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-drive file=disk-vm-snb-4G-9bcbf29744f9-0,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-1,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-2,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-3,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-4,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-5,media=disk,if=virtio
-drive file=disk-vm-snb-4G-9bcbf29744f9-6,media=disk,if=virtio
-serial stdio
-display none
-monitor null
)
append=(
ip=::::vm-snb-4G-9bcbf29744f9::dhcp
root=/dev/ram0
user=lkp
job=/job-script
ARCH=x86_64
kconfig=x86_64-rhel
branch=linux-devel/devel-hourly-2019080920
To reproduce:
# build kernel
cd linux
cp config-5.3.0-rc1-00092-g6b8fd01b21f5f .config
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
lkp
1 year, 5 months
[keys] f771fde820: kernel_BUG_at_security/keys/keyring.c
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: f771fde82051976a6fc0fd570f8b86de4a92124b ("keys: Simplify key description management")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/torvalds/linux.git master
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------+------------+------------+
| | 3b8c4a08a4 | f771fde820 |
+-------------------------------------------------+------------+------------+
| boot_successes | 705 | 703 |
| boot_failures | 43 | 32 |
| BUG:kernel_reboot-without-warning_in_test_stage | 12 | |
| invoked_oom-killer:gfp_mask=0x | 20 | 15 |
| Mem-Info | 20 | 15 |
| BUG:kernel_hang_in_boot_stage | 10 | 5 |
| RIP:__clear_user | 2 | |
| RIP:copy_user_generic_string | 3 | 3 |
| RIP:__get_user_8 | 1 | |
| WARNING:at_kernel/rcu/tree.c:#rcu_irq_exit | 1 | |
| RIP:rcu_irq_exit | 1 | |
| RIP:native_safe_halt | 1 | |
| WARNING:at_kernel/rcu/tree.c:#rcu_irq_enter | 1 | |
| RIP:rcu_irq_enter | 1 | |
| WARNING:at_kernel/rcu/tree.c:#rcu_nmi_enter | 1 | |
| RIP:rcu_nmi_enter | 1 | |
| WARNING:at_kernel/rcu/tree.c:#rcu_nmi_exit | 1 | |
| RIP:rcu_nmi_exit | 1 | |
| WARNING:at_kernel/rcu/tree.c:#rcu_eqs_exit | 1 | |
| RIP:rcu_eqs_exit | 1 | |
| BUG:scheduling_while_atomic | 1 | |
| kernel_BUG_at_security/keys/keyring.c | 0 | 12 |
| invalid_opcode:#[##] | 0 | 12 |
| RIP:__key_link_begin | 0 | 12 |
| Kernel_panic-not_syncing:Fatal_exception | 0 | 12 |
+-------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen(a)intel.com>
[ 34.431436] kernel BUG at security/keys/keyring.c:1245!
[ 34.432866] invalid opcode: 0000 [#1] SMP PTI
[ 34.433774] CPU: 1 PID: 2592 Comm: trinity-c7 Not tainted 5.2.0-rc1-00017-gf771fde820519 #1
[ 34.435431] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 34.437099] RIP: 0010:__key_link_begin+0x88/0xa0
[ 34.438538] Code: 5d 41 5c c3 0f b7 43 76 48 89 df 48 8d 70 04 e8 de dd ff ff 85 c0 79 dd 48 89 ef 89 44 24 04 e8 be f3 0b 00 8b 44 24 04 eb d1 <0f> 0b 0f 0b b8 80 ff ff ff eb c6 66 66 2e 0f 1f 84 00 00 00 00 00
[ 34.445962] RSP: 0018:ffffa91140d0fde8 EFLAGS: 00010246
[ 34.447932] RAX: 0000000000000000 RBX: ffff99787dd0f401 RCX: ffffa91140d0fe31
[ 34.450598] RDX: ffffa91140d0fe28 RSI: ffffa91140d0fe30 RDI: ffff99787dd0f400
[ 34.453125] RBP: ffff997895e78a40 R08: 0000000000000000 R09: ffff997907c03980
[ 34.455524] R10: ffff99787dd0f400 R11: 00000000d0f9514f R12: 00000000ffffffff
[ 34.458190] R13: ffff99793fde86c0 R14: ffffffffffffffec R15: 0000000000000008
[ 34.460708] FS: 00007f06eb481740(0000) GS:ffff99793fd00000(0000) knlGS:0000000000000000
[ 34.463433] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 34.465468] CR2: 00007f06e97613cc CR3: 000000007a9fe000 CR4: 00000000000406e0
[ 34.467888] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 34.470335] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 34.472748] Call Trace:
[ 34.473852] key_create_or_update+0x211/0x4b0
[ 34.475269] __x64_sys_add_key+0x101/0x200
[ 34.476740] do_syscall_64+0x5b/0x1e0
[ 34.477975] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 34.479678] RIP: 0033:0x7f06ead8e1c9
[ 34.482108] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 dc 2c 00 f7 d8 64 89 01 48
[ 34.490151] RSP: 002b:00007ffd0cc33628 EFLAGS: 00000246 ORIG_RAX: 00000000000000f8
[ 34.493640] RAX: ffffffffffffffda RBX: 00000000000000f8 RCX: 00007f06ead8e1c9
[ 34.497038] RDX: 00007f06eb342000 RSI: 0000000000400000 RDI: 000000000043c5ae
[ 34.500296] RBP: 00007f06eb449000 R08: ffffffffffffffff R09: fffffffffffffffb
[ 34.503601] R10: 0000000000000008 R11: 0000000000000246 R12: 00007f06eb449058
[ 34.506005] R13: 00007f06eb4816b0 R14: 0000000000000000 R15: 00007f06eb449000
[ 34.508374] Modules linked in: af_key mpls_router ip_tunnel vmw_vsock_vmci_transport vsock vmw_vmci ieee802154_socket ieee802154 hidp cmtp kernelcapi bnep rfcomm bluetooth ecdh_generic ecc rfkill can_bcm can_raw can pptp gre l2tp_ppp l2tp_netlink l2tp_core ip6_udp_tunnel udp_tunnel pppoe pppox ppp_generic slhc crypto_user nfnetlink scsi_transport_iscsi dccp_ipv6 atm sctp libcrc32c dccp_ipv4 dccp sr_mod cdrom sg ppdev crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel crypto_simd cryptd glue_helper joydev ata_generic pata_acpi serio_raw pcspkr parport_pc parport floppy bochs_drm ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm ata_piix libata i2c_piix4 ip_tables
[ 34.526027] ---[ end trace cfce0f246614c04a ]---
To reproduce:
# build kernel
cd linux
cp config-5.2.0-rc1-00017-gf771fde820519 .config
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Rong Chen
1 year, 5 months
21871a99b3 ("of/platform: Pause/resume sync state during init .."): WARNING: CPU: 0 PID: 1 at drivers/base/core.c:691 device_links_supplier_sync_state_resume
by kernel test robot
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
https://kernel.googlesource.com/pub/scm/linux/kernel/git/gregkh/driver-co... driver-core-testing
commit 21871a99b34c65c56a24193c277a4981529c306f
Author: Saravana Kannan <saravanak(a)google.com>
AuthorDate: Wed Jul 31 15:17:18 2019 -0700
Commit: Greg Kroah-Hartman <gregkh(a)linuxfoundation.org>
CommitDate: Thu Aug 1 16:04:14 2019 +0200
of/platform: Pause/resume sync state during init and of_platform_populate()
When all the top level devices are populated from DT during kernel
init, the supplier devices could be added and probed before the
consumer devices are added and linked to the suppliers. To avoid the
sync_state() callback from being called prematurely, pause the
sync_state() callbacks before populating the devices and resume them
at late_initcall_sync().
Similarly, when children devices are populated after kernel init using
of_platform_populate(), there could be supplier-consumer dependencies
between the children devices that are populated. To avoid the same
problem with sync_state() being called prematurely, pause and resume
sync_state() callbacks across of_platform_populate().
Signed-off-by: Saravana Kannan <saravanak(a)google.com>
Link: https://lore.kernel.org/r/20190731221721.187713-6-saravanak@google.com
Signed-off-by: Greg Kroah-Hartman <gregkh(a)linuxfoundation.org>
8f8184d6bf driver core: Add sync_state driver/bus callback
21871a99b3 of/platform: Pause/resume sync state during init and of_platform_populate()
5adf578101 of/platform: Fix device_links_supplier_sync_state_resume() warning
3880be629e Add linux-next specific files for 20190807
+-------------------------------------------------------------------------+------------+------------+------------+---------------+
| | 8f8184d6bf | 21871a99b3 | 5adf578101 | next-20190807 |
+-------------------------------------------------------------------------+------------+------------+------------+---------------+
| boot_successes | 27 | 0 | 0 | 0 |
| boot_failures | 2 | 11 | 11 | 11 |
| WARNING:at_mm/usercopy.c:#usercopy_warn | 1 | | | |
| RIP:usercopy_warn | 1 | | | |
| invoked_oom-killer:gfp_mask=0x | 1 | | | |
| Mem-Info | 1 | | | |
| WARNING:at_drivers/base/core.c:#device_links_supplier_sync_state_resume | 0 | 11 | 11 | 11 |
| RIP:device_links_supplier_sync_state_resume | 0 | 11 | 11 | 11 |
+-------------------------------------------------------------------------+------------+------------+------------+---------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <lkp(a)intel.com>
[ 26.905004] i2c i2c-1: Added multiplexed i2c bus 3
[ 26.917068] ### dt-test ### FAIL of_unittest_overlay_high_level():2380 overlay_base_root not initialized
[ 26.920311] ### dt-test ### end of unittest - 219 passed, 1 failed
[ 26.922504] ------------[ cut here ]------------
[ 26.924102] Unmatched sync_state pause/resume!
[ 26.924192] WARNING: CPU: 0 PID: 1 at drivers/base/core.c:691 device_links_supplier_sync_state_resume+0x140/0x160
[ 26.929493] Modules linked in:
[ 26.930681] CPU: 0 PID: 1 Comm: swapper Tainted: G T 5.3.0-rc1-00025-g21871a99b34c6 #1
[ 26.933665] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 26.936451] RIP: 0010:device_links_supplier_sync_state_resume+0x140/0x160
[ 26.938611] Code: 84 c0 49 8d 84 24 c8 00 00 00 0f 85 48 ff ff ff 49 8d 94 24 d0 00 00 00 48 89 55 d0 eb 86 48 c7 c7 c0 30 be 83 e8 10 c0 e5 fe <0f> 0b 48 c7 c7 80 33 c4 84 e8 12 19 d0 00 48 83 c4 10 5b 41 5c 41
[ 26.944420] RSP: 0018:ffff88801a397da8 EFLAGS: 00010286
[ 26.946213] RAX: 0000000000000022 RBX: b05332a62e1f2e76 RCX: 0000000000000000
[ 26.948487] RDX: 0000000000000022 RSI: ffffffff81276c83 RDI: 0000000000000246
[ 26.950858] RBP: ffff88801a397de0 R08: fffffbfff0aa192d R09: fffffbfff0aa192d
[ 26.953192] R10: ffff88801a397df0 R11: 0000000000000001 R12: 0000000000000000
[ 26.955411] R13: 00000000ffffffff R14: 1ffff11003472fc3 R15: ffff88801a397eb8
[ 26.957678] FS: 0000000000000000(0000) GS:ffffffff846b3000(0000) knlGS:0000000000000000
[ 26.960398] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 26.962374] CR2: 00007fb42acb9480 CR3: 000000000462a006 CR4: 00000000001606f0
[ 26.964683] Call Trace:
[ 26.965713] of_platform_sync_state_init+0x17/0x3a
[ 26.967381] ? of_core_init+0x16a/0x16a
[ 26.968769] do_one_initcall+0x103/0x295
[ 26.970179] ? trace_event_raw_event_initcall_finish+0x150/0x150
[ 26.972130] ? down_write+0xbe/0x100
[ 26.973467] ? __down_killable+0x260/0x260
[ 26.974933] ? __kasan_check_write+0x1f/0x30
[ 26.976433] kernel_init_freeable+0x232/0x349
[ 26.978003] ? rest_init+0xd0/0xd0
[ 26.979274] kernel_init+0xe/0x120
[ 26.980580] ? rest_init+0xd0/0xd0
[ 26.981870] ret_from_fork+0x24/0x30
[ 26.983168] ---[ end trace fa753e8363323d3d ]---
[ 26.991111] Freeing unused decrypted memory: 2040K
# HH:MM RESULT GOOD BAD GOOD_BUT_DIRTY DIRTY_NOT_BAD
git bisect start b1645c0cbd486ccebf76e0c3d4d2439f846316b0 609488bc979f99f805f34e9a32c1e3b71179d10b --
git bisect good 41f15b7fcd6a55ce02d7e4a353031a96f1df61b2 # 06:37 G 10 0 1 1 Merge remote-tracking branch 'mips/mips-next'
git bisect good 10cf4ad21d712fe3f90b187503661a5fa7163280 # 07:04 G 10 0 1 1 Merge remote-tracking branch 'input/next'
git bisect bad d6c8a0a14a98ea15fe01c46a04d458d86655f489 # 07:52 B 0 2 18 0 Merge remote-tracking branch 'soundwire/next'
git bisect good ddcfc1ce636ad25269b027f2df88d171e96b4d91 # 09:07 G 11 0 1 1 Merge remote-tracking branch 'tip/auto-latest'
git bisect good 625cf0c4b86f06bd96e270862251fb2f3bd7a8bd # 10:24 G 10 0 1 1 Merge remote-tracking branch 'leds/for-next'
git bisect bad 093afe985f8ffd11b7b63289a70281c9fa66ce58 # 01:15 B 0 1 17 0 Merge remote-tracking branch 'usb/usb-next'
git bisect good dd0937eff2a7dc19716b1829cfac132049c51e46 # 19:38 G 10 0 2 2 Merge remote-tracking branch 'ipmi/for-next'
git bisect bad 90bb1c44123da5b5d43335bc2f7c26407042c14a # 20:22 B 0 3 19 0 Merge remote-tracking branch 'driver-core/driver-core-next'
git bisect good 134b23eec9e3a3c795a6ceb0efe2fa63e87983b2 # 22:50 G 11 0 3 3 driver core: Add edit_links() callback for drivers
git bisect bad 97e2551de3f91add297c1dc4c9dc95297eaadf12 # 12:54 B 0 1 17 0 Merge tag 'dev_groups_all_drivers' into driver-core-next
git bisect bad 21871a99b34c65c56a24193c277a4981529c306f # 13:41 B 0 1 17 0 of/platform: Pause/resume sync state during init and of_platform_populate()
git bisect good 8f8184d6bf676a8680d6f441e40317d166b46f73 # 14:10 G 10 0 4 4 driver core: Add sync_state driver/bus callback
# first bad commit: [21871a99b34c65c56a24193c277a4981529c306f] of/platform: Pause/resume sync state during init and of_platform_populate()
git bisect good 8f8184d6bf676a8680d6f441e40317d166b46f73 # 14:22 G 30 0 5 9 driver core: Add sync_state driver/bus callback
# extra tests on HEAD of linux-next/master
git bisect bad b1645c0cbd486ccebf76e0c3d4d2439f846316b0 # 14:22 B 1 368 0 0 Add linux-next specific files for 20190805
# extra tests on tree/branch driver-core/driver-core-testing
git bisect bad 5adf5781019dd21233d6d13ab0d78bf03a13d4f1 # 14:48 B 0 3 19 0 of/platform: Fix device_links_supplier_sync_state_resume() warning
# extra tests on tree/branch linux-next/master
git bisect bad 3880be629e26f6c407593602398c6651860d5fae # 15:20 B 0 2 18 0 Add linux-next specific files for 20190807
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation
1 year, 5 months
[btrfs] 06297d8cef: fio hangs
by kernel test robot
FYI, we noticed the following commit (built with gcc-7):
commit: 06297d8cefcaa2029c4cb71b79285d2bfff06d4d ("btrfs: switch
extent_buffer blocking_writers from atomic to int")
https://kernel.googlesource.com/pub/scm/linux/kernel/git/torvalds/linux.git
master
in testcase: fio-basic
on test machine: Intel(R) Xeon(R) CPU @ 2.30GHz with 128G memory
with following parameters:
rw: randwrite
bs: 4k
ioengine: sync
caused below changes (please refer to attached dmesg/kmsg for entire
log/backtrace):
[ 34.311829] 2019-08-07 11:58:01 echo '[global]
[ 34.311830]
[ 34.318517] bs=4k
[ 34.318517]
[ 34.322805] ioengine=sync
[ 34.322805]
[ 34.327737] iodepth=32
[ 34.327738]
[ 34.332492] size=1431655765
[ 34.332493]
[ 34.337560] direct=0
[ 34.337561]
[ 34.342045] runtime=300
[ 34.342046]
[ 34.346783] invalidate=1
[ 34.346784]
[ 34.351665] fallocate=posix
[ 34.351666]
[ 34.356790] group_reporting
[ 34.356791]
[ 34.361662]
[ 34.363592] [task_0]
[ 34.363593]
[ 34.368050] rw=randwrite
[ 34.368051]
[ 34.372937] directory=/fs/sdd1
[ 34.372938]
[ 34.378767] numjobs=96' | fio --output-format=json -
[ 34.378768]
[ 187.562008] perf: interrupt took too long (2520 > 2500), lowering
kernel.perf_event_max_sample_rate to 79000
[ 188.486146] perf: interrupt took too long (3163 > 3150), lowering
kernel.perf_event_max_sample_rate to 63000
[ 189.763008] perf: interrupt took too long (3956 > 3953), lowering
kernel.perf_event_max_sample_rate to 50000
[ 194.385019] perf: interrupt took too long (4946 > 4945), lowering
kernel.perf_event_max_sample_rate to 40000
[ 194.688010] WARNING: can't dereference registers at 0000000021c3c486
for ip interrupt_entry+0xc4/0x100
Starting Update UTMP about System Runlevel Changes...
Starting watchdog daemon...
[ 1542.201214] Wed Aug 7 12:23:11 CST 2019 detected soft_timeout
[ 1542.201216]
[ 1542.225285] kill 2409 /usr/bin/time -v -o /tmp/lkp/fio.time
/lkp/lkp/src/tests/fio
[ 1542.225287]
[ 1542.287150] /usr/bin/wget -q --timeout=1800 --tries=1
--local-encoding=UTF-8
http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/sche...
-O /dev/null
[ 1542.287152]
[ 1542.613409] Wed Aug 7 12:23:11 CST 2019 wait_job_finished --timeout 60
[ 1542.613411]
[ 1542.803940] Terminated
[ 1542.803942]
[ 1543.616604] kill 1975 vmstat --timestamp -n 10
[ 1543.616606]
[ 1543.623224] kill 1971 iostat -tkx 1 /dev/sdd
[ 1543.623225]
[ 1543.629617] kill 1966 dmesg --follow --decode
[ 1543.629618]
[ 1543.636123] kill 1980 vmstat --timestamp -n 1
[ 1543.636124]
[ 1544.329205] wait for background processes: 2023 2138 2055 1989 2029
2155 1984 1994 2007 2089 2015 2073 2000 2118 2165 2049 2106 2129 2150
slabinfo mpstat softirqs numa-vmstat interrupts uptime numa-numastat
numa-meminfo proc-stat cpuidle meminfo diskstats proc-vmstat sched_debug
oom-killer latency_stats turbostat perf-stat perf-profile
[ 1544.329207]
[ 1546.577996] umount: /fs/sdd1: target is busy
[ 1546.577998]
[ 1547.476297] (In some cases useful info about processes that
[ 1547.476298]
[ 1547.560117] use the device is found by lsof(8) or fuser(1).)
[ 1547.560118]
[ 1550.398285] /usr/bin/wget -q --timeout=1800 --tries=1
--local-encoding=UTF-8
http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/sche...
-O /dev/null
[ 1550.398287]
[ 1550.441061] /usr/bin/wget -q --timeout=1800 --tries=1
--local-encoding=UTF-8
http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/sche...
-O /dev/null
[ 1550.441062]
[ 1602.613268] Wed Aug 7 12:24:11 CST 2019 sleep 141
[ 1602.613270]
[ 1743.615203] Wed Aug 7 12:26:32 CST 2019 try to force reboot
[ 1743.615204]
Stopping watchdog daemon...
Unmounting RPC Pipe File System...
Stopping NFS status monitor for NFSv2/3 locking....
Stopping OpenBSD Secure Shell server...
Stopping System Logging Service...
Stopping LSB: Start and stop bmc-watchdog...
Stopping Login Service...
Stopping D-Bus System Message Bus...
Stopping Regular background program processing daemon...
Stopping Getty on tty1...
Stopping LSB: Load kernel image with kexec...
Stopping Permit User Sessions...
Unmounting /inn/result...
Stopping LSB: Execute the kexec -e command to reboot system...
Stopping Load/Save Random Seed...
Stopping Network Time Synchronization...
Stopping Update UTMP about System Boot/Shutdown...
Stopping Raise network interfaces...
Unmounting /tmp...
Unmounting /opt/rootfs...
Unmounting /fs/sdd1...
[ 1834.925026] systemd-journald[778]: Failed to send WATCHDOG=1
notification message: Connection refused
[ 1888.266366] sysrq: Show Blocked State
[ 1888.270063] task PC stack pid father
[ 1888.276016] systemd D 0 1 0 0x80004000
[ 1888.281540] Call Trace:
[ 1888.284014] ? __schedule+0x255/0x670
[ 1888.287702] ? flush_old_exec+0xaf/0x760
[ 1888.291643] schedule+0x34/0xb0
[ 1888.294803] flush_old_exec+0xe4/0x760
[ 1888.298577] load_elf_binary+0x32d/0x1180
[ 1888.302606] ? _cond_resched+0x19/0x30
[ 1888.306374] search_binary_handler+0x91/0x1e0
[ 1888.310752] __do_execve_file+0x761/0x940
[ 1888.315473] __x64_sys_execve+0x34/0x40
[ 1888.319330] do_syscall_64+0x5b/0x1e0
[ 1888.323011] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1888.328085] RIP: 0033:0x7f25fd43a647
[ 1888.331680] Code: Bad RIP value.
[ 1888.334925] RSP: 002b:00007ffc13c11e18 EFLAGS: 00000202 ORIG_RAX:
000000000000003b
[ 1888.342508] RAX: ffffffffffffffda RBX: 0000000000000007 RCX:
00007f25fd43a647
[ 1888.349658] RDX: 0000561320ceaf30 RSI: 00007ffc13c11fe0 RDI:
00005613206fc4d0
[ 1888.356805] RBP: 00007ffc13c120a0 R08: 0000561320ceb000 R09:
0000561320cfa700
[ 1888.363954] R10: 00007f25fee92500 R11: 0000000000000202 R12:
0000000000000001
[ 1888.371106] R13: 00005613207661e0 R14: 00007ffc13c11fe0 R15:
0000000000000000
[ 1888.378261] systemd D 0 40005 0 0x00000004
[ 1888.383762] Call Trace:
[ 1888.386231] ? __schedule+0x255/0x670
[ 1888.389907] schedule+0x34/0xb0
[ 1888.393066] ? rwsem_down_write_failed+0x1b5/0x410
[ 1888.397873] rwsem_down_write_failed+0x1ba/0x410
[ 1888.402507] ? _cond_resched+0x19/0x30
[ 1888.406280] ? default_file_splice_write+0x20/0x20
[ 1888.411089] ? down_write+0x4c/0x50
[ 1888.414595] down_write+0x4c/0x50
[ 1888.417921] sync_inodes_sb+0xbe/0x310
[ 1888.421690] ? free_one_page+0x169/0x4c0
[ 1888.425631] ? default_file_splice_write+0x20/0x20
[ 1888.430447] iterate_supers+0x9f/0x110
[ 1888.434218] ksys_sync+0x40/0xb0
[ 1888.437465] __ia32_sys_sync+0xa/0x10
[ 1888.441139] do_syscall_64+0x5b/0x1e0
[ 1888.444818] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1888.449888] RIP: 0033:0x7f25fd4637f7
[ 1888.453485] Code: Bad RIP value.
[ 1888.456728] RSP: 002b:00007f25fb714d08 EFLAGS: 00000202 ORIG_RAX:
00000000000000a2
[ 1888.464313] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
00007f25fd4637f7
[ 1888.471464] RDX: 48d62f35817dccf0 RSI: 0000000000000000 RDI:
0000000000000000
[ 1888.478611] RBP: 0000000000000000 R08: 00007f25fb715700 R09:
00007f25fb715700
[ 1888.486143] R10: 00000000000003de R11: 0000000000000202 R12:
00007ffc13c1176e
[ 1888.493618] R13: 00007ffc13c1176f R14: 00007f25faf15000 R15:
0000000000000003
[ 1888.501411] kworker/u194:0 D 0 135 2 0x80004000
[ 1888.507269] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
[ 1888.514401] Call Trace:
[ 1888.517197] ? __schedule+0x255/0x670
[ 1888.521222] ? _raw_spin_lock_irqsave+0x37/0x40
[ 1888.526104] schedule+0x34/0xb0
[ 1888.529617] btrfs_tree_lock+0x100/0x1d0 [btrfs]
[ 1888.534591] ? finish_wait+0x80/0x80
[ 1888.538527] btrfs_lock_root_node+0x2f/0x40 [btrfs]
[ 1888.543769] btrfs_search_slot+0x54e/0x9a0 [btrfs]
[ 1888.548918] ? _cond_resched+0x19/0x30
[ 1888.553036] btrfs_mark_extent_written+0xb9/0xc60 [btrfs]
[ 1888.558804] ? merge_state+0x3f/0x160 [btrfs]
[ 1888.564219] ? _cond_resched+0x19/0x30
[ 1888.568330] ? join_transaction+0x24/0x440 [btrfs]
[ 1888.573491] btrfs_finish_ordered_io+0x5a0/0x860 [btrfs]
[ 1888.579156] ? syscall_return_via_sysret+0x10/0x7f
[ 1888.584298] ? syscall_return_via_sysret+0xf/0x7f
[ 1888.589356] normal_work_helper+0x83/0x340 [btrfs]
[ 1888.594494] ? move_linked_works+0x6e/0xa0
[ 1888.598937] process_one_work+0x19c/0x3c0
[ 1888.603287] worker_thread+0x3c/0x3b0
[ 1888.607284] ? process_one_work+0x3c0/0x3c0
[ 1888.611807] kthread+0x11e/0x140
[ 1888.615368] ? kthread_park+0x90/0x90
[ 1888.619365] ret_from_fork+0x1f/0x40
[ 1888.624531] kworker/u194:1 D 0 1068 2 0x80004000
To reproduce:
git clonehttps://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
Thanks,
Rong Chen
1 year, 5 months