Overview of slow unit tests

[laanwj]

At last IRC meeting we've discussed trying to speed up the unit tests, as they've become much too slow.
For this purpose I've run test_bitcoin --log_level=test_suite and picked out the slowest from the list.

The top 20 is (updated 2018-04-14 by @lucash-dev):

Test	Time (μs)
test_big_witness_transaction	39133014
test_CheckQueue_Correct_Random	14808019
knapsack_solver_test	9304171
checkinputs_test	6370348
CreateNewBlock_validity	6105558
test_CheckQueue_Memory	4230330
versionbits_test	3835090
coins_cache_simulation_test	3205869
updatecoins_simulation_test	2499840
merkle_test	2391688
rescan	1900315
SelectCoins_test	1731901
passphrase	1730167
ListCoins	1689793
test_CheckQueue_Catches_Failure	1563869
test_CheckQueue_UniqueCheck	1521864
PrevectorTestInt	1409636
test_CheckQueue_Correct_Max	1401687
bnb_search_test	1147974
cuckoocache_generations	978637

I think (open for discussion, of course) it is unreasonable for a unit test case to take more than ~1s (mind you, we have 242 of them, so each test is supposed to be quick) so we should take a look at each of these up to merkle_test.

It could be as simple in some cases as getting rid of (reasonably heavy) BOOST_* tests in inner loops, moving the checks up to a higher level.

Edit: I added the script to create this table to maintainer-tools: https://github.com/bitcoin-core/bitcoin-maintainer-tools/blob/master/unittest-statistics.py

[paveljanik]

The first one is

/** Test that random numbers of checks are correct
 */
BOOST_AUTO_TEST_CASE(test_CheckQueue_Correct_Random)
{
    std::vector<size_t> range;
    range.reserve(100000/1000);
    for (size_t i = 2; i < 100000; i += std::max((size_t)1, (size_t)GetRand(std::min((size_t)1000, ((size_t)100000) - i))))
        range.push_back(i);
    Correct_Queue_range(range);
}

By simply removing GetRand call, the time is reduced from 33s to 15s here. Ie. the test spends ~half of the time in generating random numbers.

[paveljanik]

test_big_witness_transaction is signing 4500 inputs and it takes time.

[NicolasDorier]

test_big_witness_transaction was a test I wrote for checking if the CachedHashes of segwit was thread safe. What takes time is the signing of inputs. I think a better idea is to hard code the transaction. But I think it would be kind of big.

[JeremyRubin]

Sorry for writing so many of the slow tests!

Getting rid of GetRand from the CheckQueue tests is 100% fine; and should speed things up ( @kallewoof brought that up in review, but I didn't think it would be a huge time sink).

The cuckoocache_generations test is parametrized by:

    const uint32_t BLOCK_SIZE = 10000;
    // We expect window size 60 to perform reasonably given that each epoch
    // stores 45% of the cache size (~472k).
    const uint32_t WINDOW_SIZE = 60;
    const uint32_t POP_AMOUNT = (BLOCK_SIZE / WINDOW_SIZE) / 2;
    const double load = 10;
    const size_t megabytes = 32;
    const size_t bytes = megabytes * (1 << 20);
    const uint32_t n_insert = static_cast<uint32_t>(load * (bytes / sizeof(uint256)));

picking smaller constants should be fine (although increases the potential variance, e.g., likelihood of deterministic failure). The rest of the cuckoocache_tests are also parametric (e.g., just a size in MB and a hit rate lower bound) so can be easily adjusted. I initially picked a size to match the default parameter, but we could scale down to, say 4mb or 2mb.

[NicolasDorier]

would writing my transaction with 4500 input hard coded be a problem ? I can do it but unsure if it is the right way.

[laanwj]

@NicolasDorier just how large would that data be? Very large (multi-MB) files of test data likely shouldn't be part of the repository.

[NicolasDorier]

@laanwj around 1 MB.

[JeremyRubin]

I would also note that checkqueue tests should improve a lot under #9938, I need to clean up that PR a bit though in accordance to Matt's feedback.

[laanwj]

Updated for #10128

[CinchBlue]

Do you guys think we could get an update on this issue? I think that the top unit test_CheckQueue_Correct_Random is ultimately using a FastRandomContext which seems to be doing a lot of extra sampling for the random values -- the procedure retries every time it fails to generate a bit sequence in a certain bit range. Would there be a more efficient way to pre-set the range, customize the random number generator to generate uniformly-distributed values in this bit range so that no retries are not necessary. Or, could the slowdown be happening in the verification phase?

[maflcko]

Marking "up for grabs" to see what unit tests are still slow and master and figure out how to speed them up.

https://github.com/bitcoin-core/bitcoin-maintainer-tools/blob/master/unittest-statistics.py might come in hnady.

[jamesob]

Should we add a "good first issue" label to this?

[lucash-dev]

Hi, I would like to work on this as my first issue.

[maflcko]

Just go ahead. No need to ask for permission :)

…

On Fri, Apr 13, 2018, 10:39 lucash-dev ***@***.***> wrote: Hi, I would like to work on this as my first issue. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#10026 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGGmv7DEw1coKfkr1_L-iIWAfQwmQW17ks5toLi3gaJpZM4MhVdy> .

[lucash-dev]

Updated table (as of #11200)
Can't compare numbers directly with previous ones, since it's a different setup, but the ordering should be consistent.

(pasted into OP)

test_big_witness_transaction and test_CheckQueue_Correct_Random are still the most time consuming, so I'll focus on these.

[laanwj]

@lucash-dev Thanks! Moved your table into the OP.

[lucash-dev]

The https://github.com/bitcoin-core/bitcoin-maintainer-tools/blob/master/unittest-statistics.py script was mixing up test suite and test case statistics (presumably due to some change in how test_bitcoinoutput is generated).

Created an issue and a PR in the maintainer tools repo.

[lucash-dev]

test_big_witness_transaction is spending most of time converting CMutableTransaction to CTransaction, which involves recalculating hashes. That's because each call to SignSignature does the conversion again for the whole transaction.

This means the time complexity for providing witnesses for the 4500 inputs has a O(n2) component.

Changing the test to use lower level functions ProduceSignature and UpdateTransaction, and reusing the same CTransaction in all iterations, reduces run time in about 70%.

Created a WIP PR (will add improvements to other tests to this PR).

I'm just wondering if that is not rather a bug in SignSignature. Should it create a new CTransaction every time it's called?

[maflcko]

The feature request didn't seem to attract much attention in the past. Also, the issue seems not important enough right now to keep it sitting around idle in the list of open issues.

Closing due to lack of interest. Pull requests with improvements are always welcome.