Re: "dmesg -T" date doesn't match "date" output

[Robert Elz <kre%munnari.OZ.AU@localhost>]

    Date:        Sun, 28 Oct 2018 13:14:34 +0100
    From:        Michael van Elst <mlelstv%serpens.de@localhost>
    Message-ID:  <20181028121433.GA20696%serpens.de@localhost>

  | On Sun, Oct 28, 2018 at 04:45:58PM +0700, Robert Elz wrote:
  |
  | > 1.  when the firmware is told to boot
  | > 2.  when the boot loader gets control from the firmware
  | > 3.  when the kernel first starts executing.
  | 3a. when the kernel has started clock
  | 3b. when the kernel has mounted root
  | > 4.  When the kernel starts init
  | > 5.  When /etc/rc finishes

3a and 3b aren't plausible definitions of when the system booted,
those are just implementation artifacts

  | $uptime is counted from 3a (maybe still starting at 1 instead of 0 ?).

The way it is currently done, yes, the question is how it ought be done.
[Aside: according to w (aka uptime) "uptime" is now - boottime rounded
to the nearest minute (ignoring all but the seconds parts of the times) -
that is, extraordinarily imprecise.   If the result is less than a minute 
(which means (now-boottime) < 30 seconds) the uptime does not exist.]

Note that none of the answers matter (other than for the timestamp values
printed with kernel messages, which are just offsets from something) until
we reach point 4 - until then the internal value of boottime (and time) is
mostly irrelevant (boottime, entirely irrelevant).

  | For absolute timestamps in dmesg it's not necessary to change

Yes, that could be fixed easily.   One way would be to simply subtract
the current time (as reported in the messages - the offset since T0) from
boottime when setting it (so boottime would become T0).

  | how we define $boottime.

No, for dmesg alone we do not.   But since we're here, rather than
adding yet another hack, I thought it would be better to actually
define what is boot time - in a way that can be explained and makes
some sense (and isn't "some random point about 6 seconds after
the kernel stats running, and 3 or 4 seconds before init starts" !)

  | We just have to find a suitable value for $time
  | at 3a so that this value can be added to the relative timestamp in the
  | log to get an absolute time.

subtracted from (unless you make it negative) and yes, that would
also be easy, but if that is to be the fix, simply altering the setting
of boottime (not when it is set, but the value it is set to) would be
easier.

  | The easiest way to find such a value is to make a copy of $uptime
  | when $boottime is set. We _could_ also adjust $boottime directly,
  | changing how it is defined. Or we _could_ just expose the copied
  | $uptime value and let dmesg do the computation.

Yes, we could do either.   Since boottime is currently not really
defined, changing it by a few seconds isn't going to bother anyone.

Neither of those really defines what we mean when we say "the time
the system was booted" though, and I think it would be better to
do that first.   After that it is all just mechanics.

  | N.B. if the message buffer is big enough, you'll get dmesg entries
  | from several 'epochs' that are related to different values of
  | $boottime.

Yes, that's another problem, which we have already (the definition
of boottime, and how we apply it is irrelevant to this).

  | To handle this, you have to log when an epoch starts
  | and what value of $boottime was valid then.

Truly a difficult problem without a lot of extra mechanism.

The only really good way to handle that would be to log
absolute (rather than relative) time in the messages, but
that precludes logging anything until we reach 3b, and
that's not reasonable, and would also make all of the
messages contain big numbers, rather than the current
relatively small ones.

Just adding extra messages in the log buffer is no use, as
we cannot expect the last of those to still be there when
we need to use it (that one would vanish early, then all
the later messages are still missing their offset).   Logging
it periodically would also not be useful (just more noise)
even if we put it only in the buffer and not on the console.

Even if it were there, the early messages from a new
boot would be before it, and appear to belong to the
old boottime, rather than the next one (though one can detect
that when they suddenly get smaller).   A big mess.

For now, I think we should just learn to understand
that the timestamps on any messages that predate the
current boot are meaningful only in relative form.

Perhaps dmesg could scan the buffer before printing
anything, locate the first message from the most recent
boot, and refuse to do absolute time translations on any
earlier messages ?

  | But matching this with real time is difficult.

An understatement I think.

kre