Date: Sat, 21 Apr 2018 13:52:46 -0600 From: Warner Losh <imp@bsdimp.com> To: gljennjohn@gmail.com Cc: Konstantin Belousov <kib@freebsd.org>, "freebsd-hackers@freebsd.org" <freebsd-hackers@freebsd.org>, Colin Percival <cperciva@tarsnap.com>, Conrad Meyer <cem@freebsd.org> Subject: Re: RFC: Hiding per-CPU kernel output behind bootverbose Message-ID: <CANCZdfpi7fZky9VC_TZWhm4uuwnV1N=m3pO1MmDs9GKYJZgSwg@mail.gmail.com> In-Reply-To: <20180421123544.56d7e690@ernst.home> References: <01000162df15f856-1e5d2641-2a72-4250-8d8e-adcd47bc5db4-000000@email.amazonses.com> <20180419204405.GE6887@kib.kiev.ua> <CAG6CVpUerOo%2B55nJq61Hy83RYpbOZS6puEDuemspfNS12urZZw@mail.gmail.com> <20180419214550.GF6887@kib.kiev.ua> <01000162e58a466e-98f0305b-1723-467a-bc49-342c3fa9fc5b-000000@email.amazonses.com> <20180421092049.GM6887@kib.kiev.ua> <20180421123544.56d7e690@ernst.home>
next in thread | previous in thread | raw e-mail | index | archive | help
On Sat, Apr 21, 2018 at 4:35 AM, Gary Jennejohn <gljennjohn@gmail.com>
wrote:
> On Sat, 21 Apr 2018 12:20:49 +0300
> Konstantin Belousov <kib@freebsd.org> 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 <Version 2.0> irqs 0-23 on motherboard
ioapic1 <Version 2.0> 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CANCZdfpi7fZky9VC_TZWhm4uuwnV1N=m3pO1MmDs9GKYJZgSwg>