Date: Fri, 29 Nov 2019 23:10:36 +0100 From: Peter Eriksson <pen@lysator.liu.se> To: freebsd-current@freebsd.org Cc: Enji Cooper <yaneurabeya@gmail.com> Subject: Re: Best way to print something from the kernel at 1s intervals? Message-ID: <057870D3-B59E-47FB-A832-A72DC6F54AFA@lysator.liu.se> In-Reply-To: <DA769610-A087-40C4-B903-ACF34388CDE8@gmail.com> References: <E6B8A0DA-5F4D-4B08-A376-0AE65575A6F9@lysator.liu.se> <DA769610-A087-40C4-B903-ACF34388CDE8@gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
I love dtrace, but I seriously doubt that it could be used it for this. = This is the absolutely last code that executes at kernel = shutdown/reboot. All other processes are terminated when this is = happening... Basically the code done in kern_reboot() (and stuff it calls) in = /usr/src/sys/kern/kern_shutdown.c This code in kern_reboot(): ... > EVENTHANDLER_INVOKE(shutdown_pre_sync, howto); > > /* > * Now sync filesystems > */ > if (!cold && (howto & RB_NOSYNC) =3D=3D 0 && once =3D=3D 0) { > once =3D 1; > bufshutdown(show_busybufs); > } > > print_uptime(); > > cngrab(); > > /* > * Ok, now do things that assume all filesystem activity has > * been completed. > */ > EVENTHANDLER_INVOKE(shutdown_post_sync, howto); > > if ((howto & (RB_HALT|RB_DUMP)) =3D=3D RB_DUMP && !cold && = !dumping) > doadump(TRUE); > > /* Now that we're going to really halt the system... */ > EVENTHANDLER_INVOKE(shutdown_final, howto); What I=E2=80=99ve seen is that the three different EVENTHANDLER_INVOKE() = all can cause a lot of calls that can take a long time. As can = bufshutdown(), probably when it calls vfs_unmountall() to unmount all = filesystems. We=E2=80=99re talking like 5-20 minutes (or more). I=E2=80=99ve not = really timed it. I have a feeling it sometimes is due to transactions stored up in the = ZFS filesystems that the system tries to =E2=80=9Crun=E2=80=9D so it = doesn=E2=80=99t have to do it at mount() time after the reboot. If I = reset the machine while it is busy doing this then sometimes the =E2=80=9C= zfs mount -a=E2=80=9D takes very long time at boot instead. Hmm.. I should be able to use the getnanouptime() call to get a = =E2=80=9Cclock=E2=80=9D to look for (it=E2=80=99s used in = print_uptime()). As long as the clock isn=E2=80=99t stopped at this time = in the shutdown sequence atleast :-) *Time to write some code and test this* :-) - Peter > On 29 Nov 2019, at 22:09, Enji Cooper <yaneurabeya@gmail.com> wrote: >=20 >=20 >> On Nov 28, 2019, at 12:52, Peter Eriksson <pen@lysator.liu.se> wrote: >>=20 >> =EF=BB=BFI=E2=80=99ve been looking into the =E2=80=9Ckernel looks to = be hung at reboot=E2=80=9D problem at bit. Adding a lot of printf() = calls to the relevant parts it looks like it actually isn=E2=80=99t hung = but busy unmounting filesystems (which we have thousands of), flushing = disk caches, calling registered callbacks and stuff and sometimes it = takes a bit longer than usual - probably due to ZFS having stuff queued = up that needs to be written to disk before it finishes=E2=80=A6 >>=20 >> Anyway, I=E2=80=99d like to propose that we add some kind of = counter/printf() calls in that code area so we can see that things are = indeed progressing. However, I=E2=80=99d probably prefer not to print = _every_ filesystem (or registered callbacks - a lot of those...) - that = generates a lot of output (tried that :-) but something like: >>=20 >> Unmounting filesystems: >> 1234 done >> (With the "1234 done=E2=80=9D updated something like once per = second). >>=20 >> What=E2=80=99s the right/best way to do that from the kernel? In user = space I=E2=80=99d just call time(&t) at some convenient points and only = print something if =E2=80=9Ct=E2=80=9D has changed. :-) >=20 > Can you use DTrace instead to get the information you need? > Cheers, > -Enji
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?057870D3-B59E-47FB-A832-A72DC6F54AFA>