[Swan-dev] hi resolution time in log file

[Andrew Cagney]

On 30 October 2017 at 15:11, D. Hugh Redelmeier <hugh at mimosa.com> wrote:

> | From: Andrew Cagney <andrew.cagney at gmail.com>
>
> | I noticed that the timestamp added to log files has only a 1 second
> | resolution; this isn't much help when multiple events get processed per
> | second.
>
> I haven't read logs much in a long time.  So my opinions should be
> taken with a grain of salt.
>
> Most of Pluto is a single thread.  The relationship between log lines
> is mostly sequential.  So fine-grained timing isn't important.
>
>
Our log time resolution needs to be more fine-grained than our smallest
timeout and that is sub-second (1_000_000 was chosen because it was easy).
Without this it isn't possible to tell if adjacent log events for the same
state are for the same or different events.

For instance, with xauth, pluto sends out back-to-back packets separated by
a small delay; since we can't see the delay in the logs we can't confirm
this is working.
(we've also got multiple threads and forks so we need to be able to
reliably log that interaction to a fine level)


| PS: I'm also left wondering why delta time isn't a double, would make
> | specifying sub-second timers a lot easier (i.e., 0.5)
>
> In the past, there was some advantage in never using floating point.
> That may be true on systems that use static linking and on some
> embedded systems.
>
> FP object code is generally fatter and slower than integer code, but
> perhaps not when the representation is wider than the integer ALU.
>
> Floating point is very hard to reason about.  It has all sorts of
> surprises.  God invented the integers.
>
> Many months ago I coded a change to represent in a higher precision,
> with an opaque type.  Before I got it checked in, the tree changed
> (event handling rewrite?) and I never got around to merging.
>

I look at it as separate issues:

- deltatime_t's internal representation; since it needs to at least have
the same resolution as the event loop, it might as well use the event-loops
type

- where we specify a sub-second timeout constant, 0.5 is far easier than
((deltatime_t) { { 0, 500000 } }); presumably deltatime() can deal with this

However, we've still got lots of code forced to bypass all this - the
interface for scheduling timers either takes seconds, milli-seconds, or
struct timeval.

Andrew

PS: we're spending our time grinding through NSS crypto, everything else is
in the noise (well almost, on very very loaded systems, the old linked list
version of serialno_t->struct state and the locking version of logging both
turn up in profiles)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20171101/c534127d/attachment.html>