Re: What are the in-kernel functions to print human readable timestamps (bintime)?

On Fri, Mar 11, 2022 at 2:52 AM Alexander Leidinger <Alexander@leidinger.net>
wrote:

> Hi,
>
> I'm looking for a function to convert bintime to a human readable
> format in the kernel... and what is the usual format we use?
>

Yes. We don't generally log it.


>
> The use case for this is: if something throws a log from the kernel
> about a signal, I want to know when it happened, or in terms of code
> see below (tabs are most probably messed up).
>
> Do we have some kind of policy in terms of kernel messages and
> timestamps? Like "do not commit logging with timestamps"?


Correct. The kernel doesn't know enough to properly render timestamps,
nor should it. It's a lot more complicated than you'd expect, and the
simple,
naive implementation has too many flaws...


> I have the
> code below because I needed it at least once and think something like
> this (in a human readably shape) would be beneficial to have in the
> tree.
>

I really don't want to see code like that in the tree. Having it per-message
in an ad-hoc manner strikes me as quite unwise, since how do you interpret
it after the fact, especially in the face of adjustments to boottime for any
time adjustments that happen after the event.

Now, having said that, having good timestamps in the dmesg buffer is
a desirable feature. 'Good' is subjective here, and there are times early
in boot where it's simply not possible to get a time better than '0' until
the timehands are ticking...  But the dmesg buffer has more than what
dmesg prints: it has syslog'd things (at least some of them) as well.
There's
also a priority that some lines have. <3>Foo, for example. It would be
better,
imho, to add a timestamp to the start of the lines (perhaps optionally
since that might be expensive in $HUGE systems, or at times of
extreme dmesg spew and the could be omitted in those cases).
If you are interested in just the log messages, it wouldn't be terrible
since we already add stuff to what's printed for the priority. We could say
<3,seconds-since-boot.fracsec> instead of just <3> and hack dmesg
to print the right thing.

Warner


> Code:
> ---snip---
> diff --git a/sys/kern/kern_sig.c b/sys/kern/kern_sig.c
> index 4a15bd45355..a83eebe0736 100644
> --- a/sys/kern/kern_sig.c
> +++ b/sys/kern/kern_sig.c
> @@ -80,6 +80,7 @@ __FBSDID("$FreeBSD$");
>   #include <sys/sysent.h>
>   #include <sys/syslog.h>
>   #include <sys/sysproto.h>
> +#include <sys/time.h>
>   #include <sys/timers.h>
>   #include <sys/unistd.h>
>   #include <sys/wait.h>
> @@ -3440,14 +3441,18 @@ sigexit(struct thread *td, int sig)
>                   */
>                  if (coredump(td) == 0)
>                          sig |= WCOREFLAG;
> -               if (kern_logsigexit)
> +               if (kern_logsigexit) {
> +                       struct bintime now;
> +
> +                       getbintime(&now);
>                          log(LOG_INFO,
> -                           "pid %d (%s), jid %d, uid %d: exited on "
> -                           "signal %d%s\n", p->p_pid, p->p_comm,
> +                           "%zd: pid %d (%s), jid %d, uid %d: exited on "
> +                           "signal %d%s\n", now.sec, p->p_pid, p->p_comm,
>                              p->p_ucred->cr_prison->pr_id,
>                              td->td_ucred->cr_uid,
>                              sig &~ WCOREFLAG,
>                              sig & WCOREFLAG ? " (core dumped)" : "");
> +               }
>          } else
>                  PROC_UNLOCK(p);
>          exit1(td, 0, sig);
> ---snip---
>
> Bye,
> Alexander.
>
> --
> http://www.Leidinger.net Alexander@Leidinger.net: PGP 0x8F31830F9F2772BF
> http://www.FreeBSD.org    netchild@FreeBSD.org  : PGP 0x8F31830F9F2772BF
>