log: Move "Pre-allocating up to position 0x[…] in […].dat" log message to debug category

practicalswift commented at 6:31 pm on January 31, 2021: contributor

Move Pre-allocating up to position 0x[…] in […].dat log message to debug category.

After the cleanup of -debug=net log messages PR (#20724) was merged recently the console log now has very high signal to noise ratio. That’s great! :)

This PR increases the signal to noise ratio slightly more by moving the most common remaining implementation detail log message (Pre-allocating up to position 0x[…] in […].dat) to the debug category where it belongs :)

Expected standard output from bitcoind (when in steady state) before this patch:

0$ src/bitcoind
1…
20000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
30000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
40000-00-00T00:00:00Z Pre-allocating up to position 0x0000000 in blk00000.dat
50000-00-00T00:00:00Z Pre-allocating up to position 0x000000 in rev00000.dat
60000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
70000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
80000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)

Expected standard output from bitcoind (when in steady state) after this patch:

0$ src/bitcoind
1…
20000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
30000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
40000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
50000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)
60000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo)

I find the latter alternative much easier to visually scan for anomalies (and more aesthetically pleasing TBH!).

Non-GUI users deserve nice interfaces too :)

ajtowns commented at 7:50 pm on January 31, 2021: member

ConceptACK

theStack commented at 8:10 pm on January 31, 2021: member

Concept ACK

DrahtBot added the label Utils/log/libs on Jan 31, 2021

ajtowns commented at 9:33 pm on January 31, 2021: member

Maybe also do Leaving block file from validation.cpp:FindBlockPos() ?

practicalswift commented at 9:43 pm on January 31, 2021: contributor

@ajtowns Good idea! Updated version pushed :)

DrahtBot commented at 2:26 am on February 1, 2021: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

in src/logging.h:59 in 0d674b5588 outdated

55@@ -56,6 +56,7 @@ namespace BCLog {
56         QT          = (1 << 19),
57         LEVELDB     = (1 << 20),
58         VALIDATION  = (1 << 21),
59+        FLATFILE    = (1 << 22),

laanwj commented at 10:06 am on February 1, 2021:

I am not sure it makes sense to make a new debug category for this.

But if you do, I would prefer something conceptual like “BLOCKSTORE”, flat file is an implementation detail and fairly irrelevant to users.

Also don’t forget updating the table in logging.cpp so that it can actually be enabled :slightly_smiling_face:

practicalswift commented at 3:15 pm on February 1, 2021:

Good points!

Now putting it in BLOCKSTORE which is better than FLATFILE for the reasons you mentioned. Now also adding it to logging.cpp. Thanks!

(Even with BLOCKSTORE I agree it feels a bit bad to add a debug category for this, but I can’t find an existing category that would make sense :))

laanwj commented at 10:06 am on February 1, 2021: member

Concept ACK on moving these messages to debug.

practicalswift force-pushed on Feb 1, 2021

ajtowns commented at 10:00 pm on February 1, 2021: member

Probably should be a separate PR, but might be worth thinking about moving the New outbound peer connected: ... (block-relay-only) messages to a debug category too, at least for the transient connections? (And perhaps add a new Replacing old outbound block-relay-only connection peer=X with peer=Y for the rare case when the new connection isn’t transient because you drop one of your original block-relay-only connections instead). Those messages and the ones this PR already deals with look like most of the noise in my logs currently, at any rate.

practicalswift force-pushed on Feb 2, 2021

in src/validation.cpp:3222 in 3adb5af640 outdated

3218@@ -3219,7 +3219,7 @@ static bool FindBlockPos(FlatFilePos &pos, unsigned int nAddSize, unsigned int n
3219 
3220     if ((int)nFile != nLastBlockFile) {
3221         if (!fKnown) {
3222-            LogPrintf("Leaving block file %i: %s\n", nLastBlockFile, vinfoBlockFile[nLastBlockFile].ToString());
3223+            LogPrint(BCLog::VALIDATION, "Leaving block file %i: %s\n", nLastBlockFile, vinfoBlockFile[nLastBlockFile].ToString());

laanwj commented at 8:14 pm on February 10, 2021:

Thanks for making the change, but shouldn’t this be in BLOCKSTORE too? (or move the other to validation, I don’t know, it seems that it would make sense to have the messages about block files in the same category not disjunct ones)

practicalswift commented at 8:48 pm on February 10, 2021:

Good point. Moved both to VALIDATION.

Felt a bit bad to introduce BLOCKSTORE for a single log message: nice to get rid of it! :)

log: Move "Leaving block file [...]: [...]" log message to debug category acd7980b37

log: Move "Pre-allocating up to position 0x[...] in [...].dat" log message to debug category 25f899cc23

practicalswift force-pushed on Feb 10, 2021

laanwj commented at 6:54 pm on February 11, 2021: member

ACK 25f899cc23a791c08e19acae91bebda6c3538d37

laanwj merged this on Feb 11, 2021

laanwj closed this on Feb 11, 2021

sidhujag referenced this in commit d60eaac0e8 on Feb 11, 2021

practicalswift deleted the branch on Apr 10, 2021

DrahtBot locked this on Aug 16, 2022

log: Move “Pre-allocating up to position 0x[…] in […].dat” log message to debug category #21041

Conflicts