Log/report in 10% steps during VerifyDB #8136

jonasschnelli commented at 11:58 AM on June 2, 2016: contributor

By default Bitcoin-Core does verify the last 288 blocks. This can take a couple of minutes on slow systems.

This PR adds a simple progress report during VerifyDB in 10% steps into the debug log. I think misusing the debug.log for this – relatively long taking process – is okay.

Example:

2016-06-02 11:56:01 init message: Verifying blocks...
2016-06-02 11:56:01 Verifying last 288 blocks at level 3
[0%]...[10%]...[20%]...[30%]...[40%]...[50%]...[60%]...[70%]...[80%]...[90%]...[DONE].
No coin database inconsistencies in last 289 blocks (68239 transactions)

jonasschnelli added the label Docs and Output on Jun 2, 2016

sipa commented at 12:24 PM on June 2, 2016: member

Perhaps we should also reduce the number 288. Maybe a limit specified in number of transactions is better?

jonasschnelli commented at 12:33 PM on June 2, 2016: contributor

Agree with @sipa, but could be a different PR (very likely more controversial).

sipa commented at 12:35 PM on June 2, 2016: member

Sure, that's independent of this PR.

dcousens commented at 3:09 PM on June 2, 2016: contributor

concept ACK

dcousens commented at 3:10 PM on June 2, 2016: contributor

edit: moved comment to #8138 (comment)

in src/main.cpp:None in 3868879419 outdated

3880 |          boost::this_thread::interruption_point();
3881 | -        uiInterface.ShowProgress(_("Verifying blocks..."), std::max(1, std::min(99, (int)(((double)(chainActive.Height() - pindex->nHeight)) / (double)nCheckDepth * (nCheckLevel >= 4 ? 50 : 100)))));
3882 | +        int percentageDone = std::max(1, std::min(99, (int)(((double)(chainActive.Height() - pindex->nHeight)) / (double)nCheckDepth * (nCheckLevel >= 4 ? 50 : 100))));
3883 | +        if (reportDone < percentageDone/10) {
3884 | +            // report every 10% step
3885 | +            LogPrintf("[%d%%]...", percentageDone);

laanwj commented at 2:05 PM on June 6, 2016:

It's inventive to print a partial line here instead of a full line - however this can only work if there is nothing else happening in the background, otherwise partial log messages will mix. As this is only called during AppInit2 I suppose it's safe.

jonasschnelli commented at 6:29 PM on June 6, 2016:

I think its fragile but okay as long as it is somewhere on the upper section of AppInit2(). :-)

in src/main.cpp:None in 3868879419 outdated

3866 | @@ -3867,16 +3867,23 @@ bool CVerifyDB::VerifyDB(const CChainParams& chainparams, CCoinsView *coinsview,
3867 |      if (nCheckDepth > chainActive.Height())
3868 |          nCheckDepth = chainActive.Height();
3869 |      nCheckLevel = std::max(0, std::min(4, nCheckLevel));
3870 | -    LogPrintf("Verifying last %i blocks at level %i\n", nCheckDepth, nCheckLevel);
3871 | +    LogPrintf("Verifying last %i blocks at level %i\n[0%%]...", nCheckDepth, nCheckLevel);

laanwj commented at 2:06 PM on June 6, 2016:

for clarity, let's put the 0%% in a new LogPrintf() here

jonasschnelli force-pushed on Jun 6, 2016

jonasschnelli commented at 6:29 PM on June 6, 2016: contributor

Fixed @laanwj nit.

laanwj commented at 7:26 AM on June 7, 2016: member

Tested with -printtoconsole:

2016-06-07 07:16:19 [0%%]...[10%]...[20%]...[30%]...[40%]...[50%]...[60%]...[70%]...[80%]...[90%]...[DONE].
No coin database inconsistencies in last 21 blocks (30100 transactions)
2016-06-07 07:20:17  block index          242905ms

For some reason the second line doesn't get a time/date header. This seems like a bug in LogPrintf. To work around maybe use a separate LogPrintf line there same as you did for the 0%.
Also: the first is %%, the second and latter are %. This is an effect of a printf without argument being not a printf at all but a literal string print. https://github.com/bitcoin/bitcoin/blob/master/src/util.h#L94

Log/report in 10% steps during VerifyDB 8b78486d02

jonasschnelli force-pushed on Jun 7, 2016

jonasschnelli commented at 9:05 AM on June 7, 2016: contributor

Thanks for testing! Fixed the 0%% text typo as well as the missing time/date header (switched to a single line for the [DONE] part.

laanwj commented at 1:24 PM on June 7, 2016: member

Tested ACK https://github.com/bitcoin/bitcoin/pull/8136/commits/8b78486d02ed3c1c217d79ebca78a70d73e0d570

2016-06-07 13:21:01 Verifying last 288 blocks at level 3
2016-06-07 13:21:01 [0%]...[10%]...[20%]...[30%]...[40%]...[50%]...[60%]...[70%]...[80%]...[90%]...[DONE].
2016-06-07 13:23:39 No coin database inconsistencies in last 23 blocks (35781 transactions)

Slightly tangential: the progress reporting is quite distorted, by far most of the time is spent at 0%, then it seems to take a sprint for 100%.

laanwj merged this on Jun 7, 2016

laanwj closed this on Jun 7, 2016

laanwj referenced this in commit 22e0b35676 on Jun 7, 2016

codablock referenced this in commit 9b8c0cdc0f on Sep 16, 2017

codablock referenced this in commit adc630cfdf on Sep 19, 2017

codablock referenced this in commit d5d25564cf on Dec 22, 2017

andvgal referenced this in commit 5f719fa2bf on Jan 6, 2019

MarkLTZ referenced this in commit e8e96e9c25 on Apr 28, 2019

furszy referenced this in commit 0e264e2607 on Jun 28, 2021

MarcoFalke locked this on Sep 8, 2021