Add -benchmark for reporting block processing times #2059

sipa commented at 7:16 PM on December 1, 2012: member

Depends on #2058.

BitcoinPullTester commented at 7:40 PM on December 1, 2012: none

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/49f4d1d7ab71531d4552a7d1b5b79dfc99883d49 for binaries and test log.

sipa commented at 8:14 PM on December 1, 2012: member

Example output:

 - Connect 688 transactions: 758.16ms (1.102ms/tx, 0.623ms/txin)
 - Connect: 770.16ms
 - Flush 1455 transactions: 2.30ms (0.0016ms/tx)

BitcoinPullTester commented at 8:38 PM on December 1, 2012: none

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/c79fdf173098cb8ebdd9ab4f2a2b8e4fca1042ce for binaries and test log.

BitcoinPullTester commented at 1:22 AM on December 2, 2012: none

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/c222ef6d830d884e2075864029668884e3da9459 for binaries and test log.

Diapolo commented at 9:53 AM on December 2, 2012: none

Should all used printfs honor the fBenchmark flag? And shouldn't microseconds use µs instead of ms?

in src/util.h:None in c222ef6d83 outdated

 329 | @@ -330,6 +330,12 @@ inline int64 GetTimeMillis()
 330 |              boost::posix_time::ptime(boost::gregorian::date(1970,1,1))).total_milliseconds();
 331 |  }
 332 |  
 333 | +inline int64 GetTimeMicros()
 334 | +{
 335 | +    return (boost::posix_time::ptime(boost::posix_time::microsec_clock::universal_time()) -
 336 | +            boost::posix_time::ptime(boost::gregorian::date(1970,1,1))).total_microseconds();

Diapolo commented at 10:05 AM on December 2, 2012:

Seems timer resolution on Windows is always in the ms range, I tried that function.

sipa commented at 8:48 PM on December 2, 2012:

Windows doesn't provide a microsecond clock? Or boost::posix_time::microsec_block fails to implement its name?

Diapolo commented at 9:37 PM on December 2, 2012:

Boost (sometimes) fails to provide a microsecond clock for Windows, which seems to be a known issue.

sipa commented at 8:50 PM on December 2, 2012: member

@Diapolo I've changed the code to always report in ms, but sometimes with some decimals. Avoids the necessity for a mu symbol, and is more readable. All timing printfs should honor the fBenchmark yes - should be the case now.

Diapolo commented at 9:41 PM on December 2, 2012: none

@sipa Thanks, I'm fine with that benchmark stuff then.

Edit: Seems the Make SetBestChain() atomic sneaked in here ^^.

sipa commented at 11:48 PM on December 2, 2012: member

@Diapolo Yes, since they touch the same code, I didn't bother writing them separately (I even mentioned it on the pullreq summart!). If there's an issue with the other pullreq, I'll rebase this one, and if the other gets NAK'ed or delayed, I'll separate them.

Diapolo commented at 6:04 AM on December 3, 2012: none

@sipa I think your smaller pulls should make it much faster into master, so I have no problem with what I noted above :).

Add GetTimeMicros() for ore accurate benchmarking 0ae0712b1c

Add -benchmark for reporting block processing times 8a28bb6dee

sipa commented at 10:08 PM on December 5, 2012: member

@Diapolo Feel like testing this? I'd like to know what kind of output you get on Windows.

gavinandresen commented at 10:11 PM on December 5, 2012: contributor

ACK

Diapolo commented at 6:08 AM on December 6, 2012: none

@sipa Yeah, will do that today :). Do I need to start an IBD or are you fine with just any occurance of that messages from the log?

laanwj commented at 7:40 AM on December 6, 2012: member

ACK

Diapolo commented at 8:02 AM on December 6, 2012: none

@sipa Here are a few examples with current master + some mods to block file pre-alloc and CAutoFile (dunno if these are related for the benches).

12/06/12 07:57:25 - Connect 293 transactions: 2776.80ms (9.477ms/tx, 3.644ms/txin) 12/06/12 07:57:25 - Connect: 2870.41ms 12/06/12 07:57:25 - Flush 976 transactions: 0.00ms (0.0000ms/tx)

12/06/12 07:57:25 - Connect 108 transactions: 686.40ms (6.356ms/tx, 3.556ms/txin) 12/06/12 07:57:25 - Connect: 702.00ms 12/06/12 07:57:25 - Flush 271 transactions: 0.00ms (0.0000ms/tx)

12/06/12 07:57:26 - Connect 106 transactions: 748.80ms (7.064ms/tx, 3.404ms/txin) 12/06/12 07:57:26 - Connect: 748.80ms 12/06/12 07:57:26 - Flush 283 transactions: 0.00ms (0.0000ms/tx)

12/06/12 07:57:38 - Connect 409 transactions: 3291.61ms (8.048ms/tx, 3.275ms/txin) 12/06/12 07:57:38 - Connect: 3322.81ms 12/06/12 07:57:38 - Flush 1209 transactions: 0.00ms (0.0000ms/tx)

Is this a benchmark for LevelDB access and performance?

BitcoinPullTester commented at 3:36 AM on December 7, 2012: none

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/8a28bb6deee2df7dac3288c1bc6db6221e5e43b6 for binaries and test log.

Diapolo commented at 9:43 AM on December 7, 2012: none

Some values during IBD:

12/07/12 08:08:31 - Connect 60 transactions: 15.60ms (0.260ms/tx, 0.153ms/txin) 12/07/12 08:08:31 - Connect: 15.60ms 12/07/12 08:08:31 - Flush 146 transactions: 0.00ms (0.0000ms/tx)

12/07/12 08:08:32 - Connect 165 transactions: 31.20ms (0.189ms/tx, 0.092ms/txin) 12/07/12 08:08:32 - Connect: 46.80ms 12/07/12 08:08:32 - Flush 409 transactions: 0.00ms (0.0000ms/tx)

12/07/12 08:08:32 - Connect 240 transactions: 0.00ms (0.000ms/tx, 0.000ms/txin) 12/07/12 08:08:32 - Connect: 15.60ms 12/07/12 08:08:32 - Flush 530 transactions: 0.00ms (0.0000ms/tx)

Btw. ACK

sipa commented at 12:07 PM on December 7, 2012: member

@Diapolo Seems microsecond_clock on your system has a resolution of 15.6ms - what I assume to be 1/64 of a second. That makes the numbers -benchmark would report quite useless...

Diapolo commented at 12:19 PM on December 7, 2012: none

@sipa I didn't even take a close look at the numbers, but your assumption makes sense, if I look at the numbers. Any idea for a working code-path for Win32 then? I could try with GetTimeMillis() instead and see if that numbers make more sense, as at least a ms timer-resolution should be possible (and not a 15.6ms res).

sipa commented at 12:21 PM on December 7, 2012: member

@Diapolo GetTimeMillis uses the same boost function to get the actual time, so I doubt that will make any difference. Up to you to find something that gives an accurate clock in Windows :)

Diapolo commented at 12:23 PM on December 7, 2012: none

@sipa I had read some stuff a few days ago on that issue and it seems ... well hard to do it portable. Any the native WIN32 APIs for time stuff is a thing I've never used ^^. I'll take another look.

Edit: Note that the existence of the higher resolution classes (eg: nanoseconds) depends on the installation of the library. See Build-Compiler Information for more information. Any idea if that means we need to link against the boost_date_time library?

Edit 2: I tested, which timer resolution is available via:

<pre> secs = boost::posix_time::time_duration::num_fractional_digits(); printf("DEBUG: %u digits timer resolution available\n", secs); </pre>

DEBUG: 6 digits timer resolution available

So it seems Boost is believing it's able to use microsecond resolution... which IS not true as we saw from the results ;).

Edit 3: 12/07/12 13:06:13 - Connect 70 transactions: 444.03ms (6.343ms/tx, 3.442ms/txin) 12/07/12 13:06:13 DEBUG: 6 digits timer resolution available 12/07/12 13:06:13 - Connect: 451.03ms 12/07/12 13:06:13 - Flush 181 transactions: 1.00ms (0.0055ms/tx)

Next weird thing is I now have such results in the debug.log...

gavinandresen referenced this in commit 043a8fb98d on Dec 12, 2012

gavinandresen merged this on Dec 12, 2012

gavinandresen closed this on Dec 12, 2012

sipa deleted the branch on May 3, 2013

laudney referenced this in commit e6e0c84cf8 on Mar 19, 2014

DrahtBot locked this on Sep 8, 2021