August 2019 - LKP - Ml01.01.Org

[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

2 years, 11 months

1
0
0 / 0

[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

2 years, 12 months

2
1
0 / 0

[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

2 years, 12 months

1
0
0 / 0

[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

3 years

1
0
0 / 0

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

3 years

1
0
0 / 0

[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

3 years

2
1
0 / 0

[x86/boot] 5b51ae969e: kexec boot failed

by kernel test robot

FYI, we noticed the following commit (built with gcc-7): commit: 5b51ae969e3d8ab0134ee3c98a769ad6d2cc2e24 ("x86/boot: Call get_rsdp_addr() after console_init()") https://kernel.googlesource.com/pub/scm/linux/kernel/git/torvalds/linux.git master in testcase: boot on test machine: Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz with 4G memory The commit broke kexec boot on physical machines, We have to set "nokaslr" to kernel cmdline to avoid the issue. Best Regards, Rong Chen

3 years

5
15
0 / 0

[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

3 years

1
0
0 / 0

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

3 years

2
1
0 / 0

[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

3 years

2
1
0 / 0

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

LKP August 2019