Cardano-wallet: The pools list fetching takes 3-10 mins

[Fell-x27]

Context

Splitted from https://github.com/input-output-hk/cardano-wallet/issues/2004

When I try to fetch pools list, it takes too much time. The same problem appeared within ITN either and it could be solved by shadow-caching at the application level. But I'm not sure if that behaviour is fine.

I noticed almost linear progression for time spending depends on pools count. So, this problem not appears in the testnet with low pools count.

Probably, this problem is related to the count of wallets because there are dozens in my case.

| Information | - |
| --- | --- |
| Version | v2020-08-03 |
| Platform | Linux |
| Installation | From binaries |

Steps to Reproduce

1. Run the wallet over full-synced node.
2. Request pools list
3. ...
4. PROFIT!1

Expected behavior

Fast response about couple seconds. Or 10-20 seconds may be.

Actual behavior

You have to wait for 3-10 mins. My avg value is about 5 mins.

---

Resolution

Cache account balances, and only refetch them on tip-changes (all wallets in a single query) #2034

Related to: input-output-hk/cardano-node#1674

Outstanding TODO: https://github.com/input-output-hk/cardano-wallet/issues/2042 (arguments for #2034 being ok for now is provided there)

---

QA

Tested manually:

Without fix

Using:
1.18.0 node
Master cardano-wallet pre-fix ( e.g. 51221c7f06fa119048b763b0737202c646100456)
13 wallets syncing at ≈25%

Steps:
Repeatedly run cardano-wallet stake-pool list --stake 100

Results
The first couple of times it is fast (~10s).

After trying a lot, and a couple of minutes it takes 4 minutes. 👎

With fix

Using:
Same db and node as without the fix
A wallet that includes the fix (e.g. 90c1e5953a48ffc65f004a68abd545ef68574c4b).

Steps:
Repeatedly run cardano-wallet stake-pool list --stake 100

Result
At first: ~10s.
After waiting 1 min: ~12s 👍

[KtorZ]

Testing locally against the current mainnet, listing stake pools takes between 1.2 and 1.5 seconds for me.

Note that the number of wallets does not (in theory) affect the underlying stake pools engine which lives in a completely separate database. Yet, wallets are also currently using "unbound" resources and will simply consume as much as they can, each wallet lives in its own thread and manages its own lifecycle. So it could be that your system is simply too busy restoring wallets and have no time to give to the thread listing pools.

May you try listing pools on a server with no wallets? (you can easily move your wallet database files outside of the database directory and simply leave the stake-pools.sqlite database if you do not want to have to re-install and re-sync your wallets).

[Fell-x27]

So it could be that your system is simply too busy restoring wallets and have no time to give to the thread listing pools.

The results are the same for me as for 4xCPU 8Gb server either 24xCPU 32GB local machine. So I don't think it's just because of system is too busy. When I fetch wallets, addresses, transactions everything works fast.

But the wallets count is the same for server and local.

May you try listing pools on a server with no wallets?

Sure, but later, when came home.

you can easily move your wallet database files outside of the database directory and simply leave the stake-pools.sqlite database if you do not want to have to re-install and re-sync your wallets

Yeah, I know 👍

[Fell-x27]

@KtorZ , I've checked what you asked for.

1. ~5sec with just one undersynced wallet.
2. ~1.5 sec with just one well-synced wallet.
3. About 6-7min for 50 well-synced wallets.

[Anviking]

@Fell-x27 if you're eager to try something out then, #2034 (WIP!) speeds it up from 2-3 min to 5s for me (with 10 wallets).

Edit: https://hydra.iohk.io/build/3811070#tabs-constituents in case I break the build in further commits.

[Fell-x27]

@Fell-x27 if you're eager to try something out then, #2034 (WIP!) speeds it up from 2-3 min to 5s for me (with 10 wallets).

Thanks! Will check it and share results!

[Anviking]

Today I was suddenly unable to reproduce the problem using cardano-wallet master (and 10 wallets). It only took ~6 seconds to list pools. 🤔 But after a while it slowed down to 3 minutes. And switching to #2034 at that point made it ~6 seconds again.

[Fell-x27]

Ok. Will try to build master today and check it for my case :)

[Fell-x27]

Today I was suddenly unable to reproduce the problem using cardano-wallet master (and 10 wallets). It only took ~6 seconds to list pools. But after a while it slowed down to 3 minutes. And switching to #2034 at that point made it ~6 seconds again.

Master (1d7914c7e530770dce3a248960e22eb3f0e143f2)
1033 pools, 100+ wallets
30 mins taken.

And 1-2s if there are no any wallets attached to process.

So...I've just launched one more wallet-serve just for fetching pools list to a cache-layer :laughing:
Works fine(kinda), but can't be used for fees calculation which are very slow neither.

[Anviking]

@Fell-x27 have you tried using the appropriate cardano-wallet binary from https://hydra.iohk.io/build/3811070#tabs-constituents ? It contains the #2034 fix which is not _yet_ on master.

(It has the cardano-wallet version: 2020.8.3 (git revision: 825d3f64cd641f6ba3347c5f04877145ffe9e0ae))

[Fell-x27]

Not yet. I'll try to test it later, thanks :)

[Fell-x27]

@Fell-x27 have you tried using the appropriate cardano-wallet binary from https://hydra.iohk.io/build/3811070#tabs-constituents ? It contains the #2034 fix which is not _yet_ on master.

(It has the cardano-wallet version: 2020.8.3 (git revision: [825d3f6](https://github.com/input-output-hk/cardano-wallet/commit/825d3f64cd641f6ba3347c5f04877145ffe9e0ae)))

About 3 sec for 50 wallets. Can't test for 100+ right now, but even for 50 it's obviously working good.

[Fell-x27]

Looks like fees reward-related calculation problem isn't appearing neither.

[Fell-x27]

Is this branch production-ready or unstable? Should I wait until it merged to the master or can deploy?

[KtorZ]

@Fell-x27 anything that isn't in master cannot be considered production-ready. And even master, we have nightly tests running once a day (which are mostly for tracking performance regressions) that would in principle be necessary to wait for until claiming that master is production-ready.

[Fell-x27]

I see. But I'm happy anyway.

[Fell-x27]

Looks like also CPU utilization for this version just dropped from "crazy" to "almost zero" either.

[KtorZ]

Ho. I didn't realize this was causing huge CPU spikes, which is something I find _bizarre_. From the analysis, I'd have expected the slowness to be due to thread blocking on shared concurrent variables (which is supposedly a 0-cost operation ... ).

[Fell-x27]

Ho. I didn't realize this was causing huge CPU spikes, which is something I find _bizarre_. From the analysis, I'd have expected the slowness to be due to thread blocking on shared concurrent variables (which is supposedly a 0-cost operation ... ).

Well, I can see spikes for now. Looks like they appear when new block comes. For a moment, CPU usage becomes very high, but then its almost 0 until new block coming. But previously it was a stable very high CPU load with a small periods of resting.

So now its 1% time high and 99% almost zero load.
But previously it was 1% almost zero and 99% of timeline was very intensive usage.

Anyway new statistics is much better from any point of view.

[Fell-x27]

@Anviking @KtorZ , bug alert, guys. #2034 doesn't sync reward balance for fresh-restored wallets. It keeps reward balance for already restored with prev release version, but you tried to delete and restore it again with #2034, reward balance wont be restored and scary zero will be there.

[Fell-x27]

Sorry, it was actual for build of 825d3f64cd641f6ba3347c5f04877145ffe9e0ae, but not for 03ed32945e01086fbc918ca0b3ff22ba4b1fef73 which is working fine.

[Anviking]

Thanks, good to know!

[Anviking]

I was pretty sure I saw the relevant integration tests pass on both 825d3f6 and 03ed32945e01086fbc918ca0b3ff22ba4b1fef73, though, which I find a bit odd 🤔

[Fell-x27]

I'm just sharing my local testing results.

[Fell-x27]

But if you want some funny data, I have it.
Just tried to send about 10k reward and got 18446744062438080512 lovelace estimated fees :)

request payload:

{"payments":[{"address":"addr1qxvslv6qslr5zwecafquffkaseahaus8sjecx7uu0u6k5jm4g50xym02uf23pfzy3hw67sywl29sngrug8rpk7998w6stqxy2a","amount":{"quantity":11273643926,"unit":"lovelace"}}],"withdrawal":"self"}

response:

{"estimated_min":{"quantity":18446744062438080512,"unit":"lovelace"},"estimated_max":{"quantity":18446744062438080512,"unit":"lovelace"}}

commit 03ed32945e01086fbc918ca0b3ff22ba4b1fef73

[Fell-x27]

Looks like it appears when fee + transfered_sum >= total_sum.

But estimated _migration_ fees are ok.

[Fell-x27]

demo - https://youtu.be/dZ_NQGGxkXg

[piotr-iohk]

My results are a bit inconclusive so far. I repeatedly get all stakepools within 50s - 1 min for each wallet version I tested below:

• v2020-08-03 2020.8.3 (git revision: 40a8b5daa1da77480e4b818c49f2a4977aed4a71)
• 51221c7f0 2020.8.3 (git revision: 51221c7f06fa119048b763b0737202c646100456)
• current master 2020.8.3 (git revision: fece720cb18d9676c4f1f6b0d3a69a37fab93f1c)

Test conditions:

• Mainnet
• using cardano-node 1.19.0
• Having cardano-wallet with 10 wallets syncing

[Anviking]

With the same test conditions as above, https://github.com/input-output-hk/cardano-wallet/issues/2005#issuecomment-680022983
and testing

• 2020.8.3 (git revision: fece720cb18d9676c4f1f6b0d3a69a37fab93f1c)
• 2020.8.3 (git revision: 40a8b5daa1da77480e4b818c49f2a4977aed4a71)

I get 10-13s for both

With cardano-node 1.19.0 the need for the wallet fix _should be_ lessened, which is what I see ^^ (maybe we wouldn't even have needed this fix 🙃 )

But with cardano-node 1.18.0 I get

• 2020.8.3 (git revision: fece720cb18d9676c4f1f6b0d3a69a37fab93f1c) -> 9s, then 9s
• 2020.8.3 (git revision: 40a8b5daa1da77480e4b818c49f2a4977aed4a71) -> First 16s then 3 min 20s
• switching back to fece720cb18d9676c4f1f6b0d3a69a37fab93f1c -> 4s, 16s, 19s, 9s, 16s

I have to clear and re-create all _wallet_ sqlite files before switching versions to avoid them not syncing and "Something went wrong" when listing wallets, but keeping the pool db

This 19s was the highest I've seen in a while. Maybe there's something in particular causing it 🤔

I repeatedly get all stakepools within 50s - 1 min for each wallet version

@piotr-iohk Similar times for all versions? Are you sure?

[piotr-iohk]

@piotr-iohk Similar times for all versions? Are you sure?

With cardano-node 1.19.0 yes. Haven't check with 1.18.0. I will...

Are you syncing 10 wallets? Your times are awesome (10-13s)... For me on 1.19.0 it was at least ~45s...

[KtorZ]

Perhaps some helpful remark: I've noticed that fetching pools and metadata does have a noticeable impact on the overall server's performance. So perhaps your wallet is still fetching a lot of metadata in background still @piotr-iohk ?

[piotr-iohk]

I don't think so... I waited until all metadata is fetched (at least from looking at the logs) before creating wallets.

I've had repeatable results no matter if wallets were syncing 10% or 50%... by 50% wallets synced I suppose all metadata would be fetched anyway.

[piotr-iohk]

Ok, I can see difference in case of node 1.18.0. With the very same test condidions (mainnet, 10 wallets syncing):

cardano-node 1.18.0

• with 2020.8.3 (git revision: 40a8b5daa1da77480e4b818c49f2a4977aed4a71) I got:
  4:10m
  4:30m
  3:40m

  • with current master - 2020.8.3 (git revision: 9f93d0a98be7c19035dd603149ebf06ac38d7f2f)
    47s
    50s
    51s

cardano-node 1.19.0 (well, slight difference after all as well ☺ )

• with 2020.8.3 (git revision: 40a8b5daa1da77480e4b818c49f2a4977aed4a71) I got:
  1:10m
  1:00m
  1:03m

  • with current master - 2020.8.3 (git revision: 9f93d0a98be7c19035dd603149ebf06ac38d7f2f)
    47s
    48s
    16s - got this once, but next two were also in 40-50s
    49s
    51s

[Anviking]

(well, slight difference after all as well ☺ )

maybe not in vain in that case 😌

But 50s still sounds very slow to me 🤔

Worth a new ticket?

@piotr-iohk if you search for Query in the logs do you see any slow queries that explain the 50s time?

E.g.:

[cardano-wallet.network:Info:160] [2020-08-26 11:17:35.21 UTC] Query GetEraStart took 0.101491s
[cardano-wallet.network:Info:15] [2020-08-26 11:17:35.22 UTC] Query getAccountBalance took 0.088104s
[cardano-wallet.network:Info:160] [2020-08-26 11:17:35.24 UTC] Query GetCurrentPParams took 0.030575s
[cardano-wallet.network:Info:160] [2020-08-26 11:17:35.24 UTC] Query GetUpdateInterfaceState took 0.000982s

I added more traces for the stake distribution itself in #2080

(personally I think I need to reset my DB after testing other code, will try to get back with a more accurate view of what I see using #2080 )

[piotr-iohk]

Not sure how is the relation but the time of listing pools seems to grow when there are more wallets being synced.
I don't see any obvious outstanding query time that would explain 50s... the longest query is GetNonMyopicMemberRewards which is a bit longer the more wallets are syncing. (Which applies to other querries too actually).

0 Wallets syncing:
List sp = 3s
Query GetNonMyopicMemberRewards took 2.028777786s

1 wallet syncing:
List sp = 13s
Query GetNonMyopicMemberRewards took 2.39806037s

2 wallets syncing
List sp = 26s
Query GetNonMyopicMemberRewards took 2.452248284s

3 wallets syncing
List sp = 31s
Query GetNonMyopicMemberRewards took 2.402175446s

5 wallets syncing
List sp = 40s
Query GetNonMyopicMemberRewards took 2.821580222s

10 wallets syncing
List sp = 47s
Query GetNonMyopicMemberRewards took 3.001514181s

15 wallets syncing
List sp = 1m 03s
Query GetNonMyopicMemberRewards took 3.012593506s

20 wallets syncing
List sp = 1m 11s
Query GetNonMyopicMemberRewards took 3.519106839s

Times of other querries is also growing a bit too and also the number of queries is growing when there are more wallets:

With 0 wallets (lp exec time = 4s):

Query GetNonMyopicMemberRewards took 2.386650034s
Query GetCurrentPParams took 0.000716248s
Query GetEraStart took 0.00137057s
Query getAccountBalance took 0.001327425s
Query GetCurrentPParams took 0.000513555s
Query GetUpdateInterfaceState took 0.000478

With 20 wallets (lp exec time = 1:10m):

Query GetEraStart took 0.637137392s
Query getAccountBalance took 0.648792572s
Query GetCurrentPParams took 0.626415965s
Query GetUpdateInterfaceState took 0.753813193s
Query GetStakeDistribution took 0.570119185s
Query GetEraStart took 0.771473205s
Query GetCurrentPParams took 0.650308479s
Query GetUpdateInterfaceState took 0.784389s
Query GetNonMyopicMemberRewards took 3.200318526s
Query getAccountBalance took 3.245384946s
Query GetCurrentPParams took 1.100185536s
Query GetEraStart took 0.842396347s
Query getAccountBalance took 0.854336837s
Query GetCurrentPParams took 0.759815955s
Query GetUpdateInterfaceState took 0.683372427s
Query GetEraStart took 0.841750692s
Query getAccountBalance took 0.886189268s
Query GetCurrentPParams took 0.806262374s
Query GetUpdateInterfaceState took 0.796393044s
Query GetEraStart took 0.898862386s
Query getAccountBalance took 0.962203422s
Query GetCurrentPParams took 0.736154508s
Query GetUpdateInterfaceState took 0.811650964s
Query GetEraStart took 0.695541092s
Query getAccountBalance took 0.730742968s
Query GetCurrentPParams took 0.901877006s
Query GetUpdateInterfaceState took 0.893728

But 50s still sounds very slow to me
Worth a new ticket?

I can create separate ticket for this.