Received: by 2002:a05:6358:1087:b0:cb:c9d3:cd90 with SMTP id j7csp1941699rwi; Tue, 11 Oct 2022 02:35:48 -0700 (PDT) X-Google-Smtp-Source: AMsMyM7SlUuJ8go6GzIdVqGwpqrIU4RbE70myheb3P1FD62dt77rU8mCw/xPx7sGnAlLFgnnR7q5 X-Received: by 2002:a17:902:9b88:b0:17c:97d6:5e78 with SMTP id y8-20020a1709029b8800b0017c97d65e78mr23658682plp.62.1665480948028; Tue, 11 Oct 2022 02:35:48 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1665480948; cv=none; d=google.com; s=arc-20160816; b=zBNDTzrKrNKDZu4B53/YcKgUEKbnJsh82UNYl/+BLvQaH0Ey6pHfiy69CFtMCE+DHw /c/m+V2GL9Evo/YpBBW4c+oNZM8fZPonguHWTa1uKn/UtYUGQFtNoEkIR03WXp2tUAqF NyhKdSltx2aDtcX6w25e099XcDNLJB0DzjpvqFw0uVmBsy/J/Op+2GcY2e1qzcEt23Xb PHp1/9Rg7wZeqvU9k+bu2UMiDqdwOAuUvmBC/19Ja29ZOViiTk3SzXqA0TYNq9mVPyss +rpya+QcTtHTHt0W32adEk0UXE9MFnXx54JWZGzQ9xqYe7CHQtYBPqIRP47DMPn47qWT xZCQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:content-language:cc:to :subject:from:user-agent:mime-version:date:message-id; bh=L76TDOKeH32Vu8RMP+lD38XM/+2hNe2qsTFinb39Vi0=; b=XDGQ5YyjKKJC/3WDP86iaOmw0TB+XClymkZBqCc5AveAEfaJJ5wNU+i4s9ZMBcq25r EPrReal49DpneU2pz7txIUWL1UoaQj/MWrJJTcqEehcMlKqZceC+0bq1qH1IcT0qJHJe cbWlymIEBYL7WMJY/xCiq8SOQbjfVC4eXuHKDpNUh8vKmxbYW2PHYz0JefRGE+vJCiN/ vr8XgDtqP4R1QXgmysF6HFL93lpVLqoztVI/dMvL7zojk1HGr43vmpCDA8oJMPNfIyBy jW0AUqdrRv2Rj88WgTiXQOunHkEjLQqVQ+fckRcimFFMEyvSYDV1JT2KU5Qz2zmmqMbj 51fQ== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from out1.vger.email (out1.vger.email. [2620:137:e000::1:20]) by mx.google.com with ESMTP id a23-20020a62bd17000000b005632d18cd91si7568067pff.263.2022.10.11.02.35.31; Tue, 11 Oct 2022 02:35:47 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229921AbiJKJEL (ORCPT + 99 others); Tue, 11 Oct 2022 05:04:11 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:48496 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229994AbiJKJDy (ORCPT ); Tue, 11 Oct 2022 05:03:54 -0400 Received: from mx1.molgen.mpg.de (mx3.molgen.mpg.de [141.14.17.11]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id D7C0F7C325; Tue, 11 Oct 2022 02:03:42 -0700 (PDT) Received: from [192.168.0.2] (ip5f5aef0e.dynamic.kabel-deutschland.de [95.90.239.14]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) (Authenticated sender: pmenzel) by mx.molgen.mpg.de (Postfix) with ESMTPSA id 38BC661EA192D; Tue, 11 Oct 2022 11:03:40 +0200 (CEST) Message-ID: Date: Tue, 11 Oct 2022 11:03:39 +0200 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.3.2 From: Paul Menzel Subject: Do not delay boot when printing log to serial console during startup? To: Petr Mladek , Sergey Senozhatsky Cc: Greg Kroah-Hartman , linux-serial@vger.kernel.org, LKML Content-Language: en-US Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit X-Spam-Status: No, score=-4.2 required=5.0 tests=BAYES_00,RCVD_IN_DNSWL_MED, SPF_HELO_NONE,SPF_PASS autolearn=ham autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on lindbergh.monkeyblade.net Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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: -0 [000] ...2. 0.213187: univ8250_console_init <-console_init -0 [000] ...2. 0.213187: serial8250_isa_init_ports <-univ8250_console_init -0 [000] ...2. 0.213187: serial8250_init_port <-serial8250_isa_init_ports -0 [000] ...2. 0.213187: init_timer_key <-serial8250_isa_init_ports -0 [000] ...2. 0.213187: serial8250_set_defaults <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_init_port <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: init_timer_key <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_set_defaults <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_init_port <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: init_timer_key <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_set_defaults <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_init_port <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: init_timer_key <-serial8250_isa_init_ports -0 [000] ...2. 0.213188: serial8250_set_defaults <-serial8250_isa_init_ports -0 [000] ...2. 0.213189: register_console <-univ8250_console_init -0 [000] ...2. 0.213189: try_enable_preferred_console <-register_console -0 [000] ...2. 0.213189: univ8250_console_match <-try_enable_preferred_console -0 [000] ...2. 0.213189: univ8250_console_setup <-try_enable_preferred_console -0 [000] ...2. 0.213189: serial8250_console_setup <-univ8250_console_setup -0 [000] ...2. 0.213189: uart_parse_options <-serial8250_console_setup -0 [000] ...2. 0.213190: uart_set_options <-serial8250_console_setup -0 [000] ...2. 0.213190: tty_termios_encode_baud_rate <-uart_set_options -0 [000] ...2. 0.213190: serial8250_set_termios <-uart_set_options -0 [000] ...2. 0.213191: serial8250_do_set_termios <-uart_set_options -0 [000] ...2. 0.213191: tty_get_char_size <-serial8250_do_set_termios -0 [000] ...2. 0.213191: uart_get_baud_rate <-serial8250_do_set_termios -0 [000] ...2. 0.213191: tty_termios_baud_rate <-uart_get_baud_rate -0 [000] ...2. 0.213191: serial8250_get_divisor <-serial8250_do_set_termios -0 [000] ...2. 0.213191: uart_get_divisor <-serial8250_get_divisor -0 [000] ...2. 0.213191: _raw_spin_lock_irqsave <-serial8250_do_set_termios -0 [000] d..2. 0.213192: preempt_count_add <-_raw_spin_lock_irqsave -0 [000] d..3. 0.213192: uart_update_timeout <-serial8250_do_set_termios -0 [000] d..3. 0.213192: tty_get_frame_size <-uart_update_timeout -0 [000] d..3. 0.213192: io_serial_out <-serial8250_do_set_termios -0 [000] d..3. 0.213195: serial8250_do_set_divisor <-serial8250_do_set_termios -0 [000] d..3. 0.213195: io_serial_out <-serial8250_do_set_divisor -0 [000] d..3. 0.213198: default_serial_dl_write <-serial8250_do_set_termios -0 [000] d..3. 0.213198: io_serial_out <-default_serial_dl_write -0 [000] d..3. 0.213201: io_serial_out <-serial8250_do_set_termios -0 [000] d..3. 0.213204: io_serial_out <-serial8250_do_set_termios -0 [000] d..3. 0.213207: io_serial_out <-serial8250_do_set_termios -0 [000] d..3. 0.213210: serial8250_do_set_mctrl <-serial8250_do_set_termios -0 [000] d..3. 0.213210: io_serial_out <-serial8250_do_set_mctrl -0 [000] d..3. 0.213213: _raw_spin_unlock_irqrestore <-serial8250_do_set_termios -0 [000] ...3. 0.213213: preempt_count_sub <-_raw_spin_unlock_irqrestore -0 [000] ...2. 0.213213: tty_termios_baud_rate <-serial8250_do_set_termios -0 [000] ...2. 0.213214: tty_termios_encode_baud_rate <-serial8250_do_set_termios -0 [000] ...2. 0.213214: console_lock <-register_console -0 [000] ...2. 0.213214: __cond_resched <-console_lock -0 [000] ...2. 0.213214: down <-console_lock -0 [000] ...2. 0.213214: __cond_resched <-down -0 [000] ...2. 0.213214: _raw_spin_lock_irqsave <-down -0 [000] d..2. 0.213214: preempt_count_add <-_raw_spin_lock_irqsave -0 [000] d..3. 0.213214: _raw_spin_unlock_irqrestore <-console_lock -0 [000] ...3. 0.213214: preempt_count_sub <-_raw_spin_unlock_irqrestore -0 [000] ...2. 0.213214: mutex_lock <-register_console -0 [000] ...2. 0.213215: __cond_resched <-mutex_lock -0 [000] ...2. 0.213215: mutex_unlock <-register_console -0 [000] ...2. 0.213215: console_unlock <-register_console -0 [000] ...2. 0.213215: console_emit_next_record.constprop.0 <-console_unlock -0 [000] ...2. 0.213215: prb_read_valid <-console_emit_next_record.constprop.0 -0 [000] ...2. 0.213215: _prb_read_valid <-prb_read_valid -0 [000] ...2. 0.213215: desc_read_finalized_seq <-_prb_read_valid -0 [000] ...2. 0.213215: console_emit_next_record.constprop.0 <-console_unlock -0 [000] ...2. 0.213215: prb_read_valid <-console_emit_next_record.constprop.0 -0 [000] ...2. 0.213215: _prb_read_valid <-prb_read_valid -0 [000] ...2. 0.213215: desc_read_finalized_seq <-_prb_read_valid -0 [000] ...2. 0.213216: get_data <-_prb_read_valid -0 [000] ...2. 0.213216: desc_read_finalized_seq <-_prb_read_valid -0 [000] ...2. 0.213216: record_print_text <-console_emit_next_record.constprop.0 -0 [000] ...2. 0.213216: info_print_prefix <-record_print_text -0 [000] d..2. 0.213216: __printk_safe_enter <-console_emit_next_record.constprop.0 -0 [000] d..2. 0.213216: _raw_spin_lock <-console_emit_next_record.constprop.0 -0 [000] d..2. 0.213216: preempt_count_add <-_raw_spin_lock -0 [000] d..3. 0.213216: _raw_spin_unlock <-console_emit_next_record.constprop.0 -0 [000] d..3. 0.213217: preempt_count_sub <-_raw_spin_unlock -0 [000] d..2. 0.213217: univ8250_console_write <-console_emit_next_record.constprop.0 -0 [000] d..2. 0.213217: serial8250_console_write <-console_emit_next_record.constprop.0 -0 [000] d..2. 0.213217: _raw_spin_lock_irqsave <-serial8250_console_write -0 [000] d..2. 0.213217: preempt_count_add <-_raw_spin_lock_irqsave -0 [000] d..3. 0.213217: io_serial_in <-serial8250_console_write -0 [000] d..3. 0.213220: io_serial_out <-serial8250_console_write -0 [000] d..3. 0.213223: uart_console_write <-serial8250_console_write -0 [000] d..3. 0.213223: serial8250_console_putchar <-uart_console_write -0 [000] d..3. 0.213223: wait_for_xmitr <-serial8250_console_putchar -0 [000] d..3. 0.213223: io_serial_in <-wait_for_xmitr -0 [000] d..3. 0.213226: io_serial_out <-uart_console_write -0 [000] d..3. 0.213229: serial8250_console_putchar <-uart_console_write -0 [000] d..3. 0.213229: wait_for_xmitr <-serial8250_console_putchar -0 [000] d..3. 0.213229: io_serial_in <-wait_for_xmitr -0 [000] d..3. 0.213232: __const_udelay <-wait_for_xmitr -0 [000] d..3. 0.213232: delay_tsc <-wait_for_xmitr -0 [000] d..3. 0.213233: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213233: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213233: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213233: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213233: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213233: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213233: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213233: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213233: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213233: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213234: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213234: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213234: io_serial_in <-wait_for_xmitr -0 [000] d..3. 0.213237: __const_udelay <-wait_for_xmitr -0 [000] d..3. 0.213237: delay_tsc <-wait_for_xmitr -0 [000] d..3. 0.213237: preempt_count_add <-delay_tsc -0 [000] d..4. 0.213237: preempt_count_sub <-delay_tsc -0 [000] d..3. 0.213237: preempt_count_add <-delay_tsc -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