Re: CVS commit: src/sys/kern

[Robert Elz]

Date:Sat, 14 Apr 2018 05:24:40 +1000
From:matthew green 
Message-ID:  <8304.1523647...@splode.eterna.com.au>

  |  i'd recommend going for at  least 100ns intervals, if not 10ns.

I have implemented it in a way that the precision can be controlled
by sysctl - without actually adding the sysctl magic to make that
happen (someone more familiar with that should be able to add it
easily, it is just an integer variable to be accessed/set).

This way sites that need lots of precision in the timing of log
messages can get it, and those that prefer smaller log lines
can choose that instead (once someone implements the sysctl.)

  | we could also make this only relevant on ports with cpus that
  | have faster cpus, leaving older systems with smaller logs.

The default (which I have surrently set at units of 100nsec - ie: 7 digits)
could be made to depend upon the port, or even on the detected
clock rate of the CPU for ports that support a significantly wide range.

  | (the seconds part shouldn't change, i think, as there is no
  | reason to believe any port has longer uptime than another.)

The seconds field simply grows as needed and can handle systems
that boot now and are still running when the sun goes supernova
(I doubt any will still be running after that).

I have made dmesg dynamically adapt to what the kernel happens to
send (on a message by mesage basis) but still (as it does today) print
all (numermic format timestamps and deltas) timestamps in units of
microseconds.   Once this is cheked in if someone wants to add an
option to dmesg to control the precision it prints, go for it.

This is all being tested now - but as I don't have the sysctl code implemented,
and I am way too lazy to learn how top make gdb patch a running system,
testing different precisions for the log messages takes rebuilding and 
rebooting, so it is kind of slow. 

kre

Re: CVS commit: src/sys/kern

[Jason Thorpe]

> On Apr 13, 2018, at 12:24 PM, matthew green  wrote:
> 
> we could also make this only relevant on ports with cpus that
> have faster cpus, leaving older systems with smaller logs.
> (the seconds part shouldn't change, i think, as there is no
> reason to believe any port has longer uptime than another.)

I would actually argue that slower systems should tend to have a longer uptime. 
 After all, there’s less opportunity for something to go wrong per unit of wall 
clock time :-)

-- thorpej

re: CVS commit: src/sys/kern

[matthew green]

Robert Elz writes:
> Date:Fri, 13 Apr 2018 05:21:16 -0400
> From:"Christos Zoulas" 
> Message-ID:  <20180413092116.b3b08f...@cvs.netbsd.org>
> 
>   |   src/sys/kern: subr_prf.c
> 
>   | make this narrower by popular request.
> 
> Would it perhaps be reasonable to just print microseconds (or even
> 10's or 100's of microseconds) instead of nanoseconds ?
> 
>   n = snprintf(buf, sizeof(buf), "[% 5jd.%.6ld] ",
>   (intmax_t)ts.tv_sec, ts.tv_nsec / 1000);
> 
> (or .5d and 1 or .4d and 10).   And perhaps really
> 4jd instead of 5jd - once it is well past dmesg.boot range, it
> doesn't matter nearly so much if occasionally the times don't
> line up - from 4 -> 5 digits is 2:45 approx, from 5->6 is over a
> day, and 11 1/2 days to switch to 7 digits.

in my day job we've been requested to add nanosecond as there
are too many times the same microsecond has many logs.  modern
CPUs can get a lot done in 1us.  i'd recommend going for at
least 100ns intervals, if not 10ns.

we could also make this only relevant on ports with cpus that
have faster cpus, leaving older systems with smaller logs.
(the seconds part shouldn't change, i think, as there is no
reason to believe any port has longer uptime than another.)

thanks.


.mrg.

Re: CVS commit: src/sys/kern

[Christos Zoulas]

In article <12933.1523625...@jinx.noi.kre.to>,
Robert Elz   wrote:
>Date:Fri, 13 Apr 2018 05:21:16 -0400
>From:"Christos Zoulas" 
>Message-ID:  <20180413092116.b3b08f...@cvs.netbsd.org>
>
>  |src/sys/kern: subr_prf.c
>
>  | make this narrower by popular request.
>
>Would it perhaps be reasonable to just print microseconds (or even
>10's or 100's of microseconds) instead of nanoseconds ?
>
>   n = snprintf(buf, sizeof(buf), "[% 5jd.%.6ld] ",
>   (intmax_t)ts.tv_sec, ts.tv_nsec / 1000);
>
>(or .5d and 1 or .4d and 10).   And perhaps really
>4jd instead of 5jd - once it is well past dmesg.boot range, it
>doesn't matter nearly so much if occasionally the times don't
>line up - from 4 -> 5 digits is 2:45 approx, from 5->6 is over a
>day, and 11 1/2 days to switch to 7 digits.

I am fine with all. If the scale changes, we'll need to change dmesg...

christos

Re: CVS commit: src/sys/kern

[Robert Elz]

Date:Fri, 13 Apr 2018 05:21:16 -0400
From:"Christos Zoulas" 
Message-ID:  <20180413092116.b3b08f...@cvs.netbsd.org>

  | src/sys/kern: subr_prf.c

  | make this narrower by popular request.

Would it perhaps be reasonable to just print microseconds (or even
10's or 100's of microseconds) instead of nanoseconds ?

n = snprintf(buf, sizeof(buf), "[% 5jd.%.6ld] ",
(intmax_t)ts.tv_sec, ts.tv_nsec / 1000);

(or .5d and 1 or .4d and 10).   And perhaps really
4jd instead of 5jd - once it is well past dmesg.boot range, it
doesn't matter nearly so much if occasionally the times don't
line up - from 4 -> 5 digits is 2:45 approx, from 5->6 is over a
day, and 11 1/2 days to switch to 7 digits.

kre