On Tue, Oct 11, 2022 at 11:03:39AM +0200, Paul Menzel wrote: > Dear Linux folks, > > > We boot our systems generally with the serial console enabled > `console=ttyS0,115200n8`, and noticed that initializing the console takes at > least one second. > > $ dmesg | grep -e 'DMI:' -e 'printk: console' > [ 0.000000] DMI: Dell Inc. PowerEdge R7525/05Y13N, BIOS 2.7.3 > 03/30/2022 > [ 2.691432] printk: console [tty0] enabled > [ 5.414384] printk: console [ttyS0] enabled > > $ dmesg | grep -e 'DMI:' -e 'printk:' > [ 0.000000] DMI: Dell Inc. Precision Tower 3620/0MWYPT, BIOS 2.22.0 > 07/13/2022 > [ 0.146953] printk: console [tty0] enabled > [ 1.374382] printk: console [ttyS0] enabled > > $ dmesg | grep -e 'DMI:' -e 'printk: console' > [ 0.000000] DMI: Dell Inc. PowerEdge R7425/08V001, BIOS 1.6.7 > 10/29/2018 > [ 1.589543] printk: console [tty0] enabled > [ 3.057770] printk: console [ttyS0] enabled > > $ dmesg | grep -e 'DMI:' -e 'printk: console' > [ 0.000000] DMI: HPE ProLiant DL385 Gen10 Plus/ProLiant DL385 Gen10 > Plus, BIOS A42 12/03/2021 > [ 5.171202] printk: console [tty0] enabled > [ 8.066602] printk: console [ttyS0] enabled > > `initcall_debug` shows: > > [ 0.190491] calling univ8250_console_init+0x0/0x2b @ 0 > [ 1.488645] printk: console [ttyS0] enabled > [ 1.492945] initcall univ8250_console_init+0x0/0x2b returned 0 after > 0 usecs > > (Note, that the “after time” by initcall does not match the timestamp at the > beginning.) > > Tracing with the trace *function* (`ftrace=function`) shows: > > <idle>-0 [000] ...2. 0.213187: univ8250_console_init > <-console_init > <idle>-0 [000] ...2. 0.213187: serial8250_isa_init_ports > <-univ8250_console_init > <idle>-0 [000] ...2. 0.213187: serial8250_init_port > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213187: init_timer_key > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213187: serial8250_set_defaults > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_init_port > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: init_timer_key > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_set_defaults > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_init_port > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: init_timer_key > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_set_defaults > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_init_port > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: init_timer_key > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213188: serial8250_set_defaults > <-serial8250_isa_init_ports > <idle>-0 [000] ...2. 0.213189: register_console > <-univ8250_console_init > <idle>-0 [000] ...2. 0.213189: > try_enable_preferred_console <-register_console > <idle>-0 [000] ...2. 0.213189: univ8250_console_match > <-try_enable_preferred_console > <idle>-0 [000] ...2. 0.213189: univ8250_console_setup > <-try_enable_preferred_console > <idle>-0 [000] ...2. 0.213189: serial8250_console_setup > <-univ8250_console_setup > <idle>-0 [000] ...2. 0.213189: uart_parse_options > <-serial8250_console_setup > <idle>-0 [000] ...2. 0.213190: uart_set_options > <-serial8250_console_setup > <idle>-0 [000] ...2. 0.213190: > tty_termios_encode_baud_rate <-uart_set_options > <idle>-0 [000] ...2. 0.213190: serial8250_set_termios > <-uart_set_options > <idle>-0 [000] ...2. 0.213191: serial8250_do_set_termios > <-uart_set_options > <idle>-0 [000] ...2. 0.213191: tty_get_char_size > <-serial8250_do_set_termios > <idle>-0 [000] ...2. 0.213191: uart_get_baud_rate > <-serial8250_do_set_termios > <idle>-0 [000] ...2. 0.213191: tty_termios_baud_rate > <-uart_get_baud_rate > <idle>-0 [000] ...2. 0.213191: serial8250_get_divisor > <-serial8250_do_set_termios > <idle>-0 [000] ...2. 0.213191: uart_get_divisor > <-serial8250_get_divisor > <idle>-0 [000] ...2. 0.213191: _raw_spin_lock_irqsave > <-serial8250_do_set_termios > <idle>-0 [000] d..2. 0.213192: preempt_count_add > <-_raw_spin_lock_irqsave > <idle>-0 [000] d..3. 0.213192: uart_update_timeout > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213192: tty_get_frame_size > <-uart_update_timeout > <idle>-0 [000] d..3. 0.213192: io_serial_out > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213195: serial8250_do_set_divisor > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213195: io_serial_out > <-serial8250_do_set_divisor > <idle>-0 [000] d..3. 0.213198: default_serial_dl_write > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213198: io_serial_out > <-default_serial_dl_write > <idle>-0 [000] d..3. 0.213201: io_serial_out > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213204: io_serial_out > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213207: io_serial_out > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213210: serial8250_do_set_mctrl > <-serial8250_do_set_termios > <idle>-0 [000] d..3. 0.213210: io_serial_out > <-serial8250_do_set_mctrl > <idle>-0 [000] d..3. 0.213213: > _raw_spin_unlock_irqrestore <-serial8250_do_set_termios > <idle>-0 [000] ...3. 0.213213: preempt_count_sub > <-_raw_spin_unlock_irqrestore > <idle>-0 [000] ...2. 0.213213: tty_termios_baud_rate > <-serial8250_do_set_termios > <idle>-0 [000] ...2. 0.213214: > tty_termios_encode_baud_rate <-serial8250_do_set_termios > <idle>-0 [000] ...2. 0.213214: console_lock > <-register_console > <idle>-0 [000] ...2. 0.213214: __cond_resched > <-console_lock > <idle>-0 [000] ...2. 0.213214: down <-console_lock > <idle>-0 [000] ...2. 0.213214: __cond_resched <-down > <idle>-0 [000] ...2. 0.213214: _raw_spin_lock_irqsave > <-down > <idle>-0 [000] d..2. 0.213214: preempt_count_add > <-_raw_spin_lock_irqsave > <idle>-0 [000] d..3. 0.213214: > _raw_spin_unlock_irqrestore <-console_lock > <idle>-0 [000] ...3. 0.213214: preempt_count_sub > <-_raw_spin_unlock_irqrestore > <idle>-0 [000] ...2. 0.213214: mutex_lock > <-register_console > <idle>-0 [000] ...2. 0.213215: __cond_resched > <-mutex_lock > <idle>-0 [000] ...2. 0.213215: mutex_unlock > <-register_console > <idle>-0 [000] ...2. 0.213215: console_unlock > <-register_console > <idle>-0 [000] ...2. 0.213215: > console_emit_next_record.constprop.0 <-console_unlock > <idle>-0 [000] ...2. 0.213215: prb_read_valid > <-console_emit_next_record.constprop.0 > <idle>-0 [000] ...2. 0.213215: _prb_read_valid > <-prb_read_valid > <idle>-0 [000] ...2. 0.213215: desc_read_finalized_seq > <-_prb_read_valid > <idle>-0 [000] ...2. 0.213215: > console_emit_next_record.constprop.0 <-console_unlock > <idle>-0 [000] ...2. 0.213215: prb_read_valid > <-console_emit_next_record.constprop.0 > <idle>-0 [000] ...2. 0.213215: _prb_read_valid > <-prb_read_valid > <idle>-0 [000] ...2. 0.213215: desc_read_finalized_seq > <-_prb_read_valid > <idle>-0 [000] ...2. 0.213216: get_data > <-_prb_read_valid > <idle>-0 [000] ...2. 0.213216: desc_read_finalized_seq > <-_prb_read_valid > <idle>-0 [000] ...2. 0.213216: record_print_text > <-console_emit_next_record.constprop.0 > <idle>-0 [000] ...2. 0.213216: info_print_prefix > <-record_print_text > <idle>-0 [000] d..2. 0.213216: __printk_safe_enter > <-console_emit_next_record.constprop.0 > <idle>-0 [000] d..2. 0.213216: _raw_spin_lock > <-console_emit_next_record.constprop.0 > <idle>-0 [000] d..2. 0.213216: preempt_count_add > <-_raw_spin_lock > <idle>-0 [000] d..3. 0.213216: _raw_spin_unlock > <-console_emit_next_record.constprop.0 > <idle>-0 [000] d..3. 0.213217: preempt_count_sub > <-_raw_spin_unlock > <idle>-0 [000] d..2. 0.213217: univ8250_console_write > <-console_emit_next_record.constprop.0 > <idle>-0 [000] d..2. 0.213217: serial8250_console_write > <-console_emit_next_record.constprop.0 > <idle>-0 [000] d..2. 0.213217: _raw_spin_lock_irqsave > <-serial8250_console_write > <idle>-0 [000] d..2. 0.213217: preempt_count_add > <-_raw_spin_lock_irqsave > <idle>-0 [000] d..3. 0.213217: io_serial_in > <-serial8250_console_write > <idle>-0 [000] d..3. 0.213220: io_serial_out > <-serial8250_console_write > <idle>-0 [000] d..3. 0.213223: uart_console_write > <-serial8250_console_write > <idle>-0 [000] d..3. 0.213223: > serial8250_console_putchar <-uart_console_write > <idle>-0 [000] d..3. 0.213223: wait_for_xmitr > <-serial8250_console_putchar > <idle>-0 [000] d..3. 0.213223: io_serial_in > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213226: io_serial_out > <-uart_console_write > <idle>-0 [000] d..3. 0.213229: > serial8250_console_putchar <-uart_console_write > <idle>-0 [000] d..3. 0.213229: wait_for_xmitr > <-serial8250_console_putchar > <idle>-0 [000] d..3. 0.213229: io_serial_in > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213232: __const_udelay > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213232: delay_tsc > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213233: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213233: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213233: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213233: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213233: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213233: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213233: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213233: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213233: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213233: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213234: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213234: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213234: io_serial_in > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213237: __const_udelay > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213237: delay_tsc > <-wait_for_xmitr > <idle>-0 [000] d..3. 0.213237: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213237: preempt_count_sub > <-delay_tsc > <idle>-0 [000] d..3. 0.213237: preempt_count_add > <-delay_tsc > <idle>-0 [000] d..4. 0.213237: preempt_count_sub > <-delay_tsc > > So it looks to me like, that the already recorded messages are printed out > over the serial console first, before it continues. The documentation of > `register_console()` in `kernel/printk/printk.c` confirms that: > > > * The console driver calls this routine during kernel initialization > > * to register the console printing procedure with printk() and to > > * print any messages that were printed by the kernel before the > > * console driver was initialized. > > Is there an option to enable the serial console but send the messages to it > asynchronously so it does not hold up the boot? See the patches posted to the mailing lists a few weeks ago for how the console/printk code will be reworked to handle issues like this. thanks, greg k-h
