Improve AddToWallet performance when rescanning #6850

bittylicious commented at 7:32 PM on October 18, 2015: none

Large performance improvement when adding transactions if the client is not currently at the tip of the blockchain. This particularly improves wallet rescan times, including following from a zapwallettxes.

In AddToWallet, two large indices are created over the wallet in order to make an estimate of the time a wallet transaction was created. This is slow anyway (possibly subject to a further fix) but also unnecessary if we are not at the tip because we just default to the block time. This patch skips the rescan code if we were going to fall back to the block time anyway, so shouldn't change the logic.

On a wallet with around 180,000 keys (500 MB, so pretty large) this sped up the resync time 20x from about 10 hours to 30 minutes.

gmaxwell commented at 7:34 PM on October 18, 2015: contributor

Hurrah. Will test and review. thanks for this work.

luke-jr commented at 7:39 PM on October 18, 2015: member

No doubt there is probably room to optimise this, but I'm pretty sure your change modifies the behaviour. Even when rescanning (or otherwise lacking receive-time information), the block time is not used unconditionally, and is prevented from moving less than 5 minutes backward in time as the wallet progresses forward.

bittylicious commented at 7:39 PM on October 18, 2015: none

Just to add some more rationale - at Bittylicious, we have a situation where we sent a transaction involving some unconfirmed change. This will never confirm because the original transaction that generated the change became mutated. Thus, we needed to zapwallettxes in order to remove this transaction and restore balances.

The restore process was going to take about 10 hours (wallet and blocks on SSD) on our huge 500 MB wallet. This was too much downtime for Bittylicious. After a lot of difficult profiling, I determined that it was AddToWallet that was taking all the time because of the iteration to find nTimeSmart. When rescanning, we a) just assume this is the block time anyway, and b) restore the metadata for nTimeSmart anyway.

This was tested by comparing the wallet from the traditional zapwallettxes (before this commit) to the wallet after this patch. It looks the same based on a random sample of transaction and overall wallet balance.

I think that this patch should be accepted because this fix:

Doesn't actually change the logic at all (reviewers should definitely check this)
Is very simple, adding just a simple if statement (essentially)
Has a massive speed improvement when rescanning

Ideally, we'd look into creating new indices and get rid of OrderedTxItems but that's more invasive, has some other performance impacts, and wouldn't make a huge difference for small wallets.

bittylicious commented at 7:42 PM on October 18, 2015: none

luke-jr: The time can only move a maximum of five minutes forwards. I think the if statement here stops the iteration block from being entered if this is basically impossible. Hence, I don't think it changes the behaviour in any way. Naturally, with this being my first commit especially, I may be wrong.

in src/wallet/wallet.cpp:None in 5a7a52d65c outdated

 651 | @@ -652,8 +652,12 @@ bool CWallet::AddToWallet(const CWalletTx& wtxIn, bool fFromLoadWallet, CWalletD
 652 |                  {
 653 |                      int64_t latestNow = wtx.nTimeReceived;
 654 |                      int64_t latestEntry = 0;
 655 | +                    int64_t blocktime = mapBlockIndex[wtxIn.hashBlock]->GetBlockTime();

dcousens commented at 11:29 PM on October 18, 2015:

nit: blockTime?

bittylicious commented at 8:20 AM on October 19, 2015:

dcousens: It's just a line moved from below so I didn't want to change anything. Arguably it could indeed be cased properly, but I think in this case, the fewer changes the better.

dcousens commented at 9:10 AM on October 20, 2015:

Sure

luke-jr commented at 9:24 AM on October 19, 2015: member

@bittylicious Can you confirm #6851 performs better than this, for you?

bittylicious commented at 11:01 AM on October 19, 2015: none

luke-jr: I don't see how #6851 can logically perform better than this commit. This commit has a simple if block that means the code won't get executed at all, whereas your code fix is more comprehensive but still means it will enter the iterator loop when we know it won't do anything already.

These two pull requests are not mutually exclusive. Yours is a more comprehensive fix that will make AddToWallet calls a lot more efficient, and mine will make it more efficient as well when we're not at the tip. Mine is simpler to approve as it has no significant overheads and yours is definitely necessary as well as long as the overheads are considered.

Additionally, on my wallet, this fix is a 2000% speed increase. It doesn't make sense talking about percentages really though as they depend on wallet sizes.

laanwj added the label Wallet on Oct 19, 2015

luke-jr commented at 4:51 AM on October 20, 2015: member

@bittylicious This one actually breaks smart times, though. If you want to fix that, I agree these aren't mutually exclusive.

I said #6851 is faster, because I actually compared it to the same base with smart times removed entirely (effectively what this would do). I was mainly just asking you to confirm my results on your own wallet. (Why it's faster, I'm not really sure - I would guess there's something outside smart times using the ordered wallet.)

bittylicious commented at 8:13 AM on October 20, 2015: none

@luke-jr You keep no saying that, but I need to know why you think this breaks smart times. The if block basically just skips the iteration loop if it's impossible to come to a better smart time. I don't think this changes the behaviour at all.

luke-jr commented at 5:05 PM on October 20, 2015: member

It's not impossible to come to a better smart time during rescan. In fact, your conditional here is almost never true.

bittylicious commented at 5:29 PM on October 20, 2015: none

@luke-jr GIve me a specific example please.

I believe that my if statement stops the iteration loop from being entered if we're not going to be able to get a more accurate nTimeSmart anyway. If you can give me a specific example with specific wtx.nTimeReceived and blockTime values, I'll investigate.

luke-jr commented at 5:40 PM on October 20, 2015: member

Put both 16EW6Rv9P9AxFDBrZV816dD4sj1EAYUX3f and 1Ebb8NfVmKMoGuMJCAEbVMv2dX8GnzgxSa in the same wallet.
You will receive 2d8c9330529acd61ba96719785613d8c577ba731a58b456642ff363702a802ca first, with a smart-time of 2015-10-20 16:41:15.
You will receive 22de2409c7740dcdff4b234a1e02e40109e18fc5774d7da53916b259ef3e7843 second. Its smart-time should also be 2015-10-20 16:41:15, but with this PR will instead get 2015-10-20 16:41:03, a time before that of the earlier transaction.

bittylicious commented at 12:03 AM on October 21, 2015: none

@luke-jr Thanks for that - that's very helpful.

My brain hurts right now, but I think that I didn't consider the max(...) in the wtx.nTimeSmart = ... statement. I still think we can do this with an if statement though which should cover the possibilities here.

Although I haven't worked entirely through the logic, just changing the if to something like if (latestNow < blocktime + 300) should cover all possible cases in in the statement. Let me know if you agree.

Improve AddToWallet performance when rescanning

Large performance improvement when adding tranasctions if the client is not currently at the tip of the blockchain. This particularly improves wallet rescan times, including following from a zapwallettxes.

In AddToWallet, two large indicies are created over the wallet in order to make an estimate of the time a wallet transaction was created. This is slow anyway (possibly subject to a further fix) but also unnecssary if we are not at the tip because we just default to the block time. This patch skips the rescan code if we were going to fall back to the block time anyway, so shouldn't change the logic.

On a wallet with around 180,000 keys (500 MB, so pretty large) this sped up the resync time 20x from about 10 hours to 30 minutes.

cf9c739e63

bittylicious force-pushed on Nov 17, 2015

Increased tolerance for nSmartTime calculation in AddToWallet 93c5885265

bittylicious commented at 3:49 PM on November 17, 2015: none

I've now changed the commit to make it enter the nSmartTime calculation loop if we're within 5 minutes of blocktime. I now think the logic is the same, and this will still add some good efficiency, especially when rescanning for wallet transactions.

gmaxwell commented at 12:19 AM on November 23, 2015: contributor

@bittylicious Hows your feelings about the importance of this with the sorting brain-damage now fixed? (I'm asking in order to figure out if I should go review and test this one).

bittylicious commented at 7:59 AM on November 23, 2015: none

@gmaxwell It's not nearly as important as before, but I imagine it would still yield a noticeable improvement especially with scanwallet where the nSmartTime scan would still be unnecessarily performed for every single transaction.

MarcoFalke commented at 12:12 AM on January 6, 2016: member

@bittylicious Needs rebase, if still relevant.

bittylicious commented at 10:01 AM on January 7, 2016: none

Let me wait until the first RC release of 0.12 that has #6851 in and then I can do a comparison of zapwallettx times between that and this fix on my huge wallet. Then I'll rebase if appropriate.

jonasschnelli commented at 12:55 PM on January 20, 2016: contributor

@bittylicious: interested in rebasing and showing out some statistics (compare against 0.12rc1)?

bittylicious commented at 7:28 PM on March 16, 2016: none

Hi again,

I've done a test with my ~600 MB live wallet against both v0.12 and v0.12 with my patch ported. In a nutshell, the timings are practically identical for a rescan so I think this issue can be closed and not merged. The patch by @luke-jr seems to speed up things sufficiently and this patch seems to many an immeasurable speedup.

Here's the debug output. It's a powerful system, entire blockchain and wallet on SSD:

v0.12, no patch

2016-03-16 16:32:54 Still rescanning. At block 163583. Progress=0.009117 2016-03-16 16:33:54 Still rescanning. At block 188743. Progress=0.019686 2016-03-16 16:34:54 Still rescanning. At block 201922. Progress=0.030898 2016-03-16 16:35:54 Still rescanning. At block 213473. Progress=0.041434 2016-03-16 16:36:54 Still rescanning. At block 222117. Progress=0.052545 2016-03-16 16:37:54 Still rescanning. At block 229953. Progress=0.062877 2016-03-16 16:38:54 Still rescanning. At block 236878. Progress=0.072711 2016-03-16 16:39:54 Still rescanning. At block 246228. Progress=0.082867 2016-03-16 16:40:54 Still rescanning. At block 255822. Progress=0.093255 2016-03-16 16:41:54 Still rescanning. At block 265030. Progress=0.103538 2016-03-16 16:42:54 Still rescanning. At block 271919. Progress=0.112860 2016-03-16 16:43:54 Still rescanning. At block 278346. Progress=0.121969 2016-03-16 16:44:54 Still rescanning. At block 284943. Progress=0.130991 2016-03-16 16:45:54 Still rescanning. At block 290017. Progress=0.139231 2016-03-16 16:46:54 Still rescanning. At block 295451. Progress=0.150492 2016-03-16 16:47:54 Still rescanning. At block 300780. Progress=0.191434 2016-03-16 16:48:54 Still rescanning. At block 305992. Progress=0.230894 2016-03-16 16:49:54 Still rescanning. At block 311365. Progress=0.271236 2016-03-16 16:50:54 Still rescanning. At block 316238. Progress=0.310451 2016-03-16 16:51:54 Still rescanning. At block 321132. Progress=0.350094 2016-03-16 16:52:54 Still rescanning. At block 325348. Progress=0.387382 2016-03-16 16:53:54 Still rescanning. At block 329378. Progress=0.424493 2016-03-16 16:54:54 Still rescanning. At block 332875. Progress=0.459921 2016-03-16 16:55:54 Still rescanning. At block 336399. Progress=0.494143 2016-03-16 16:56:54 Still rescanning. At block 339841. Progress=0.527287 2016-03-16 16:57:54 Still rescanning. At block 343259. Progress=0.559345 2016-03-16 16:58:54 Still rescanning. At block 346294. Progress=0.587935 2016-03-16 16:59:54 Still rescanning. At block 349389. Progress=0.616732 2016-03-16 17:00:54 Still rescanning. At block 352331. Progress=0.644348 2016-03-16 17:01:54 Still rescanning. At block 355309. Progress=0.671989 2016-03-16 17:02:54 Still rescanning. At block 358321. Progress=0.698427 2016-03-16 17:03:54 Still rescanning. At block 361064. Progress=0.722283 2016-03-16 17:04:54 Still rescanning. At block 363534. Progress=0.744310 2016-03-16 17:05:54 Still rescanning. At block 365484. Progress=0.762397 2016-03-16 17:06:54 Still rescanning. At block 367693. Progress=0.780202 2016-03-16 17:07:54 Still rescanning. At block 369763. Progress=0.796382 2016-03-16 17:08:54 Still rescanning. At block 372611. Progress=0.817347 2016-03-16 17:09:54 Still rescanning. At block 374699. Progress=0.832884 2016-03-16 17:10:54 Still rescanning. At block 377061. Progress=0.850577 2016-03-16 17:11:54 Still rescanning. At block 379377. Progress=0.867255 2016-03-16 17:12:54 Still rescanning. At block 381648. Progress=0.882724 2016-03-16 17:13:54 Still rescanning. At block 383630. Progress=0.896106 2016-03-16 17:14:54 Still rescanning. At block 385950. Progress=0.910327 2016-03-16 17:15:54 Still rescanning. At block 387929. Progress=0.921990 2016-03-16 17:16:54 Still rescanning. At block 389764. Progress=0.932731 2016-03-16 17:17:54 Still rescanning. At block 391911. Progress=0.944668 2016-03-16 17:18:54 Still rescanning. At block 393811. Progress=0.955269 2016-03-16 17:19:54 Still rescanning. At block 395547. Progress=0.964383 2016-03-16 17:20:54 Still rescanning. At block 397406. Progress=0.972814 2016-03-16 17:21:54 Still rescanning. At block 399174. Progress=0.981227 2016-03-16 17:22:54 Still rescanning. At block 400668. Progress=0.989273 2016-03-16 17:23:54 Still rescanning. At block 402348. Progress=0.997172

Time taken ~ 51 minutes

v0.12 with my patch

2016-03-16 18:04:55 Still rescanning. At block 163357. Progress=0.009081 2016-03-16 18:05:55 Still rescanning. At block 188608. Progress=0.019591 2016-03-16 18:06:55 Still rescanning. At block 201816. Progress=0.030787 2016-03-16 18:07:55 Still rescanning. At block 213404. Progress=0.041349 2016-03-16 18:08:55 Still rescanning. At block 221957. Progress=0.052326 2016-03-16 18:09:55 Still rescanning. At block 229686. Progress=0.062469 2016-03-16 18:10:55 Still rescanning. At block 236423. Progress=0.072051 2016-03-16 18:11:55 Still rescanning. At block 245252. Progress=0.081995 2016-03-16 18:12:55 Still rescanning. At block 254634. Progress=0.091987 2016-03-16 18:13:55 Still rescanning. At block 263677. Progress=0.102150 2016-03-16 18:14:55 Still rescanning. At block 271016. Progress=0.111177 2016-03-16 18:15:55 Still rescanning. At block 276824. Progress=0.120132 2016-03-16 18:16:55 Still rescanning. At block 283409. Progress=0.128778 2016-03-16 18:17:55 Still rescanning. At block 288788. Progress=0.137058 2016-03-16 18:18:55 Still rescanning. At block 293949. Progress=0.145385 2016-03-16 18:19:55 Still rescanning. At block 299321. Progress=0.179888 2016-03-16 18:20:55 Still rescanning. At block 304439. Progress=0.219421 2016-03-16 18:21:55 Still rescanning. At block 309822. Progress=0.258949 2016-03-16 18:22:55 Still rescanning. At block 314756. Progress=0.298892 2016-03-16 18:23:55 Still rescanning. At block 319585. Progress=0.336945 2016-03-16 18:24:55 Still rescanning. At block 323895. Progress=0.373935 2016-03-16 18:25:55 Still rescanning. At block 327902. Progress=0.410890 2016-03-16 18:26:55 Still rescanning. At block 331598. Progress=0.446760 2016-03-16 18:27:55 Still rescanning. At block 334922. Progress=0.480770 2016-03-16 18:28:55 Still rescanning. At block 338694. Progress=0.514792 2016-03-16 18:29:55 Still rescanning. At block 341914. Progress=0.546907 2016-03-16 18:30:55 Still rescanning. At block 345026. Progress=0.575844 2016-03-16 18:31:55 Still rescanning. At block 348057. Progress=0.604610 2016-03-16 18:32:55 Still rescanning. At block 351172. Progress=0.632943 2016-03-16 18:33:55 Still rescanning. At block 354114. Progress=0.660866 2016-03-16 18:34:55 Still rescanning. At block 357138. Progress=0.687754 2016-03-16 18:35:55 Still rescanning. At block 359982. Progress=0.713010 2016-03-16 18:36:55 Still rescanning. At block 362603. Progress=0.735772 2016-03-16 18:37:55 Still rescanning. At block 364807. Progress=0.755987 2016-03-16 18:38:55 Still rescanning. At block 367004. Progress=0.774494 2016-03-16 18:39:55 Still rescanning. At block 368699. Progress=0.788374 2016-03-16 18:40:55 Still rescanning. At block 371486. Progress=0.809230 2016-03-16 18:41:55 Still rescanning. At block 373971. Progress=0.827231 2016-03-16 18:42:55 Still rescanning. At block 376027. Progress=0.843316 2016-03-16 18:43:55 Still rescanning. At block 378459. Progress=0.860582 2016-03-16 18:44:55 Still rescanning. At block 380725. Progress=0.876383 2016-03-16 18:45:55 Still rescanning. At block 382740. Progress=0.890353 2016-03-16 18:46:55 Still rescanning. At block 385070. Progress=0.904749 2016-03-16 18:47:55 Still rescanning. At block 387141. Progress=0.917505 2016-03-16 18:48:55 Still rescanning. At block 389012. Progress=0.928132 2016-03-16 18:49:55 Still rescanning. At block 390963. Progress=0.939245 2016-03-16 18:50:55 Still rescanning. At block 393039. Progress=0.950609 2016-03-16 18:51:55 Still rescanning. At block 394753. Progress=0.960300 2016-03-16 18:52:55 Still rescanning. At block 396527. Progress=0.968891 2016-03-16 18:53:55 Still rescanning. At block 398389. Progress=0.977307 2016-03-16 18:54:55 Still rescanning. At block 399940. Progress=0.985437 2016-03-16 18:55:55 Still rescanning. At block 401469. Progress=0.993110

Time taken ~ 51 minutes

jonasschnelli commented at 7:55 AM on March 17, 2016: contributor

Closing. Superseded by #6851.

jonasschnelli closed this on Mar 17, 2016

DrahtBot locked this on Sep 8, 2021