[src/trunk]: src Correct the 6 second offset issue between the time reported by

[kre <kre%NetBSD.org@localhost>]

details:   https://anonhg.NetBSD.org/src/rev/d46fe552b6e6
branches:  trunk
changeset: 445486:d46fe552b6e6
user:      kre <kre%NetBSD.org@localhost>
date:      Tue Oct 30 19:40:35 2018 +0000

description:
Correct the 6 second offset issue between the time reported by
dmesg -T and the actual time a message was produced, noted on
current-users by Geoff Wing (Oct 27, 2018).

The size of the offset would depend upon architecture, and processor,
but was the delay from starting the clocks to initialising the time
of day (after mounting root, in case that is needed).

Change the kernel to set boottime to be the time at which the
clocks were started, rather than the time at which it is init'd
(by subtracting the interval between).

Correct dmesg to properly compute the ToD based upon the
boottime (which is a timespec, not a timeval, and has been
since Jan 2009) and the time logged in the message.

Note that this can (rarely) be 1 second earlier than date reports.
This occurs  when the time when the message was logged was actually
in the next second, but the timecounters have not yet processed
the tick, and so the time of the last tick, near the end of the
previous second, is reported instead.   Since times are always
truncated, rather than rounded, it is occasionally possible to
observe that disparity (if you try hard enough).

IOW: sys/kern/subr_prf.c:addtstamp() uses getnanouptime() rather
than nanouptime().

Note in dmesg(8) that -T conversions are gibberish other than
when the message comes from current the running kernel.  (It
could be fixed when -M is used, for messages generated by the
kernel whose corpse is being observed.   But hasn't been...)

diffstat:

 sbin/dmesg/dmesg.8   |  10 ++++++++--
 sbin/dmesg/dmesg.c   |  15 +++++++++++----
 sys/kern/init_main.c |  15 ++++++++++++---
 3 files changed, 31 insertions(+), 9 deletions(-)

diffs (117 lines):

diff -r 3a5f7a9fbe02 -r d46fe552b6e6 sbin/dmesg/dmesg.8
--- a/sbin/dmesg/dmesg.8        Tue Oct 30 16:41:51 2018 +0000
+++ b/sbin/dmesg/dmesg.8        Tue Oct 30 19:40:35 2018 +0000
@@ -1,4 +1,4 @@
-.\"    $NetBSD: dmesg.8,v 1.25 2018/09/20 10:03:31 kre Exp $
+.\"    $NetBSD: dmesg.8,v 1.26 2018/10/30 19:40:36 kre Exp $
 .\"
 .\" Copyright (c) 1980, 1991, 1993
 .\"    The Regents of the University of California.  All rights reserved.
@@ -29,7 +29,7 @@
 .\"
 .\"     @(#)dmesg.8    8.1 (Berkeley) 6/5/93
 .\"
-.Dd September 18, 2018
+.Dd October 30, 2018
 .Dt DMESG 8
 .Os
 .Sh NAME
@@ -98,6 +98,12 @@
 command appeared in
 .Bx 3.0 .
 .Sh BUGS
+The
+.Fl T
+option will report nonsense when displaying lines from
+the message buffer that were not added by the current
+running kernel.
+.Pp
 When
 .Fl TT
 is used, the duration is always given with maximum units of hours,
diff -r 3a5f7a9fbe02 -r d46fe552b6e6 sbin/dmesg/dmesg.c
--- a/sbin/dmesg/dmesg.c        Tue Oct 30 16:41:51 2018 +0000
+++ b/sbin/dmesg/dmesg.c        Tue Oct 30 19:40:35 2018 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: dmesg.c,v 1.40 2018/09/20 23:46:42 kre Exp $   */
+/*     $NetBSD: dmesg.c,v 1.41 2018/10/30 19:40:36 kre Exp $   */
 /*-
  * Copyright (c) 1991, 1993
  *     The Regents of the University of California.  All rights reserved.
@@ -38,7 +38,7 @@
 #if 0
 static char sccsid[] = "@(#)dmesg.c    8.1 (Berkeley) 6/5/93";
 #else
-__RCSID("$NetBSD: dmesg.c,v 1.40 2018/09/20 23:46:42 kre Exp $");
+__RCSID("$NetBSD: dmesg.c,v 1.41 2018/10/30 19:40:36 kre Exp $");
 #endif
 #endif /* not lint */
 
@@ -151,7 +151,7 @@
 #ifndef SMALL
        char tbuf[64];
        char *memf, *nlistf;
-       struct timeval boottime;
+       struct timespec boottime;
        struct timespec lasttime;
        intmax_t sec;
        long nsec, fsec;
@@ -168,7 +168,7 @@
                radix = ".";    /* could also select "," */
 
        boottime.tv_sec = 0;
-       boottime.tv_usec = 0;
+       boottime.tv_nsec = 0;
        lasttime.tv_sec = 0;
        lasttime.tv_nsec = 0;
        deltas = quiet = humantime = 0;
@@ -337,6 +337,13 @@
                                        struct tm tm;
 
                                        t = boottime.tv_sec + sec;
+                                       if (nsec + boottime.tv_nsec >=
+                                           ( 1L                /* 1 second */
+                                                * 1000L        /* ms */
+                                                * 1000L        /* us */
+                                                * 1000L        /* ns */ ))
+                                                       t++;
+
                                        if (localtime_r(&t, &tm) != NULL) {
                                                strftime(tbuf, sizeof(tbuf),
                                                    "%a %b %e %H:%M:%S %Z %Y",
diff -r 3a5f7a9fbe02 -r d46fe552b6e6 sys/kern/init_main.c
--- a/sys/kern/init_main.c      Tue Oct 30 16:41:51 2018 +0000
+++ b/sys/kern/init_main.c      Tue Oct 30 19:40:35 2018 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: init_main.c,v 1.499 2018/10/26 18:16:42 martin Exp $   */
+/*     $NetBSD: init_main.c,v 1.500 2018/10/30 19:40:35 kre Exp $      */
 
 /*-
  * Copyright (c) 2008, 2009 The NetBSD Foundation, Inc.
@@ -97,7 +97,7 @@
  */
 
 #include <sys/cdefs.h>
-__KERNEL_RCSID(0, "$NetBSD: init_main.c,v 1.499 2018/10/26 18:16:42 martin Exp $");
+__KERNEL_RCSID(0, "$NetBSD: init_main.c,v 1.500 2018/10/30 19:40:35 kre Exp $");
 
 #include "opt_ddb.h"
 #include "opt_inet.h"
@@ -663,7 +663,16 @@
         * munched in mi_switch() after the time got set.
         */
        getnanotime(&time);
-       boottime = time;
+       {
+               struct timespec ut;
+               /*
+                * was:
+                *      boottime = time;
+                * but we can do better
+                */
+               nanouptime(&ut);
+               timespecsub(&time, &ut, &boottime);
+       }
 
        mutex_enter(proc_lock);
        LIST_FOREACH(p, &allproc, p_list) {