Date: Fri, 29 Mar 2019 21:57:32 +1100 (EST) From: Bruce Evans <brde@optusnet.com.au> To: Alexey Dokuchaev <danfe@freebsd.org> Cc: Bruce Evans <brde@optusnet.com.au>, Ravi Pokala <rpokala@freebsd.org>, svn-src-head@freebsd.org, Kyle Evans <kevans@freebsd.org>, svn-src-all@freebsd.org, src-committers@freebsd.org Subject: Re: svn commit: r345680 - head/sys/conf Message-ID: <20190329205849.E1647@besplex.bde.org> In-Reply-To: <20190329094903.GA12522@FreeBSD.org> References: <201903290400.x2T40kp7013212@repo.freebsd.org> <CAF5D833-B3C3-4AD6-9B77-0363C56E93E9@panasas.com> <20190329164644.X957@besplex.bde.org> <20190329094903.GA12522@FreeBSD.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On Fri, 29 Mar 2019, Alexey Dokuchaev wrote:
> On Fri, Mar 29, 2019 at 05:40:05PM +1100, Bruce Evans wrote:
>>>> ...
>>>> -options BOOT_TAG=\"---<<BOOT>>---\"
>>>> +options BOOT_TAG=\"\"
>>
>> Useful variations are not always easy to invent. I usually just add 1 for
>> numeric values. This example is useful. It kills the boot tag. It gives
>> an empty tag, and the kernel does extra work to avoid printing a newline
>> after an empty tag.
>
> That's a nice idea, thanks Bruce. I always had to revert commits that had
> added this stupid boot tag; if empty tag does not imply a newline, then it
> makes things much easier.
>
> ./danfe
>
> P.S. Boot tag of a healthy human is "Copyright (c) 1992-2018 The FreeBSD
> Project".
Actually, there are ordering problems. After fixing lost messages, I get
for the simplest case of a non-verbose cold boot:
XX Mar 29 19:14:08 gamplex syslogd: kernel boot file is /kernel
This boot file message is the first one. I often grep for it, so as to
ignore messages for previous boots.
XX Mar 29 19:14:08 gamplex kernel: ---<<BOOT>>---
This is almost first.
XX Mar 29 19:14:08 gamplex kernel: Test of early printf to msgbuf
XX Mar 29 19:14:08 gamplex kernel: Test of early printf to console
Tests for my fixes. msgbufinit() is called early and uses a statically
allocated buffer until the dynamic message buffer is mapped. Early messages
are thus not lost for the message buffer. They may be lost for the
console.
XX Mar 29 19:14:08 gamplex kernel: GDB: debug ports: sio
XX Mar 29 19:14:08 gamplex kernel: GDB: current port: sio
XX Mar 29 19:14:08 gamplex kernel: KDB: debugger backends: ddb gdb
XX Mar 29 19:14:08 gamplex kernel: KDB: current backend: ddb
Standard early messages if DDB is configured.
XX Mar 29 19:14:08 gamplex kernel: WARNING: loader(8) metadata is missing!
I don't use loader on i386, and am reminded that I don't like it by this
warning.
XX Mar 29 19:14:08 gamplex kernel: Copyright (c) 1992-2019 The FreeBSD Project.
Finally the copyright message. The source code still obfuscates the order
of this using SYSINIT(), and on x86 and powerpc still has a bogus "Good
{morning,afternoon,evening, night}" comment that isn't even attached to its
code (the printf() of the message). The comment is in cpu_startup()
which runs at SI_SUB_CPU, SI_ORDER_FIRST. This is much later than printing
the copyright, which runs at SI_SUB_COPYRIGHT. In between, there are SUBs
for VM, KMEM, HYPERISOR, WITNESS, MTX_POOL_DYNAMIC, LOCK, EVENTHANDLER,
VNET_PRELINK and KLD. Before COPYRIGHT, there are only DUMMY, DONE and
TUNABLES under sysinit, but lots more in early initialization including
early console use for the above messages and ddb. The comment on
SI_SUB_COPYRIGHT wrongly says that it is for the first use of the console.
Booting with -v gives many more early messages that are usually lost. E.g.,
ones about SMAP on x86.
Warm boots sometimes give a dynamic message buffer that is actually useful.
To be useful, it must be retained at boot. Otherwise, it is easier to
put the message buffer in the bss.
The dynamic message buffer only works for me on amd64 and i386 with pae_mode=1
(and probably also more than 4GB RAM). Otherwise, it is below 4GB and the
BIOS scribbles on it (fairly sparsely, but it doesn't have enough error
correcting to recover). Recovering it fixes loss of the last few messages
for the previous boot, but risks doubling of non-lost messages. The BOOT
tags are useful for seeing where the new messages start.
Everything usually works as well as possible:
XX Mar 25 02:59:49 iotaplex syslogd: exiting on signal 15
The use of an amd64 kernel a few days ago was terminated by turning the
system off. Messages printed after killing syslogd were lost.
XX Mar 29 21:33:49 iotaplex syslogd: kernel boot file is /boot/kernel/kernel
XX Mar 29 21:33:49 iotaplex kernel: ---<<BOOT>>---
XX Mar 29 21:33:49 iotaplex kernel: Test of early printf to msgbuf
XX Mar 29 21:33:49 iotaplex kernel: GDB: debug ports: sio
XX Mar 29 21:33:49 iotaplex kernel: GDB: current port: sio
XX Mar 29 21:33:49 iotaplex kernel: KDB: debugger backends: ddb gdb
XX Mar 29 21:33:49 iotaplex kernel: KDB: current backend: ddb
XX Mar 29 21:33:49 iotaplex kernel: Copyright (c) 1992-2019 The FreeBSD Project.
Cold boot of the same kernel today (actually, i386 was running before this,
but the boot was cold enough for the message buffer).
XX ...
XX Mar 29 21:34:32 iotaplex syslogd: exiting on signal 15
As usual, messages printed after killing syslogd are not logged properly...
XX Mar 29 21:35:55 iotaplex syslogd: kernel boot file is /boot/kernel/kernel
Warm boot of the same amd64 kernel.
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system process `vnlru' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system process `syncer' to stop...
XX Mar 29 21:35:55 iotaplex kernel: Syncing disks, vnodes remaining... 0 0 0 done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system thread `bufdaemon' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system thread `bufspacedaemon-0' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system thread `bufspacedaemon-1' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system thread `bufspacedaemon-2' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: Waiting (max 60 seconds) for system thread `bufspacedaemon-3' to stop... done
XX Mar 29 21:35:55 iotaplex kernel: All buffers synced.
... the new boot finds the lost messages in the old message buffer and logs
them. It also finds non-lost messages and the old klog pointer so it knows
to not log the non-lost messages again. Everything is as correct as possible
except for the timestamps (these are for when the new syslogd reads the
messages, not for the events logged by printing the messages).
XX Mar 29 21:35:55 iotaplex kernel: ---<<BOOT>>---
XX Mar 29 21:35:55 iotaplex kernel: Test of early printf to msgbuf
No "Test of early printf to console" on amd64, since I only do this for
i386.
XX Mar 29 21:35:55 iotaplex kernel: GDB: debug ports: sio
XX Mar 29 21:35:55 iotaplex kernel: GDB: current port: sio
XX Mar 29 21:35:55 iotaplex kernel: KDB: debugger backends: ddb gdb
XX Mar 29 21:35:55 iotaplex kernel: KDB: current backend: ddb
These debugging messages are always before all SYSINIT()s so long before
the COPYRIGHT one.
XX Mar 29 21:35:55 iotaplex kernel: Copyright (c) 1992-2019 The FreeBSD Project.
Continuing with the warm boot. The tag is correctly placed for delimiting
messages printed by the new boot.
Bruce
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20190329205849.E1647>