From: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
To: Paul Menzel <pmenzel@molgen.mpg.de>
Cc: Petr Mladek <pmladek@suse.com>,
Sergey Senozhatsky <senozhatsky@chromium.org>,
linux-serial@vger.kernel.org, LKML <linux-kernel@vger.kernel.org>
Subject: Re: Do not delay boot when printing log to serial console during startup?
Date: Tue, 11 Oct 2022 11:44:43 +0200 [thread overview]
Message-ID: <Y0U7C2IHYDkiiSxU@kroah.com> (raw)
In-Reply-To: <c87cc376-3b0d-8fda-7fc1-555c930faaf1@molgen.mpg.de>
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 prev parent reply other threads:[~2022-10-11 9:44 UTC|newest]
Thread overview: 4+ messages / expand[flat|nested] mbox.gz Atom feed top
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 [this message]
2022-10-11 9:50 ` Sergey Senozhatsky
2022-11-14 13:45 ` Petr Mladek
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=Y0U7C2IHYDkiiSxU@kroah.com \
--to=gregkh@linuxfoundation.org \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-serial@vger.kernel.org \
--cc=pmenzel@molgen.mpg.de \
--cc=pmladek@suse.com \
--cc=senozhatsky@chromium.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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).