perf: Amortize clearing unsorted cache entries (Juno genesis fix) (ba…

…ckport #12885) (#12961)

* perf: Amortize clearing unsorted cache entries (Juno genesis fix) (#12885)

This change fixes a bounty by the Juno team.  Juno's invariant checks took 10 hours during their most recent chain halt. This PR cuts that down to 30 seconds.  See https://github.com/CosmosContracts/bounties#improve-speed-of-invariant-checks.

The root problem is deep in the `can-withdraw` invariant check, which calls this repeatedly: https://github.com/cosmos/cosmos-sdk/blob/main/x/distribution/keeper/store.go#L337.  Iterators have a chain of parents and in this case creates an iterator from the `cachekv` store.  For the genesis file, it has a cache of 500,000+ unsorted entries, which are sorted as strings here: https://github.com/cosmos/cosmos-sdk/blob/main/store/cachekv/store.go#L314.  Each delegation from `can-withdraw` uses this cache and many of the cache checks miss or are a very small range.  This means very few entries get removed from the unsorted cache and they have to be re-sorted on the next call.  With a full cache it takes about 180ms on my machine to sort them.

This change introduce a minimum number of entries that will get processed and removed from the unsorted list. It's set at the same value that directs the code to sort them in the first place.  This ensures the unsorted values get removed in a relative short amount of time, and amortizes the cost to ensure an individual check does not have to process the entire cache.

## Benchmarks
On running the benchmarks included in this change produces:
```shell
name                    old time/op    new time/op    delta
LargeUnsortedMisses-32     21.2s ± 9%      0.0s ± 1%   -99.91%  (p=0.000 n=20+17)

name                    old alloc/op   new alloc/op   delta
LargeUnsortedMisses-32    1.64GB ± 0%    0.00GB ± 0%   -99.83%  (p=0.000 n=19+19)

name                    old allocs/op  new allocs/op  delta
LargeUnsortedMisses-32     20.0k ± 0%     41.1k ± 0%  +105.23%  (p=0.000 n=19+20)
```

## Invariant checks results
This is what the invariant checks for Juno look like with this change (on a Hetzner AX101):

```shell
INF starting node with ABCI Tendermint in-process
4:11PM INF Starting multiAppConn service impl=multiAppConn module=proxy
4:11PM INF Starting localClient service connection=query impl=localClient module=abci-client
4:11PM INF Starting localClient service connection=snapshot impl=localClient module=abci-client
4:11PM INF Starting localClient service connection=mempool impl=localClient module=abci-client
4:11PM INF Starting localClient service connection=consensus impl=localClient module=abci-client
4:11PM INF Starting EventBus service impl=EventBus module=events
4:11PM INF Starting PubSub service impl=PubSub module=pubsub
4:11PM INF Starting IndexerService service impl=IndexerService module=txindex
4:11PM INF ABCI Handshake App Info hash= height=0 module=consensus protocol-version=0 software-version=v9.0.0-36-g8fd6f16
4:11PM INF ABCI Replay Blocks appHeight=0 module=consensus stateHeight=0 storeHeight=0
4:12PM INF asserting crisis invariants inv=1/11 module=x/crisis name=gov/module-account
4:12PM INF asserting crisis invariants inv=2/11 module=x/crisis name=distribution/nonnegative-outstanding
4:12PM INF asserting crisis invariants inv=3/11 module=x/crisis name=distribution/can-withdraw
4:12PM INF asserting crisis invariants inv=4/11 module=x/crisis name=distribution/reference-count
4:12PM INF asserting crisis invariants inv=5/11 module=x/crisis name=distribution/module-account
4:12PM INF asserting crisis invariants inv=6/11 module=x/crisis name=bank/nonnegative-outstanding
4:12PM INF asserting crisis invariants inv=7/11 module=x/crisis name=bank/total-supply
4:12PM INF asserting crisis invariants inv=8/11 module=x/crisis name=staking/module-accounts
4:12PM INF asserting crisis invariants inv=9/11 module=x/crisis name=staking/nonnegative-power
4:12PM INF asserting crisis invariants inv=10/11 module=x/crisis name=staking/positive-delegation
4:12PM INF asserting crisis invariants inv=11/11 module=x/crisis name=staking/delegator-shares
4:12PM INF asserted all invariants duration=28383.559601 height=4136532 module=x/crisis
```

## Alternatives
There is another PR which fixes this problem for the Juno genesis file cosmos/cosmos-sdk#12886. However, because of its concurrent nature, it happens to hit a large range relatively early, clearing the unsorted entries and allowing the rest of the checks to not sort it.

(cherry picked from commit 4fc1f73)

# Conflicts:
#	CHANGELOG.md

* fix conflict

Co-authored-by: blazeroni <blazeroni@gmail.com>
Co-authored-by: Julien Robert <julien@rbrt.fr>
Co-authored-by: Marko <marbar3778@yahoo.com>

CHANGELOG.md

@@ -39,6 +39,7 @@ Ref: https://keepachangelog.com/en/1.0.0/
 
 ### Improvements
 
+* [#12886](https://github.com/cosmos/cosmos-sdk/pull/12886) Amortize cost of processing cache KV store.
 * [#12970](https://github.com/cosmos/cosmos-sdk/pull/12970) Bump Tendermint to `v0.34.21` and IAVL to `v0.19.1`.
 * [#12693](https://github.com/cosmos/cosmos-sdk/pull/12693) Make sure the order of each node is consistent when emitting proto events.
 

store/cachekv/search_benchmark_test.go

@@ -0,0 +1,43 @@
+package cachekv
+
+import (
+	db "github.com/tendermint/tm-db"
+	"strconv"
+	"testing"
+)
+
+func BenchmarkLargeUnsortedMisses(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		b.StopTimer()
+		store := generateStore()
+		b.StartTimer()
+
+		for k := 0; k < 10000; k++ {
+			// cache has A + Z values
+			// these are within range, but match nothing
+			store.dirtyItems([]byte("B1"), []byte("B2"))
+		}
+	}
+}
+
+func generateStore() *Store {
+	cache := map[string]*cValue{}
+	unsorted := map[string]struct{}{}
+	for i := 0; i < 5000; i++ {
+		key := "A" + strconv.Itoa(i)
+		unsorted[key] = struct{}{}
+		cache[key] = &cValue{}
+	}
+
+	for i := 0; i < 5000; i++ {
+		key := "Z" + strconv.Itoa(i)
+		unsorted[key] = struct{}{}
+		cache[key] = &cValue{}
+	}
+
+	return &Store{
+		cache:         cache,
+		unsortedCache: unsorted,
+		sortedCache:   db.NewMemDB(),
+	}
+}

store/cachekv/store.go

@@ -15,6 +15,7 @@ import (
 	"github.com/cosmos/cosmos-sdk/store/types"
 	"github.com/cosmos/cosmos-sdk/telemetry"
 	"github.com/cosmos/cosmos-sdk/types/kv"
+	"github.com/tendermint/tendermint/libs/math"
 )
 
 // If value is nil but deleted is false, it means the parent doesn't have the
@@ -275,6 +276,8 @@ const (
 	stateAlreadySorted
 )
 
+const minSortSize = 1024
+
 // Constructs a slice of dirty items, to use w/ memIterator.
 func (store *Store) dirtyItems(start, end []byte) {
 	startStr, endStr := conv.UnsafeBytesToStr(start), conv.UnsafeBytesToStr(end)
@@ -291,7 +294,7 @@ func (store *Store) dirtyItems(start, end []byte) {
 	// O(N^2) overhead.
 	// Even without that, too many range checks eventually becomes more expensive
 	// than just not having the cache.
-	if n < 1024 {
+	if n < minSortSize {
 		for key := range store.unsortedCache {
 			if dbm.IsKeyInDomain(conv.UnsafeStrToBytes(key), start, end) {
 				cacheValue := store.cache[key]
@@ -322,6 +325,17 @@ func (store *Store) dirtyItems(start, end []byte) {
 		startIndex = 0
 	}
 
+	// Since we spent cycles to sort the values, we should process and remove a reasonable amount
+	// ensure start to end is at least minSortSize in size
+	// if below minSortSize, expand it to cover additional values
+	// this amortizes the cost of processing elements across multiple calls
+	if endIndex-startIndex < minSortSize {
+		endIndex = math.MinInt(startIndex+minSortSize, len(strL)-1)
+		if endIndex-startIndex < minSortSize {
+			startIndex = math.MaxInt(endIndex-minSortSize, 0)
+		}
+	}
+
 	kvL := make([]*kv.Pair, 0)
 	for i := startIndex; i <= endIndex; i++ {
 		key := strL[i]