Greeting, FYI, we noticed a -2.8% regression of reaim.jobs_per_min due to commit: commit: 4c1379d7bb42fa664e0784539208ed74108c53f1 ("ACPICA: Debug output: Add option to display method/object evaluation") https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master in testcase: ftq on test machine: 256 threads Phi with 96G memory with following parameters: nr_task: 100% samples: 6000ss test: cache freq: 20 cpufreq_governor: performance test-description: The FTQ benchmarks measure hardware and software interference or 'noise' on a node from the applications perspective. test-url: https://github.com/rminnich/ftq In addition to that, the commit also has significant impact on the following tests: +------------------+---------------------------------------------------------------------------+ | testcase: change | perf_test: perf_test.msr_test.round1.cpu_util_zero.pass -100.0% undefined | | test machine | 72 threads Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz with 128G memory | | test parameters | type=lkp | | | ucode=0x3d | +------------------+---------------------------------------------------------------------------+ 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/nr_job/nr_task/rootfs/runtime/tbox_group/test/testcase/ucode: gcc-7/performance/x86_64-rhel-7.2/1500/100%/debian-x86_64-2018-04-03.cgz/300s/lkp-hsw-ep2/all_utime/reaim/0x3d commit: 73a049a90f ("ACPICA: disassembler: disassemble OEMx tables as AML") 4c1379d7bb ("ACPICA: Debug output: Add option to display method/object evaluation") 73a049a90fb241af 4c1379d7bb42fa664e07845392 ---------------- -------------------------- %stddev %change %stddev \ | \ 0.07 ± 3% +20.2% 0.09 ± 12% reaim.child_systime 308866 -2.8% 300200 reaim.jobs_per_min 4289 -2.8% 4169 reaim.jobs_per_min_child 314258 -2.7% 305679 reaim.max_jobs_per_min 20.93 +2.9% 21.53 reaim.parent_time 0.44 ± 9% +84.5% 0.82 ± 6% reaim.std_dev_percent 0.09 ± 9% +83.7% 0.17 ± 6% reaim.std_dev_time 321.38 -4.7% 306.29 reaim.time.elapsed_time 321.38 -4.7% 306.29 reaim.time.elapsed_time.max 127264 ± 2% +40.6% 178887 reaim.time.involuntary_context_switches 93024 ± 2% -8.4% 85173 reaim.time.minor_page_faults 6448 -2.6% 6282 reaim.time.percent_of_cpu_this_job_got 20724 -7.2% 19241 reaim.time.user_time 4929 -6.9% 4591 reaim.time.voluntary_context_switches 1512000 -7.1% 1404000 reaim.workload 442.00 ±158% -100.0% 0.00 meminfo.Mlocked 0.03 ± 2% +0.1 0.11 mpstat.cpu.sys% 1231 +56.9% 1932 ± 3% vmstat.system.cs 63.75 ±158% -100.0% 0.00 numa-vmstat.node0.nr_mlock 46.25 ±159% -100.0% 0.00 numa-vmstat.node1.nr_mlock 1.50 ± 15% -0.3 1.24 ± 15% perf-stat.overall.cache-miss-rate% 50.13 ± 3% +6.4 56.58 ± 5% perf-stat.overall.iTLB-load-miss-rate% 566199 ± 6% -23.7% 432237 ± 7% perf-stat.overall.instructions-per-iTLB-miss 59.86 ± 3% -23.1 36.79 ± 10% perf-stat.overall.node-store-miss-rate% 6653969 ± 8% +25.4% 8340919 ± 14% perf-stat.ps.cache-references 1202 +56.7% 1884 ± 4% perf-stat.ps.context-switches 185718 ± 5% +28.9% 239386 ± 7% perf-stat.ps.iTLB-load-misses 2755 -1.5% 2713 perf-stat.ps.minor-faults 22055 ± 22% -41.6% 12879 ± 11% perf-stat.ps.node-store-misses 14552 ± 12% +53.3% 22311 ± 14% perf-stat.ps.node-stores 2755 -1.5% 2713 perf-stat.ps.page-faults 3.414e+13 -7.1% 3.172e+13 perf-stat.total.instructions 69181 -1.7% 67973 proc-vmstat.nr_active_anon 6177 +4.6% 6461 proc-vmstat.nr_mapped 109.50 ±159% -100.0% 0.00 proc-vmstat.nr_mlock 69181 -1.7% 67973 proc-vmstat.nr_zone_active_anon 17125 ± 10% -55.2% 7668 ± 20% proc-vmstat.numa_hint_faults 4847 ± 80% -81.0% 920.75 ± 85% proc-vmstat.numa_hint_faults_local 799546 -5.8% 753399 proc-vmstat.numa_hit 785482 -5.9% 739309 proc-vmstat.numa_local 63641 ± 34% -57.8% 26863 ± 93% proc-vmstat.numa_pte_updates 861155 -5.6% 812594 proc-vmstat.pgalloc_normal 922986 -6.5% 863086 proc-vmstat.pgfault 833697 -5.8% 785608 proc-vmstat.pgfree 17.88 ± 5% -4.2 13.72 ± 21% perf-profile.calltrace.cycles-pp.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues 8.65 ± 10% -2.8 5.83 ± 26% perf-profile.calltrace.cycles-pp.clockevents_program_event.hrtimer_interrupt.smp_apic_timer_interrupt.apic_timer_interrupt 3.81 ± 39% -1.9 1.89 ± 30% perf-profile.calltrace.cycles-pp.ktime_get.clockevents_program_event.hrtimer_interrupt.smp_apic_timer_interrupt.apic_timer_interrupt 4.05 ± 6% -1.3 2.72 ± 25% perf-profile.calltrace.cycles-pp.ktime_get_update_offsets_now.hrtimer_interrupt.smp_apic_timer_interrupt.apic_timer_interrupt 3.42 ±100% -1.3 2.11 ±173% perf-profile.calltrace.cycles-pp.irq_work_interrupt 3.42 ±100% -1.3 2.11 ±173% perf-profile.calltrace.cycles-pp.smp_irq_work_interrupt.irq_work_interrupt 3.40 ±100% -1.3 2.11 ±173% perf-profile.calltrace.cycles-pp.irq_work_run_list.irq_work_run.smp_irq_work_interrupt.irq_work_interrupt 3.40 ±100% -1.3 2.11 ±173% perf-profile.calltrace.cycles-pp.irq_work_run.smp_irq_work_interrupt.irq_work_interrupt 3.40 ±100% -1.1 2.27 ±173% perf-profile.calltrace.cycles-pp.printk.irq_work_run_list.irq_work_run.smp_irq_work_interrupt.irq_work_interrupt 3.40 ±100% -1.1 2.27 ±173% perf-profile.calltrace.cycles-pp.vprintk_emit.printk.irq_work_run_list.irq_work_run.smp_irq_work_interrupt 3.40 ±100% -1.1 2.27 ±173% perf-profile.calltrace.cycles-pp.console_unlock.vprintk_emit.printk.irq_work_run_list.irq_work_run 3.38 ±100% -1.1 2.30 ±173% perf-profile.calltrace.cycles-pp.secondary_startup_64 3.38 ±100% -1.1 2.30 ±173% perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64 3.38 ±100% -1.1 2.30 ±173% perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64 3.37 ±100% -1.1 2.30 ±173% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64 3.33 ±100% -1.0 2.29 ±173% perf-profile.calltrace.cycles-pp.cpuidle_enter_state.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64 3.29 ±101% -1.0 2.29 ±173% perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.do_idle.cpu_startup_entry.start_secondary 2.59 ± 13% -0.8 1.78 ± 20% perf-profile.calltrace.cycles-pp.__update_load_avg_se.task_tick_fair.scheduler_tick.update_process_times.tick_sched_handle 1.37 ± 11% -0.7 0.65 ± 64% perf-profile.calltrace.cycles-pp.timerqueue_del.__remove_hrtimer.__hrtimer_run_queues.hrtimer_interrupt.smp_apic_timer_interrupt 2.93 ±101% -0.7 2.21 ±173% perf-profile.calltrace.cycles-pp.serial8250_console_write.console_unlock.vprintk_emit.printk.irq_work_run_list 2.04 ± 13% -0.7 1.35 ± 30% perf-profile.calltrace.cycles-pp.update_curr.task_tick_fair.scheduler_tick.update_process_times.tick_sched_handle 0.80 ± 16% -0.5 0.30 ±100% perf-profile.calltrace.cycles-pp._raw_spin_lock_irq.__hrtimer_run_queues.hrtimer_interrupt.smp_apic_timer_interrupt.apic_timer_interrupt 0.00 +5.5e+11% 5530 ±110% sched_debug.cfs_rq:/.MIN_vruntime.avg 12338 +45.3% 17924 ± 7% sched_debug.cfs_rq:/.load.avg 39464 ± 43% +709.9% 319609 ± 46% sched_debug.cfs_rq:/.load.max 5132 ± 59% +704.6% 41295 ± 41% sched_debug.cfs_rq:/.load.stddev 299.73 ± 28% +60.1% 479.92 ± 19% sched_debug.cfs_rq:/.load_avg.max 52.90 ± 37% +48.5% 78.55 ± 11% sched_debug.cfs_rq:/.load_avg.stddev 0.00 +5.5e+11% 5530 ±110% sched_debug.cfs_rq:/.max_vruntime.avg 56400 ± 32% +258.5% 202169 ± 5% sched_debug.cfs_rq:/.min_vruntime.stddev 0.08 ± 13% +26.3% 0.10 ± 11% sched_debug.cfs_rq:/.nr_running.stddev 11.16 ± 6% +26.1% 14.08 ± 4% sched_debug.cfs_rq:/.runnable_load_avg.avg 34.70 ± 30% +486.6% 203.54 ± 30% sched_debug.cfs_rq:/.runnable_load_avg.max 3.74 ± 31% +599.1% 26.17 ± 30% sched_debug.cfs_rq:/.runnable_load_avg.stddev 12213 +46.1% 17837 ± 7% sched_debug.cfs_rq:/.runnable_weight.avg 35964 ± 43% +788.0% 319358 ± 46% sched_debug.cfs_rq:/.runnable_weight.max 4732 ± 62% +770.0% 41175 ± 42% sched_debug.cfs_rq:/.runnable_weight.stddev 40678 ±144% +3754.8% 1568088 ± 2% sched_debug.cfs_rq:/.spread0.avg 127330 ± 55% +1238.0% 1703696 ± 3% sched_debug.cfs_rq:/.spread0.max -87205 -98.1% -1677 sched_debug.cfs_rq:/.spread0.min 56217 ± 32% +259.5% 202080 ± 5% sched_debug.cfs_rq:/.spread0.stddev 698851 ± 8% -16.4% 584422 ± 9% sched_debug.cpu.avg_idle.min 165933 ± 7% +13.4% 188123 sched_debug.cpu.clock.avg 165941 ± 7% +13.4% 188129 sched_debug.cpu.clock.max 165919 ± 7% +13.4% 188115 sched_debug.cpu.clock.min 5.35 ± 23% -32.9% 3.59 ± 7% sched_debug.cpu.clock.stddev 165933 ± 7% +13.4% 188123 sched_debug.cpu.clock_task.avg 165941 ± 7% +13.4% 188129 sched_debug.cpu.clock_task.max 165919 ± 7% +13.4% 188115 sched_debug.cpu.clock_task.min 5.35 ± 23% -32.9% 3.59 ± 7% sched_debug.cpu.clock_task.stddev 11.33 ± 4% +19.3% 13.51 ± 9% sched_debug.cpu.cpu_load[0].avg 38.97 ± 28% +418.2% 201.92 ± 30% sched_debug.cpu.cpu_load[0].max 4.46 ± 41% +443.0% 24.23 ± 33% sched_debug.cpu.cpu_load[0].stddev 11.43 ± 4% +17.6% 13.44 ± 8% sched_debug.cpu.cpu_load[1].avg 37.25 ± 26% +418.9% 193.29 ± 30% sched_debug.cpu.cpu_load[1].max 4.08 ± 36% +463.5% 23.00 ± 35% sched_debug.cpu.cpu_load[1].stddev 11.49 ± 4% +16.2% 13.34 ± 7% sched_debug.cpu.cpu_load[2].avg 35.41 ± 21% +398.6% 176.54 ± 30% sched_debug.cpu.cpu_load[2].max 3.74 ± 31% +460.0% 20.96 ± 34% sched_debug.cpu.cpu_load[2].stddev 34.54 ± 14% +336.3% 150.71 ± 21% sched_debug.cpu.cpu_load[3].max 3.51 ± 22% +407.6% 17.84 ± 27% sched_debug.cpu.cpu_load[3].stddev 55.55 +164.1% 146.71 ± 15% sched_debug.cpu.cpu_load[4].max 5.57 ± 6% +202.7% 16.85 ± 18% sched_debug.cpu.cpu_load[4].stddev 4396 ± 6% +13.1% 4974 ± 7% sched_debug.cpu.curr->pid.avg 3517 ± 17% -47.9% 1832 ± 34% sched_debug.cpu.curr->pid.min 305.14 ± 37% +98.3% 604.98 ± 22% sched_debug.cpu.curr->pid.stddev 12364 +39.5% 17254 ± 14% sched_debug.cpu.load.avg 39007 ± 44% +721.4% 320411 ± 46% sched_debug.cpu.load.max 5044 ± 63% +681.3% 39414 ± 48% sched_debug.cpu.load.stddev 133158 ± 9% +16.9% 155714 sched_debug.cpu.nr_load_updates.avg 140928 ± 9% +15.6% 162887 sched_debug.cpu.nr_load_updates.max 1369 ± 37% +66.8% 2283 ± 4% sched_debug.cpu.nr_load_updates.stddev 0.19 ± 3% +22.7% 0.23 ± 15% sched_debug.cpu.nr_running.stddev 3143 ± 6% +52.3% 4788 ± 3% sched_debug.cpu.nr_switches.avg 11472 ± 19% +67.3% 19197 ± 3% sched_debug.cpu.nr_switches.max 2464 ± 19% +73.5% 4275 ± 6% sched_debug.cpu.nr_switches.stddev 165920 ± 7% +13.4% 188116 sched_debug.cpu_clk 162590 ± 7% +13.6% 184783 sched_debug.ktime 167206 ± 6% +13.6% 189868 sched_debug.sched_clk ftq.time.involuntary_context_switches 260000 +-+----------------------------------------------------------------+ |O | 240000 +-+ O | 220000 O-+ O O | | O O O O O | 200000 +-+ O | 180000 +-+ O OO OO OO O OOO O OO OO OO OO | O O O | 160000 +-+ O OOO O O O O O O | 140000 +-+ O O O | | | 120000 +-+ + | 100000 +-+ +. +. .+ :+ | |+.+ ++.++.++.++ ++.++ +.+ ++.+++.++.++.++.++.+++.++ | 80000 +-+----------------------------------------------------------------+ [*] bisect-good sample [O] bisect-bad sample *************************************************************************************************** lkp-hsw-ep2: 72 threads Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz with 128G memory ========================================================================================= compiler/kconfig/rootfs/tbox_group/testcase/type/ucode: gcc-7/x86_64-rhel-7.2/debian-x86_64-2018-04-03.cgz/lkp-hsw-ep2/perf_test/lkp/0x3d commit: 73a049a90f ("ACPICA: disassembler: disassemble OEMx tables as AML") 4c1379d7bb ("ACPICA: Debug output: Add option to display method/object evaluation") 73a049a90fb241af 4c1379d7bb42fa664e07845392 ---------------- -------------------------- fail:runs %reproduction fail:runs | | | :8 100% 8:8 perf_test.msr_test.round1.cpu_util_zero.fail %stddev %change %stddev \ | \ 1.00 -100.0% 0.00 perf_test.msr_test.round1.cpu_util_zero.pass 1432 +13.1% 1620 ± 3% perf_test.time.elapsed_time 1432 +13.1% 1620 ± 3% perf_test.time.elapsed_time.max 43385 -6.9% 40403 ± 2% perf_test.time.involuntary_context_switches 76.62 ± 2% +16.3% 89.12 ± 2% perf_test.time.percent_of_cpu_this_job_got 295.24 +17.2% 346.06 ± 13% perf_test.time.system_time 810.50 +36.5% 1106 ± 2% perf_test.time.user_time 360596 +43.1% 515953 ± 17% perf_test.time.voluntary_context_switches 16568 +46.1% 24206 meminfo.Inactive(anon) 30398 +16.8% 35515 meminfo.Mapped 1843 ± 10% +9.1% 2010 ± 7% meminfo.Mlocked 19473 +39.3% 27124 meminfo.Shmem 2897 -11.6% 2561 ± 3% meminfo.max_used_kB 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