Re: [init/console] a91bd6223e: unixbench.score -5.9% regression

[Petr Mladek]

Hello,

just for record.

On Tue 2021-02-09 13:49:25, kernel test robot wrote:
> 
> Greeting,
> 
> FYI, we noticed a -5.9% regression of unixbench.score due to commit:
> 
> 
> commit: a91bd6223ecd46addc71ee6fcd432206d39365d2 ("Revert "init/console: Use ttynull as a fallback when there is no console"")
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> 
> 
> in testcase: unixbench
> on test machine: 16 threads Intel(R) Xeon(R) E-2278G CPU @ 3.40GHz with 32G memory
> with following parameters:
> 
> 	runtime: 300s
> 	nr_task: 30%
> 	test: dhry2reg
> 	cpufreq_governor: performance
> 	ucode: 0xde
> 
> test-description: UnixBench is the original BYTE UNIX benchmark suite aims to test performance of Unix-like system.
> test-url: https://github.com/kdlucas/byte-unixbench
> 
> 
> 
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
> 
> 
> 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 split-job --compatible job.yaml
>         bin/lkp run                    compatible-job.yaml
> 
> =========================================================================================
> compiler/cpufreq_governor/kconfig/nr_task/rootfs/runtime/tbox_group/test/testcase/ucode:
>   gcc-9/performance/x86_64-rhel-8.3/30%/debian-10.4-x86_64-20200603.cgz/300s/lkp-cfl-e1/dhry2reg/unixbench/0xde
> 
> commit: 
>   c4cc3b1de3 ("Merge tag 'gcc-plugins-v5.11-rc3' of git://git.kernel.org/pub/scm/linux/kernel/git/kees/linux")
>   a91bd6223e ("Revert "init/console: Use ttynull as a fallback when there is no console"")
> 
> c4cc3b1de31b76f4 a91bd6223ecd46addc71ee6fcd4 
> ---------------- --------------------------- 
>        fail:runs  %reproduction    fail:runs
>            |             |             |    
>           0:4            2%           0:4     perf-profile.children.cycles-pp.error_entry
>          %stddev     %change         %stddev
>              \          |                \  
>      19487            -5.9%      18336        unixbench.score
>  8.875e+10            -5.9%  8.351e+10        unixbench.workload
>       0.50            +0.1        0.61 ±  3%  mpstat.cpu.all.irq%
>      44280 ±  4%     +15.9%      51322 ±  3%  softirqs.CPU0.SCHED
>      29624 ±  3%      +9.6%      32476        vmstat.system.in

>       2207 ±1927%   +3559.5%      80796 ± 18%  sched_debug.cfs_rq:/.spread0.avg
>     135343 ± 38%     +61.1%     218075 ± 16%  sched_debug.cfs_rq:/.spread0.max
>       0.01 ± 31%     +78.3%       0.01 ± 22%  perf-sched.sch_delay.avg.ms.do_nanosleep.hrtimer_nanosleep.__x64_sys_nanosleep.do_syscall_64
>       0.01 ±  7%     +22.8%       0.02 ±  2%  perf-sched.sch_delay.avg.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
>       0.02 ± 15%     +27.1%       0.02 ± 11%  perf-sched.sch_delay.avg.ms.do_wait.kernel_wait4.__do_sys_wait4.do_syscall_64
>       0.02 ± 44%    +113.3%       0.04 ± 12%  perf-sched.sch_delay.avg.ms.exit_to_user_mode_prepare.syscall_exit_to_user_mode.entry_SYSCALL_64_after_hwframe.[unknown]
>       0.02 ± 10%     +56.1%       0.03 ± 25%  perf-sched.sch_delay.avg.ms.schedule_hrtimeout_range_clock.poll_schedule_timeout.constprop.0.do_select
>       0.02 ± 44%    +113.3%       0.04 ± 12%  perf-sched.sch_delay.max.ms.exit_to_user_mode_prepare.syscall_exit_to_user_mode.entry_SYSCALL_64_after_hwframe.[unknown]
>       0.01 ± 11%     +37.5%       0.01 ± 19%  perf-sched.total_sch_delay.average.ms
>       2001          +120.7%       4416 ± 33%  perf-sched.wait_and_delay.max.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
>       0.05 ± 54%     +56.5%       0.08 ±  7%  perf-sched.wait_time.avg.ms.schedule_timeout.khugepaged.kthread.ret_from_fork
>       2001          +120.7%       4416 ± 33%  perf-sched.wait_time.max.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
>       0.05 ± 54%     +56.5%       0.08 ±  7%  perf-sched.wait_time.max.ms.schedule_timeout.khugepaged.kthread.ret_from_fork

>       0.07 ±173%      +0.2        0.27 ± 21%  perf-profile.children.cycles-pp.io_serial_in
>       0.07 ±173%      +0.2        0.30 ± 21%  perf-profile.children.cycles-pp.serial8250_console_putchar
>       0.07 ±173%      +0.2        0.31 ± 20%  perf-profile.children.cycles-pp.wait_for_xmitr
>       0.08 ±173%      +0.2        0.32 ± 21%  perf-profile.children.cycles-pp.uart_console_write
>       0.08 ±173%      +0.2        0.33 ± 21%  perf-profile.children.cycles-pp.serial8250_console_write
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.asm_sysvec_irq_work
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.sysvec_irq_work
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.__sysvec_irq_work
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.irq_work_run
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.irq_work_single
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.printk
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.vprintk_emit
>       0.09 ±173%      +0.2        0.33 ± 22%  perf-profile.children.cycles-pp.console_unlock
>       0.09 ±173%      +0.3        0.34 ± 24%  perf-profile.children.cycles-pp.irq_work_run_list

The commit fixed regression in registration of console drivers.
A console was likely not registered before and saved some cycles.
But people want consoles ;-)

By other words, this regression is kind of expected.

Best Regards,
Petr