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

Merged
merged 1 commit into from Oct 26, 2015

Conversation

Projects
None yet
10 participants
@sdaftuar
Member

sdaftuar commented Oct 23, 2015

(Inspired by #6880)

@btcdrak

This comment has been minimized.

Show comment
Hide comment
@btcdrak

btcdrak Oct 23, 2015

Member

Thanks for picking it up, not sure why the other got closed.

Member

btcdrak commented Oct 23, 2015

Thanks for picking it up, not sure why the other got closed.

@morcos

This comment has been minimized.

Show comment
Hide comment
@morcos

morcos Oct 24, 2015

Member

Concept ACK. I'd really like the higher precision.

Member

morcos commented Oct 24, 2015

Concept ACK. I'd really like the higher precision.

+/** Return a time useful for the debug log */
+int64_t GetLogTimeMicros()
+{
+ if (nMockTime) return nMockTime*1000000;

This comment has been minimized.

@TheBlueMatt

TheBlueMatt Oct 24, 2015

Contributor

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

@TheBlueMatt

TheBlueMatt Oct 24, 2015

Contributor

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

This comment has been minimized.

@petertodd

petertodd Oct 24, 2015

Contributor

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.

@petertodd

petertodd Oct 24, 2015

Contributor

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.

This comment has been minimized.

@sdaftuar

sdaftuar Oct 26, 2015

Member

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.

@sdaftuar

sdaftuar Oct 26, 2015

Member

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

This comment has been minimized.

Show comment
Hide comment
@laanwj

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

Member

laanwj commented Oct 24, 2015

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.

@MarcoFalke

View changes

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

This comment has been minimized.

@MarcoFalke

MarcoFalke Oct 24, 2015

Member

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

@MarcoFalke

MarcoFalke Oct 24, 2015

Member

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

This comment has been minimized.

@sdaftuar

sdaftuar Oct 26, 2015

Member

Good idea; fixed.

@sdaftuar

sdaftuar Oct 26, 2015

Member

Good idea; fixed.

@petertodd

This comment has been minimized.

Show comment
Hide comment
@petertodd

petertodd Oct 24, 2015

Contributor

Concept ACK

Contributor

petertodd commented Oct 24, 2015

Concept ACK

@laanwj laanwj added the Feature label Oct 26, 2015

@instagibbs

This comment has been minimized.

Show comment
Hide comment
@instagibbs

instagibbs Oct 26, 2015

Member

ACK, works as advertised

Member

instagibbs commented Oct 26, 2015

ACK, works as advertised

@gmaxwell

This comment has been minimized.

Show comment
Hide comment
@gmaxwell

gmaxwell Oct 26, 2015

Member

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

Member

gmaxwell commented Oct 26, 2015

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

@laanwj

View changes

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

This comment has been minimized.

@laanwj

laanwj Oct 26, 2015

Member

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);
@laanwj

laanwj Oct 26, 2015

Member

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

This comment has been minimized.

@sdaftuar

sdaftuar Oct 26, 2015

Member

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

@sdaftuar

sdaftuar Oct 26, 2015

Member

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

This comment has been minimized.

@laanwj

laanwj Oct 26, 2015

Member

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

laanwj Oct 26, 2015

Member

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

This comment has been minimized.

Show comment
Hide comment
@laanwj

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

Member

laanwj commented Oct 26, 2015

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

@jgarzik

This comment has been minimized.

Show comment
Hide comment
@jgarzik

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

Contributor

jgarzik commented Oct 26, 2015

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

This comment has been minimized.

Show comment
Hide comment
@gmaxwell

gmaxwell Oct 26, 2015

Member

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

Member

gmaxwell commented Oct 26, 2015

@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 laanwj merged commit 7bbc7c3 into bitcoin:master Oct 26, 2015

1 check was pending

continuous-integration/travis-ci/pr The Travis CI build is in progress
Details

laanwj added a commit that referenced this pull request Oct 26, 2015

Merge pull request #6881
7bbc7c3 Add option for microsecond precision in debug.log (Suhas Daftuar)
@laanwj

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Oct 26, 2015

Member

Would really like to keep this an option, so will merge as-is.

Member

laanwj commented Oct 26, 2015

Would really like to keep this an option, so will merge as-is.

@jgarzik

This comment has been minimized.

Show comment
Hide comment
@jgarzik

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

Contributor

jgarzik commented Oct 26, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@laanwj

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

Member

laanwj commented Oct 26, 2015

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

This comment has been minimized.

Show comment
Hide comment
@jgarzik

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

Contributor

jgarzik commented Oct 26, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@petertodd

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

Contributor

petertodd commented Oct 26, 2015

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 added a commit to luke-jr/bitcoin that referenced this pull request Nov 27, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment