Debug: Add option for microsecond precision in debug.log #6881

pull sdaftuar wants to merge 1 commits into bitcoin:master from sdaftuar:add-microsecond-timestamps changing 5 files +22 −3

sdaftuar commented at 6:23 PM on October 23, 2015: member

(Inspired by #6880)
btcdrak commented at 6:26 PM on October 23, 2015: contributor

Thanks for picking it up, not sure why the other got closed.
morcos commented at 12:44 AM on October 24, 2015: member

Concept ACK. I'd really like the higher precision.
in src/utiltime.cpp:None in a606db326d outdated
```
  39 | @@ -40,6 +40,14 @@ int64_t GetTimeMicros()
  40 |              boost::posix_time::ptime(boost::gregorian::date(1970,1,1))).total_microseconds();
  41 |  }
  42 |  
  43 | +/** Return a time useful for the debug log */
  44 | +int64_t GetLogTimeMicros()
  45 | +{
  46 | +    if (nMockTime) return nMockTime*1000000;
```
TheBlueMatt commented at 1:07 AM on October 24, 2015:

Do we really care about mock times for debug log entires?

petertodd commented at 7:42 PM on October 24, 2015:

I think we should, as if we ever give a way to change the mocktime via RPC it'd be useful to be able to correlate the log files to what time we set.

sdaftuar commented at 2:10 PM on October 26, 2015:

Yeah I have some code I use to test that plays back historical data to a node and uses mocktime, and having the debug log have (mostly) consistent timestamps is helpful to me, so I figured I'd preserve the existing behavior.
laanwj commented at 6:02 AM on October 24, 2015: member

Concept ACK - can be useful. Do keep it disabled by default, high-precision time makes correlation/side channel attacks easier, better to not make the logs more valuable.

in src/init.cpp:None in a606db326d outdated

 726 | @@ -726,6 +727,7 @@ bool AppInit2(boost::thread_group& threadGroup, CScheduler& scheduler)
 727 |      // Set this early so that parameter interactions go to console
 728 |      fPrintToConsole = GetBoolArg("-printtoconsole", false);
 729 |      fLogTimestamps = GetBoolArg("-logtimestamps", true);
 730 | +    fLogTimeMicros = GetBoolArg("-logtimemicros", false);

MarcoFalke commented at 2:16 PM on October 24, 2015:

Nit: Can you use the already present fLogTimeMicros which defaults to false instead of hardcoding it twice? (c.f. #6349)

sdaftuar commented at 2:11 PM on October 26, 2015:

Good idea; fixed.

petertodd commented at 7:42 PM on October 24, 2015: contributor

Concept ACK
laanwj added the label Feature on Oct 26, 2015
sdaftuar force-pushed on Oct 26, 2015
instagibbs commented at 5:53 PM on October 26, 2015: member

ACK, works as advertised
gmaxwell commented at 6:30 PM on October 26, 2015: contributor

GetTimeMicros() is not a monotone clock. Will doom befall our users when the log entry timestamps sometimes go backwards?

in src/init.cpp:None in fc099a3b22 outdated

 726 | @@ -726,6 +727,7 @@ bool AppInit2(boost::thread_group& threadGroup, CScheduler& scheduler)
 727 |      // Set this early so that parameter interactions go to console
 728 |      fPrintToConsole = GetBoolArg("-printtoconsole", false);
 729 |      fLogTimestamps = GetBoolArg("-logtimestamps", true);
 730 | +    fLogTimeMicros = GetBoolArg("-logtimemicros", fLogTimeMicros);

laanwj commented at 6:39 PM on October 26, 2015:

Instead of passing fLogTimeMicros both as input and output I'd prefer the default to be handled like the others, e.g. in the header,

static const bool DEFAULT_LOGTIMEMICROS = false;

Then

strUsage += HelpMessageOpt("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS));
...
LogTimeMicros = GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);

sdaftuar commented at 6:48 PM on October 26, 2015:

Will do -- is that fine to put in util.h, since the global is declared in util.cpp? (I don't see anything else like that in util.h, so just want to double-check.)

laanwj commented at 6:57 PM on October 26, 2015:

Yep, sounds good to me. You're right that the other options in util.h don't stick to this either, but it's the sane thing to do for new options :)

laanwj commented at 6:56 PM on October 26, 2015: member

@gmaxwell I don't think potential jumps in time will have apocalyptic effect for users. The debug log is meant for reporting to humans, which can generally cope. Using monotone time for log timestamps is not very usual - as it counts since some unspecified starting point, it is only useful for deltas.
Add option for microsecond precision in debug.log 7bbc7c314f
sdaftuar force-pushed on Oct 26, 2015
jgarzik commented at 7:07 PM on October 26, 2015: contributor

ut ACK - though I do not see value in making this yet another option

IMO just add micros to the log and be done with it.
gmaxwell commented at 7:54 PM on October 26, 2015: contributor

@laanwj There are other ways to make the time monotone-- apply max with the last priinted time. (OS returned monotone time can also be adjusted to whatever timebase by finding the initial offset; but that goes down a rabbit hole).

WRT Jeff's comment. I too would rather have them on all the time, and any message where we're worried about creating privacy violating logs, we should just stop logging them by default-- they're probably already problematic with 1 second times. (I'm not sure which messages these would be as I don't currently have any nodes without debugging turned up!)
laanwj merged this on Oct 26, 2015
laanwj closed this on Oct 26, 2015
laanwj referenced this in commit 2b625510d3 on Oct 26, 2015
laanwj commented at 8:05 PM on October 26, 2015: member

Would really like to keep this an option, so will merge as-is.
jgarzik commented at 8:11 PM on October 26, 2015: contributor

@laanwj Justification?

More options = more work. Where is the value in yet another default-off option that few users will ever know about, much less use?

Default-off this is basically dead code we must maintain.
laanwj commented at 8:15 PM on October 26, 2015: member

See my post above. Also there is no need for microsecond timestamps for most people. It will just take up more horizontal space. If you need them ,you can enable them.
jgarzik commented at 8:33 PM on October 26, 2015: contributor

@laanwj "no need for microsecond timestamps for most people" Citation needed?

Apache, MySQL, Linux kernel, several sys-loggers and other major servers/services moved to sub-second timestamps a while ago.
petertodd commented at 9:08 PM on October 26, 2015: contributor

FWIW I've never even needed second-precision timestamps myself. Equally, dmesg for example gives me "seconds since boot" or something, rather than what I usually am more interested in, the date - wouldn't use that as an example of user friendly for general debugging.
luke-jr referenced this in commit 0d6449af9d on Nov 27, 2015
MarcoFalke locked this on Sep 8, 2021

Contributors

Labels

Linked (view graph)

#6880 New -logtimerelative option to do millisec debug.log timestamps