Profile retrieving UTXOs from the data store

[ignopeverell]

Running grin wallet info can take a very long time when there are hundreds or thousands of UTXOs. Normally reading those from rocksdb (even including related headers) should be extremely fast. Profile it and check what's wrong.

[yeastplume]

Well that's interesting, from an initial perf run it looks like the bulk of time is spent parsing a hex string

• 1.99% 0.00% grin grin [.] grin_api::handlers::UtxoHandler::get_utxo
  • grin_api::handlers::UtxoHandler::get_utxo
    • 1.31% grin_util::hex::from_hex
      grin_util::hex::split_n
      core::iter::iterator::Iterator::collect
      <collections::vec::Vec as core::iter::traits::FromIterator>::from_iter
      <collections::vec::Vec as collections::vec::SpecExtend<T, I>>::from_iter
      • <collections::vec::Vec as collections::vec::SpecExtend<T, I>>::spec_extend
    • 0.67% grin_chain::chain::Chain::get_unspent
      grin_chain::sumtree::SumTrees::is_unspent ::get_output_pos grin_store::Store::get_ser grin_store::Store::get_ser_limited grin_store::Store::get rocksdb::db::::get rocksdb::db::::get_opt rocksdb_get rocksdb::DB::Get rocksdb::DB::Get rocksdb::DBImpl::Get rocksdb::DBImpl::GetImpl rocksdb::Version::Get rocksdb::TableCache::Get rocksdb::TableCache::FindTable rocksdb::TableCache::GetTableReader rocksdb::BlockBasedTableFactory::NewTableReader rocksdb::BlockBasedTable::Open rocksdb::ReadProperties

[ignopeverell]

I was half expecting something silly like that. Those simple bottlenecks are the best, everything after that gets faster!

[yeastplume]

I need to do another run or so with a much larger UTXO set, had one preparing for a few hours.. I'll run another perf against it using a swapped-out version of from_hex and see whether it makes a difference.

[yeastplume]

whoops... nope. I replaced the from_hex function and it was only a minor speed increase. I did another with about 234 coinbase transactions built (nothing else.. ) a lot of slowdown on the wallet side as well churning something before even calling the UTXO api.

This is the graph from get_utxo:

• 84.87% 0.00% grin grin [.] grin_api::handlers::UtxoHandler::get_utxo
  • grin_api::handlers::UtxoHandler::get_utxo
    • 84.40% grin_chain::chain::Chain::get_unspent
      • 83.67% grin_chain::sumtree::SumTrees::is_unspent
      • 83.63% <grin_store::sumtree::PMMRBackend as grin_core::core::pmmr::Backend>::get
        • 83.62% grin_core::ser::deserialize
          • <grin_core::core::pmmr::HashSum as grin_core::ser::Readable>::read - 83.61% ::read
            • 83.61% secp256k1zkp::Secp256k1::with_caps
              • secp256k1_context_create
                • 70.37% secp256k1_ecmult_context_build
                  • 70.14% secp256k1_ecmult_odd_multiples_table_storage_var
                  • 46.57% secp256k1_ecmult_odd_multiples_table
                    • 45.35% secp256k1_gej_add_ge_var
                      • 30.61% secp256k1_fe_mul
                        30.03% secp256k1_fe_mul_inner
                      • 8.93% secp256k1_fe_sqr
                        8.73% secp256k1_fe_sqr_inner
                        1.65% secp256k1_fe_negate
                        1.16% secp256k1_fe_add
                        1.14% secp256k1_fe_normalize_weak
                        0.77% native_irq_return_iret
                  • 19.48% secp256k1_ge_set_table_gej_var
                    • 15.30% secp256k1_ge_set_gej_zinv
                      • 12.21% secp256k1_fe_mul
                        11.53% secp256k1_fe_mul_inner
                      • 2.72% secp256k1_fe_sqr
                        2.69% secp256k1_fe_sqr_inner
                    • 3.80% secp256k1_fe_mul
                      3.64% secp256k1_fe_mul_inner
                  • 3.82% secp256k1_ge_to_storage
                    2.88% secp256k1_fe_normalize
                • 13.24% secp256k1_ecmult_gen_context_build
                  • 7.37% secp256k1_gej_add_var
                  • 5.41% secp256k1_fe_mul
                  • 1.41% secp256k1_fe_sqr
                  • 3.52% secp256k1_ge_set_all_gej_var
                  • 1.82% secp256k1_ge_set_gej_zinv
                  • 1.60% secp256k1_fe_inv_all_var
                    1.02% secp256k1_gej_double_var
                  • 0.61% secp256k1_ecmult_gen_blind
      • 0.73% ::get_output_by_commit

[yeastplume]

So it looks as if the Readable trait implementation for HashSum is where the most slowdown is on the server side. Will post the graph from the wallet side shortly.

[ignopeverell]

Mmmh and looks like most of it is spent in secp256k1? Only thing that HashSum::read does is build a Commitment, doesn't seem that it should trigger that much processing.

[yeastplume]

Indeed... here's another one from the wallet.. this is from the moment you start the wallet info command until the first hit against the api server, again, most of the time in secp256k1. This was a good 10-15 seconds

[yeastplume]

Okay, this one in particular doesn't look like an issue in with libsecp speed, it's just being called a lot. Looks like an implementation for finding derived keys that needs speeding up.

https://github.com/mimblewimble/grin/blob/8f0373b81e1e882240eec95161c054ce0f571607/keychain/src/keychain.rs#L96

[yeastplume]

Okay, the wallet side was a fairly easy fix... server still seems sluggish, and it appears get_unspent is where the major inefficiency is.

[yeastplume]

Got it. Have a more accurate perf report here:

https://github.com/mimblewimble/grin/blob/8f0373b81e1e882240eec95161c054ce0f571607/core/src/core/transaction.rs#L565

It's the fact that secp256k1 is being initialized each and every time it's being called. There should probably be a common static instance stored somewhere.

Nearing the end of my useful coding period for today, if you want to look at it @ignopeverell

[ignopeverell]

Sorry I think I'm a little under the weather. I've been staring at this for the last 30 min and fighting the borrow checker with little result. I might take it easy for a couple days and get back to it when I'm less foggy. Thanks a lot for profiling all this and tracking it down! I'll get a fix ASAP.

[yeastplume]

That's no problem, I've added a solution to the PR I have outstanding which addresses that issue. https://github.com/mimblewimble/grin/pull/238

That PR greatly speeds things up overall, but now I can see most time is now spent in json serializing, so I'm sure there's more room for optimization.

[yeastplume]

JSON serialising time is down to serialising/deserialising rangeproofs as part of every output, even when it's not necessary. I think I'll leave it at the last commit for now, greatly speeded up but still room for improvement.. in particular we need to avoid passing rangeproofs around when they're not necessary, and should probably have a way to deserialise Outputs without necessarily reading the entire range proof in all cases.

[yeastplume]

Think this is all to close now, if everyone is seeing vastly quicker results from wallet info?

[ignopeverell]

Night and day. Thanks for both profiling and fixing!