From owner-freebsd-hackers@freebsd.org Sat Apr 21 19:52:49 2018 Return-Path: Delivered-To: freebsd-hackers@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 07D09F92BE6 for ; Sat, 21 Apr 2018 19:52:49 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: from mail-it0-x22a.google.com (mail-it0-x22a.google.com [IPv6:2607:f8b0:4001:c0b::22a]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 85C4C84876 for ; Sat, 21 Apr 2018 19:52:48 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: by mail-it0-x22a.google.com with SMTP id 19-v6so6230493itw.3 for ; Sat, 21 Apr 2018 12:52:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=bsdimp-com.20150623.gappssmtp.com; s=20150623; h=mime-version:sender:in-reply-to:references:from:date:message-id :subject:to:cc; bh=FexdtQcWWIPZFwZJMOTvo3xA63cOYz6NtTHTEYezejg=; b=CC81YIBYN+v45mdslUL/W5xr8JTPuFA9FyAj2fohJuo9m5p5x/MKYFhcdLVsCbro7T k/GdQ/FEcHH9iKh+681vklRpX/MBKuRRpUlISKJhKY1rcxloeLG50icu53ZlGZ+WXdFr giAfk4ZtSR4OxIDp46omeZpeCuKnBENZPm5fZkYVBWFusx8L2w1YpRtDHpMRLn1dBjtN bbFeblSeXm+6sayIKHz15qSWHrat2whDByMqMbTJKANawNNNgqqk4iMYaUySC5R+hbI7 zU11sOcLkXPfo96CcNTb7oGQhF3w3MTm5emzF0k235sOyvYd6leQfk9W024XI8ApkaOn i6xg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:sender:in-reply-to:references:from :date:message-id:subject:to:cc; bh=FexdtQcWWIPZFwZJMOTvo3xA63cOYz6NtTHTEYezejg=; b=YzLM9hRRFMgXGYs1siNEJzqBrT2LFKPU7uqY4FgbWoQvPGbdac4biZLUHMjsbhdv9H YGDsDM6buGT+HbACD1Mk6bXuAaM1IqHpCq0YNbfSOJCGzFoRO/6t15LRv6U/DNs8V3xl uaaMi+BFMJ+oYhQSCCjjLoKpfAFQpHZPWzFHgyI20IAsk9sCtk8HEFuW1cYPZkIuMz0P ISroT2u4wbLx0NjF7Y0egjL3ZIo1eH54m+Nh7/1yZ5FEkMt+CWf17VXX8+m6rghywzvC IYdJ0EPbb28xrFJW7Rg7WyUCfSmT056naOt08Dp36SAss16/EFNR5JqYJs9e+pe1w+fq xLRQ== X-Gm-Message-State: ALQs6tAy+1dstKR2jyGGAkTrQ0nr38AdUGUtrCpmMo3/0mVzszAmbI8J FI36X1O+3pNmMhuJ0zPtp10V5HXL7sZy8eIDdY9tSw== X-Google-Smtp-Source: AB8JxZqy6+nxBigOhVWGRjOEexH29dQNTuZ8CrOZclKckr8YGeH4z5Y8F8JttuJOeruJ84WKoLu9oUREY7s41ucJ2Rc= X-Received: by 2002:a24:ad64:: with SMTP id a36-v6mr7743845itj.1.1524340367554; Sat, 21 Apr 2018 12:52:47 -0700 (PDT) MIME-Version: 1.0 Sender: wlosh@bsdimp.com Received: by 2002:a4f:a604:0:0:0:0:0 with HTTP; Sat, 21 Apr 2018 12:52:46 -0700 (PDT) X-Originating-IP: [2603:300b:6:5100:1052:acc7:f9de:2b6d] In-Reply-To: <20180421123544.56d7e690@ernst.home> References: <01000162df15f856-1e5d2641-2a72-4250-8d8e-adcd47bc5db4-000000@email.amazonses.com> <20180419204405.GE6887@kib.kiev.ua> <20180419214550.GF6887@kib.kiev.ua> <01000162e58a466e-98f0305b-1723-467a-bc49-342c3fa9fc5b-000000@email.amazonses.com> <20180421092049.GM6887@kib.kiev.ua> <20180421123544.56d7e690@ernst.home> From: Warner Losh Date: Sat, 21 Apr 2018 13:52:46 -0600 X-Google-Sender-Auth: RuBu3rV8Qou6L2hcrgLMYeupyU0 Message-ID: Subject: Re: RFC: Hiding per-CPU kernel output behind bootverbose To: gljennjohn@gmail.com Cc: Konstantin Belousov , "freebsd-hackers@freebsd.org" , Colin Percival , Conrad Meyer Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.25 X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.25 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 21 Apr 2018 19:52:49 -0000 On Sat, Apr 21, 2018 at 4:35 AM, Gary Jennejohn wrote: > On Sat, 21 Apr 2018 12:20:49 +0300 > Konstantin Belousov wrote: > > > On Sat, Apr 21, 2018 at 12:11:07AM +0000, Colin Percival wrote: > > > On 04/19/18 14:45, Konstantin Belousov wrote: > > > > On Thu, Apr 19, 2018 at 02:37:56PM -0700, Conrad Meyer wrote: > > > >> On Thu, Apr 19, 2018 at 1:44 PM, Konstantin Belousov wrote: > > > >>> The 'CPU XX Launched' messages are very useful for initial > diagnostic > > > >>> of the SMP startup failures. You need to enable bootverbose to see > the > > > >>> hang details, but for initial hint they are required. > Unfortunately, AP > > > >>> startup hangs occur too often to pretend that this can be > delegated to > > > >>> very specific circumstances. > > > >> > > > >> Really? I don't know that I've ever seen an AP startup hang. How > > > >> often do they occur? > > > > > > > > It was epidemic with Sandy Bridge, mostly correlated to specific BIOS > > > > supplier and its interaction with the x2APIC enablement, see > madt.c:170 > > > > and below. > > > > > > > > There were several recent reports of the issue with Broadwell Xeon > > > > machines, no additional data or resolution. > > > > > > > > There are sporadic reports of the problem, where I do not see > > > > a clear commonality. > > > > > > Would it be sufficient for debugging purposes if I change the > !bootverbose > > > case from printing many lines of > > > > > > SMP: AP CPU #N Launched! > > > > > > to instead have a single > > > > > > SMP: Launching AP CPUs: 86 73 111 21 8 77 100 28 57 42 10 60 87 88 41 > 113 36 > > > 19 72 46 92 52 24 81 90 3 107 96 9 14 80 118 29 121 62 74 56 55 1 12 > 63 18 67 > > > 13 45 102 33 94 69 68 93 83 48 31 30 32 51 89 71 78 64 84 123 61 40 47 > 37 22 > > > 54 101 38 4 97 44 17 109 104 5 85 43 2 99 39 65 95 53 58 66 91 125 23 > 115 16 > > > 35 79 112 103 82 7 75 11 6 98 15 126 127 20 70 34 105 27 50 116 120 49 > 25 108 > > > 106 122 117 114 26 110 59 76 124 119 > > > > > > ? (With each AP printing its number as it reaches the appropriate > point?) > > > > > > This yields almost the same gain as silencing the launch messages > completely, > > > while still allowing you to see each CPU announcing itself. > > I am fine with the behaviour, but I am not sure how would you implement > > this. printf(9) buffers the output, you need to flush it somehow. > > > > And printf(9) calls vprintf(9) which in turn calls _vprintf which > will allocate a buffer on the stack (bad idea) if the option > PRINTF_BUFR_SIZE is set in the kernel config file. So it seems > that output may even be double buffered. > I don't think either of these is true (the double buffered part,. nor the buffered part). Well, they are both kinda true, but they don't matter. It's all to make dmesg and friends work. There's other issues, but at this stage of the boot we're single threaded and the CPUs that are launching take out a spin lock. We always call putchar for each character that kvprintf(). So any buffering that's done is in addition to putchar going to the console. diff --git a/sys/x86/x86/mp_x86.c b/sys/x86/x86/mp_x86.c index 3fcf7aa25152..06973b1ea6d5 100644 --- a/sys/x86/x86/mp_x86.c +++ b/sys/x86/x86/mp_x86.c @@ -1020,7 +1020,7 @@ init_secondary_tail(void) smp_cpus++; CTR1(KTR_SMP, "SMP: AP CPU #%d Launched", cpuid); - printf("SMP: AP CPU #%d Launched!\n", cpuid); + printf("%d%s", cpuid, smp_cpus == mp_ncpus ? "\n" : " "); /* Determine if we are a logical CPU. */ if (cpu_info[PCPU_GET(apic_id)].cpu_hyperthread) is enough to give them all to me on a single line. We'd need another printf that says 'Starting APs: ' since otherwise we see: andom: unblocking device. ioapic0 irqs 0-23 on motherboard ioapic1 irqs 24-47 on motherboard 1 8 10 20 2 19 11 12 22 4 14 23 16 13 3 18 5 17 21 9 15 6 7 Timecounter "TSC-low" frequency 1350029824 Hz quality 1000 which doesn't make a lot of sense. Comments? Warner