* Do not delay boot when printing log to serial console during startup?
@ 2022-10-11 9:03 Paul Menzel
2022-10-11 9:44 ` Greg Kroah-Hartman
` (2 more replies)
0 siblings, 3 replies; 4+ messages in thread
From: Paul Menzel @ 2022-10-11 9:03 UTC (permalink / raw)
To: Petr Mladek, Sergey Senozhatsky; +Cc: Greg Kroah-Hartman, linux-serial, LKML
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?
Kind regards,
Paul
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: Do not delay boot when printing log to serial console during startup?
2022-10-11 9:03 Do not delay boot when printing log to serial console during startup? Paul Menzel
@ 2022-10-11 9:44 ` Greg Kroah-Hartman
2022-10-11 9:50 ` Sergey Senozhatsky
2022-11-14 13:45 ` Petr Mladek
2 siblings, 0 replies; 4+ messages in thread
From: Greg Kroah-Hartman @ 2022-10-11 9:44 UTC (permalink / raw)
To: Paul Menzel; +Cc: Petr Mladek, Sergey Senozhatsky, linux-serial, LKML
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
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Do not delay boot when printing log to serial console during startup?
2022-10-11 9:03 Do not delay boot when printing log to serial console during startup? Paul Menzel
2022-10-11 9:44 ` Greg Kroah-Hartman
@ 2022-10-11 9:50 ` Sergey Senozhatsky
2022-11-14 13:45 ` Petr Mladek
2 siblings, 0 replies; 4+ messages in thread
From: Sergey Senozhatsky @ 2022-10-11 9:50 UTC (permalink / raw)
To: Paul Menzel
Cc: Petr Mladek, Sergey Senozhatsky, Greg Kroah-Hartman, linux-serial,
LKML
On (22/10/11 11:03), Paul Menzel wrote:
>
> We boot our systems generally with the serial console enabled
> `console=ttyS0,115200n8`, and noticed that initializing the console takes at
> least one second.
[..]
> 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:
I guess your console has CON_PRINTBUFFER flag set, so we flush all
pending kernel messages on this console after registration. Off the
top of my head, you might want to play with the default console loglevel
so that we will suppress printing of most of the messages.
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Do not delay boot when printing log to serial console during startup?
2022-10-11 9:03 Do not delay boot when printing log to serial console during startup? Paul Menzel
2022-10-11 9:44 ` Greg Kroah-Hartman
2022-10-11 9:50 ` Sergey Senozhatsky
@ 2022-11-14 13:45 ` Petr Mladek
2 siblings, 0 replies; 4+ messages in thread
From: Petr Mladek @ 2022-11-14 13:45 UTC (permalink / raw)
To: Paul Menzel
Cc: Sergey Senozhatsky, Greg Kroah-Hartman, John Ogness, linux-serial,
LKML
Adding John into Cc. He is working on introducing printk kthreads that
might allow to handle consoles asynchronously.
On Tue 2022-10-11 11:03:39, 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.)
The message "printk: console [ttyS0] enabled" is printed almost at the
end of register_console(). It happens after all previously printed
messages reach the console.
It might take a long time to show all messages on slow serial consoles.
> 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.
Most people want to see all messages. Any previous warning or error might
the reason why the system crashed later.
If you want faster boot, you might consider using "quiet" or
loglevel=<some low number> on the kernel command line. It will
show only the most important messages on the console.
> Is there an option to enable the serial console but send the messages to it
> asynchronously so it does not hold up the boot?
We have been trying to get this into upstream for years. It is not
that easy. Asynchronous handling increases the risk that a console
will not show the last important messages when things go wrong.
Anyway, we are still trying. One puzzle of this effort is just
being reviewed in this thread,
https://lore.kernel.org/r/20221107141638.3790965-1-john.ogness@linutronix.de
Best Regards,
Petr
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2022-11-14 13:45 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-10-11 9:03 Do not delay boot when printing log to serial console during startup? Paul Menzel
2022-10-11 9:44 ` Greg Kroah-Hartman
2022-10-11 9:50 ` Sergey Senozhatsky
2022-11-14 13:45 ` Petr Mladek
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).