[Swan-dev] hi resolution time in log file

D. Hugh Redelmeier hugh at mimosa.com
Thu Nov 2 16:13:08 UTC 2017


| From: Andrew Cagney <andrew.cagney at gmail.com>

| 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.

I would have thought that a log entry would be easy to ascribe to an
event.

| 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.

If it matters for a particular log entry (and not many distinct ones)
then add it to that log entry.  If it is needed pervasively, log it
pervasively.

| (we've also got multiple threads and forks so we need to be able to
| reliably log that interaction to a fine level)

Really?  There intereaction isn't based on fine-grained time as far as
I know.  It is based on causality (inducing time relationships) and on
gross time-outs.

| > | 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

I assume that you mean a macro to hide the details.  Sure.

| 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.

Yes.  The code I never finished was intended to make a more universal
and opaque representation for Pluto code to use.  Only at the interface 
with the system does the representation get opened.

There are still different kinds of time and they should have distinct 
types -- we want the compiler enforce some logical restrictions.

Note: if is represented by floating point, I will become uncomfortable 
with any tests that care about equality.  In general, equality is not 
meaningful in FP; ensuring that you are in one of the special cases where 
it is meaningful is an unpleasant burden on the reader and the writer.

| 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)

Sadly NSS appears to be a pig.  But even if it weren't, crypto is a
pig.

Code size matters too.  There again, I think NSS is a pig.  When we
used our own crypto code, I think crypto took a lot less space
relatively.

One big code and time expense is our logging, especially our debug
logging.  It used to be that we could compile without it but that no
longer is the case.

We really ought to go through the logging to see what deserves to be
tossed.  It is easy to add logging but nobody removes it.


More information about the Swan-dev mailing list