Re: Do not delay boot when printing log to serial console during startup?

From: Greg Kroah-Hartman
Date: Tue Oct 11 2022 - 05:44:06 EST

Next message: Andy Shevchenko: "Re: [PATCH] Revert "mfd: syscon: Remove repetition of the regmap_get_val_endian()""
Previous message: Bean Huo: "Re: [PATCH v2 1/2] scsi: ufs: core: Remove unnecessary if statement"
In reply to: Paul Menzel: "Do not delay boot when printing log to serial console during startup?"
Next in thread: Sergey Senozhatsky: "Re: Do not delay boot when printing log to serial console during startup?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Next message: Andy Shevchenko: "Re: [PATCH] Revert "mfd: syscon: Remove repetition of the regmap_get_val_endian()""
Previous message: Bean Huo: "Re: [PATCH v2 1/2] scsi: ufs: core: Remove unnecessary if statement"
In reply to: Paul Menzel: "Do not delay boot when printing log to serial console during startup?"
Next in thread: Sergey Senozhatsky: "Re: Do not delay boot when printing log to serial console during startup?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]