From owner-freebsd-current@freebsd.org Fri Nov 29 22:10:45 2019 Return-Path: Delivered-To: freebsd-current@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 40DF91BDB61 for ; Fri, 29 Nov 2019 22:10:45 +0000 (UTC) (envelope-from pen@lysator.liu.se) Received: from mail.lysator.liu.se (mail.lysator.liu.se [IPv6:2001:6b0:17:f0a0::3]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 47Ppc368jqz4MTp for ; Fri, 29 Nov 2019 22:10:43 +0000 (UTC) (envelope-from pen@lysator.liu.se) Received: from mail.lysator.liu.se (localhost [127.0.0.1]) by mail.lysator.liu.se (Postfix) with ESMTP id 7094F40014; Fri, 29 Nov 2019 23:10:37 +0100 (CET) Received: from [192.168.1.132] (h-201-140.A785.priv.bahnhof.se [98.128.201.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.lysator.liu.se (Postfix) with ESMTPSA id 43EC240011; Fri, 29 Nov 2019 23:10:37 +0100 (CET) Content-Type: text/plain; charset=utf-8 Mime-Version: 1.0 (Mac OS X Mail 13.0 \(3601.0.10\)) Subject: Re: Best way to print something from the kernel at 1s intervals? From: Peter Eriksson In-Reply-To: Date: Fri, 29 Nov 2019 23:10:36 +0100 Cc: Enji Cooper Content-Transfer-Encoding: quoted-printable Message-Id: <057870D3-B59E-47FB-A832-A72DC6F54AFA@lysator.liu.se> References: To: freebsd-current@freebsd.org X-Mailer: Apple Mail (2.3601.0.10) X-Virus-Scanned: ClamAV using ClamSMTP X-Rspamd-Queue-Id: 47Ppc368jqz4MTp X-Spamd-Bar: - Authentication-Results: mx1.freebsd.org; dkim=none; dmarc=pass (policy=none) header.from=liu.se; spf=pass (mx1.freebsd.org: domain of pen@lysator.liu.se designates 2001:6b0:17:f0a0::3 as permitted sender) smtp.mailfrom=pen@lysator.liu.se X-Spamd-Result: default: False [-1.69 / 15.00]; ARC_NA(0.00)[]; RCVD_VIA_SMTP_AUTH(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-0.998,0]; FROM_HAS_DN(0.00)[]; TO_DN_SOME(0.00)[]; R_SPF_ALLOW(-0.20)[+a:mail.lysator.liu.se]; MV_CASE(0.50)[]; MIME_GOOD(-0.10)[text/plain]; MIME_TRACE(0.00)[0:+]; NEURAL_HAM_LONG(-1.00)[-0.998,0]; RCVD_COUNT_THREE(0.00)[3]; TO_MATCH_ENVRCPT_SOME(0.00)[]; RCVD_IN_DNSWL_MED(-0.20)[3.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.a.0.f.7.1.0.0.0.b.6.0.1.0.0.2.list.dnswl.org : 127.0.11.2]; RCPT_COUNT_TWO(0.00)[2]; DMARC_POLICY_ALLOW(-0.50)[liu.se,none]; IP_SCORE(-0.20)[ipnet: 2001:6b0::/32(-0.54), asn: 1653(-0.44), country: EU(-0.00)]; RCVD_TLS_LAST(0.00)[]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; SUBJECT_ENDS_QUESTION(1.00)[]; ASN(0.00)[asn:1653, ipnet:2001:6b0::/32, country:EU]; FREEMAIL_CC(0.00)[gmail.com]; MID_RHS_MATCH_FROM(0.00)[] X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 29 Nov 2019 22:10:45 -0000 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 wrote: >=20 >=20 >> On Nov 28, 2019, at 12:52, Peter Eriksson 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