Received: by 2002:a05:6358:1087:b0:cb:c9d3:cd90 with SMTP id j7csp1949864rwi; Tue, 11 Oct 2022 02:44:59 -0700 (PDT) X-Google-Smtp-Source: AMsMyM4fGSqaDK3E+EeTpntDqaKb9aX/kQte8oKNTxtyL38LENpZcLpNcCNLIllgItIxN3EdHmbZ X-Received: by 2002:a17:902:f643:b0:17a:a2e:40c7 with SMTP id m3-20020a170902f64300b0017a0a2e40c7mr23381130plg.6.1665481499332; Tue, 11 Oct 2022 02:44:59 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1665481499; cv=none; d=google.com; s=arc-20160816; b=c/BJlFiU3wzMEbTPDo7ZFGtyK5SMOny2mfeQcUQQRPgTKtiqVvRBzusHqY7pOpAV29 2eFUwSMrXXbtXpYtP/pYeOH+0DfKcl4Jo8M7z/kfoRMkRkDAZiOC+jtyVG9gbTtFfmts xeW5xxjcW739hzS+f09Nlsn2Xd39vCuWWlEWAjLOsmh1drI0vpfgKx73vbYlMsgrwcgD OXTdK2pYI7i7dDkMgtrNXDIu65TBXK9Zut0UtjacgNa0tpsD8F+eTaJWRkUIX6xyNtdD s1516j1aLhy/R1Jt8VEpmJpLmudTDhlFB01TNUdrj4Xz5TnafBQfnn+fcXUiQm8nPdzI JlEA== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:in-reply-to:content-transfer-encoding :content-disposition:mime-version:references:message-id:subject:cc :to:from:date:dkim-signature; bh=URYsBvSxU/T2xeVhXNjaEotLHthYQHjmp8Gtu+4DtIo=; b=EQvR7KPfpwa4P6lVCuHW6vM8NP+DmQN/8kyqUAmOLq0Ie4OQ0vc5jgLCa8UDufaUUu 61IF7flz22NwY2GDErjtOWS/D7JVcqj878i3LGCN/ZyNGHOENFNY1wwV1Q2fFZDLQpnV HCvdNlYjoJK2Bhl1cdxCXAsSLWQmcy76nAUeojnS2UMABCBMYtMLk7DDYrF7recbbES+ KmREqea+Z6lIKk35X9zdGqRBMJQ0v7DlwVU1aJhRZuvONBvpmRpmqIVk75/vEJK2SC8b R0MQhWUHrQWFn/7Jl/pAMPpzh4S/mEzNCrTMqMvAqBRrs3WxiKxa8jOK1H5ViON5mtlT HtaA== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@linuxfoundation.org header.s=korg header.b=mju2WyJJ; 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; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linuxfoundation.org Return-Path: Received: from out1.vger.email (out1.vger.email. [2620:137:e000::1:20]) by mx.google.com with ESMTP id 198-20020a6300cf000000b004632f369fc2si4966927pga.178.2022.10.11.02.44.46; Tue, 11 Oct 2022 02:44:59 -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; dkim=pass header.i=@linuxfoundation.org header.s=korg header.b=mju2WyJJ; 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; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linuxfoundation.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229507AbiJKJoE (ORCPT + 99 others); Tue, 11 Oct 2022 05:44:04 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:38532 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229468AbiJKJoC (ORCPT ); Tue, 11 Oct 2022 05:44:02 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id EF1001E727; Tue, 11 Oct 2022 02:44:00 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 649916115A; Tue, 11 Oct 2022 09:44:00 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 64595C433D6; Tue, 11 Oct 2022 09:43:59 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=linuxfoundation.org; s=korg; t=1665481439; bh=cmkfm8Ez8Xk48ifchcjtsgK793vW9o9xFsSrZOsZiX0=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=mju2WyJJJm71OKWZiP421wddtGfpxMHcLC7SnWs3BZDjdb1QUL6PO6blRwd8rYBpJ O83k0X2jIravx6pDoDPCM29n+QDqxyB0Fby2DxRrNQ4BD9wlhKhXRkPrlgjNs27/5i KRXr/DV710QEpA9Be1cEvOgPpTBc2q8fz3ZPWj7Q= Date: Tue, 11 Oct 2022 11:44:43 +0200 From: Greg Kroah-Hartman To: Paul Menzel Cc: Petr Mladek , Sergey Senozhatsky , linux-serial@vger.kernel.org, LKML Subject: Re: Do not delay boot when printing log to serial console during startup? Message-ID: References: MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: X-Spam-Status: No, score=-7.1 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_HI, 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 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: > > -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? 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