dcrdata icon indicating copy to clipboard operation
dcrdata copied to clipboard

Published 20 hours ago • verified publisher icon decred

stakedb: upgrade ticket pool badger DB from v1.6.2 to v3.2103.2

Open ukane-philemon opened this issue 2 years ago • 5 comments

This upgrades the badger DB used by the ticket pool from v1.6.2 to v3.2103.2. Closes #1750.

Successful upgrade log 
2022-12-14 09:58:19.740 [INF] DATD: Log folder:  /root/.dcrdata/logs/mainnet
2022-12-14 09:58:19.740 [INF] DATD: Config file: /root/.dcrdata/dcrdata.conf
2022-12-14 09:58:19.741 [INF] DATD: dcrdata version 6.2.0-pre+dev (Go version go1.19.3)
2022-12-14 09:58:19.749 [INF] RPCC: Established connection to RPC server localhost:9109
2022-12-14 09:58:19.752 [INF] DATD: Connected to dcrd (JSON-RPC API v8.0.0) on MainNet
2022-12-14 09:58:19.752 [INF] SKDB: Loading ticket pool DB. This may take a minute...
2022-12-14 09:58:19.752 [INF] SKDB: Your ticket pool DB is not compatible with current badger version. Please wait for backup...
2022-12-14 09:58:19.752 [INF] SKDB: Backing up ticket pool DB to /root/.dcrdata/data/mainnet/ticket_pool.bdgr-bak before upgrading. This may take a while...
2022-12-14 09:58:20.379 [INF] SKDB: Your ticket pool DB backup was successful.
2022-12-14 09:58:20.416 [INF] SKDB: Automatic upgrade to version 3 started...
2022-12-14 09:58:20.644 [INF] SKDB: badger: All 1 tables opened in 224ms
2022-12-14 09:58:20.648 [INF] SKDB: Loading all ticket pool diffs from DB...
2022-12-14 09:58:23.106 [INF] SKDB: Successfully loaded 720253 ticket pool diffs
2022-12-14 09:58:23.115 [INF] SKDB: badger: All 0 tables opened in 0s
2022-12-14 09:58:23.116 [INF] SKDB: badger: Discard stats nextEmptySlot: 0
2022-12-14 09:58:23.116 [INF] SKDB: badger: Set nextTxnTs to 0
2022-12-14 09:58:23.116 [INF] SKDB: badger: DropAll called. Blocking writes...
2022-12-14 09:58:23.116 [INF] SKDB: badger: Writes flushed. Stopping compactions now...
2022-12-14 09:58:23.119 [INF] SKDB: badger: Deleted 0 SSTables. Now deleting value logs...
2022-12-14 09:58:23.119 [INF] SKDB: badger: Value logs deleted. Creating value log file: 1
2022-12-14 09:58:23.119 [INF] SKDB: badger: Deleted 1 value log files. DropAll done.
2022-12-14 09:58:23.120 [INF] SKDB: badger: Resuming writes
2022-12-14 09:58:27.430 [INF] SKDB: Successfully rewrote DB to version 3
2022-12-14 09:58:27.612 [INF] SKDB: Automatic upgrade to version 3 was successful
2022-12-14 09:58:27.612 [INF] SKDB: You may delete the old ticket pool DB file (/root/.dcrdata/data/mainnet/ticket_pool.bdgr-bak).
2022-12-14 09:58:27.612 [INF] SKDB: Loading all ticket pool diffs from DB version 3...
2022-12-14 09:58:29.673 [INF] SKDB: Successfully loaded 720253 ticket pool diffs
2022-12-14 09:58:29.862 [INF] SKDB: Advancing ticket pool DB to tip via diffs...
2022-12-14 09:58:30.802 [INF] SKDB: Pre-populating live ticket cache and computing pool value...
2022-12-14 09:58:38.321 [INF] DATD: Loaded StakeDatabase at height 720253
2022-12-14 09:58:38.321 [INF] DATD: Address cache capacity: 4096 addresses: ~512 MiB tx data (3947580 items) + 512 MiB UTXOs

EDIT:

Successful upgrade log 
2022-12-15 19:43:19.144 [INF] DATD: Log folder:  /root/.dcrdata/logs/mainnet
2022-12-15 19:43:19.144 [INF] DATD: Config file: /root/.dcrdata/dcrdata.conf
2022-12-15 19:43:19.144 [INF] DATD: dcrdata version 6.2.0-pre+dev (Go version go1.19.3)
2022-12-15 19:43:19.146 [INF] RPCC: Established connection to RPC server localhost:9109
2022-12-15 19:43:19.147 [INF] DATD: Connected to dcrd (JSON-RPC API v8.0.0) on MainNet
2022-12-15 19:43:19.147 [INF] SKDB: Loading ticket pool DB. This may take a minute...
2022-12-15 19:43:19.148 [INF] SKDB: Upgrading ticket pool DB to version 1
2022-12-15 19:43:19.341 [INF] SKDB: badger: All 1 tables opened in 190ms
2022-12-15 19:43:19.344 [INF] SKDB: Upgrading ticket pool DB to version 2
2022-12-15 19:43:19.550 [INF] SKDB: badger: All 1 tables opened in 203ms
2022-12-15 19:43:19.552 [INF] SKDB: Backing up ticket pool DB to /root/.dcrdata/data/mainnet/ticket_pool.bdgr-bak before upgrading. This may take a while...
2022-12-15 19:43:19.682 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.020712ms.
2022-12-15 19:43:19.762 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.901798ms.
2022-12-15 19:43:19.855 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 22.440447ms.
2022-12-15 19:43:19.917 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.583304ms.
2022-12-15 19:43:19.993 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.484396ms.
2022-12-15 19:43:20.072 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.157435ms.
2022-12-15 19:43:20.145 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 11.173582ms.
2022-12-15 19:43:20.230 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.49463ms.
2022-12-15 19:43:20.305 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.605834ms.
2022-12-15 19:43:20.379 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 9.790649ms.
2022-12-15 19:43:20.450 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 10.291776ms.
2022-12-15 19:43:20.528 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 11.241865ms.
2022-12-15 19:43:20.598 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 9.222519ms.
2022-12-15 19:43:20.598 [INF] SKDB: badger: DB.Backup Time elapsed: 01s, bytes sent: 55 MB, speed: 55 MB/sec
2022-12-15 19:43:20.666 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.684576ms.
2022-12-15 19:43:20.736 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.406371ms.
2022-12-15 19:43:20.873 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 71.279286ms.
2022-12-15 19:43:20.886 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.999811ms.
2022-12-15 19:43:20.955 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 9.245852ms.
2022-12-15 19:43:21.025 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.264333ms.
2022-12-15 19:43:21.110 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 10.452983ms.
2022-12-15 19:43:21.183 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.317278ms.
2022-12-15 19:43:21.252 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 9.204826ms.
2022-12-15 19:43:21.325 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.352212ms.
2022-12-15 19:43:21.407 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.871461ms.
2022-12-15 19:43:21.487 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.158807ms.
2022-12-15 19:43:21.558 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.72563ms.
2022-12-15 19:43:21.595 [INF] SKDB: badger: DB.Backup Time elapsed: 02s, bytes sent: 110 MB, speed: 55 MB/sec
2022-12-15 19:43:21.632 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.675448ms.
2022-12-15 19:43:21.709 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.503776ms.
2022-12-15 19:43:21.779 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.134142ms.
2022-12-15 19:43:21.854 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.953518ms.
2022-12-15 19:43:21.931 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 12.09688ms.
2022-12-15 19:43:22.078 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 79.89348ms.
2022-12-15 19:43:22.090 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.120829ms.
2022-12-15 19:43:22.152 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.025047ms.
2022-12-15 19:43:22.225 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.601728ms.
2022-12-15 19:43:22.304 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 11.795625ms.
2022-12-15 19:43:22.373 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.996106ms.
2022-12-15 19:43:22.440 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.533488ms.
2022-12-15 19:43:22.508 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.935097ms.
2022-12-15 19:43:22.578 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.445574ms.
2022-12-15 19:43:22.595 [INF] SKDB: badger: DB.Backup Time elapsed: 03s, bytes sent: 169 MB, speed: 56 MB/sec
2022-12-15 19:43:22.652 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.315566ms.
2022-12-15 19:43:22.728 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 9.25035ms.
2022-12-15 19:43:22.794 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.180166ms.
2022-12-15 19:43:22.923 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.247908ms.
2022-12-15 19:43:23.096 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.223136ms.
2022-12-15 19:43:23.268 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.663541ms.
2022-12-15 19:43:23.431 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.239961ms.
2022-12-15 19:43:23.659 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 70.77837ms.
2022-12-15 19:43:23.659 [INF] SKDB: badger: DB.Backup Time elapsed: 04s, bytes sent: 202 MB, speed: 51 MB/sec
2022-12-15 19:43:23.764 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.964961ms.
2022-12-15 19:43:23.937 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.535093ms.
2022-12-15 19:43:24.030 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.110399ms.
2022-12-15 19:43:24.047 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.484832ms.
2022-12-15 19:43:24.063 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.215557ms.
2022-12-15 19:43:24.079 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.074869ms.
2022-12-15 19:43:24.097 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.789145ms.
2022-12-15 19:43:24.118 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.562338ms.
2022-12-15 19:43:24.135 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 8.27209ms.
2022-12-15 19:43:24.151 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.413806ms.
2022-12-15 19:43:24.167 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.528918ms.
2022-12-15 19:43:24.183 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.335602ms.
2022-12-15 19:43:24.204 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 10.563576ms.
2022-12-15 19:43:24.220 [INF] SKDB: badger: DB.Backup Created batch of size: 4.2 MB in 7.028091ms.
2022-12-15 19:43:24.257 [INF] SKDB: badger: DB.Backup Created batch of size: 2.2 MB in 3.831008ms.
2022-12-15 19:43:24.257 [INF] SKDB: badger: DB.Backup Sent 720254 keys
2022-12-15 19:43:24.316 [INF] SKDB: Your ticket pool DB backup was successful.
2022-12-15 19:43:24.410 [INF] SKDB: badger: All 0 tables opened in 0s
2022-12-15 19:43:24.411 [INF] SKDB: badger: Discard stats nextEmptySlot: 0
2022-12-15 19:43:24.412 [INF] SKDB: badger: Set nextTxnTs to 0
2022-12-15 19:43:26.505 [INF] SKDB: Upgrade completed. You may delete the old ticket pool DB backup file at (/root/.dcrdata/data/mainnet/ticket_pool.bdgr-bak).
2022-12-15 19:43:26.505 [INF] SKDB: badger: Lifetime L0 stalled for: 0s
2022-12-15 19:43:26.697 [INF] SKDB: badger:
Level 0 [ ]: NumTables: 04. Size: 247 MiB of 0 B. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 64 MiB
Level 1 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 2 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 3 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 4 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 5 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 6 [B]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level Done
2022-12-15 19:43:26.787 [INF] SKDB: Ticket pool DB has been successfully upgraded to version 2
2022-12-15 19:43:26.791 [INF] SKDB: badger: All 4 tables opened in 1ms
2022-12-15 19:43:26.792 [INF] SKDB: badger: Discard stats nextEmptySlot: 0
2022-12-15 19:43:26.792 [INF] SKDB: badger: Set nextTxnTs to 1434821
2022-12-15 19:43:26.792 [INF] SKDB: Loading all ticket pool diffs from DB version 2...
2022-12-15 19:43:28.838 [INF] SKDB: Successfully loaded 720253 ticket pool diffs
2022-12-15 19:43:29.036 [INF] SKDB: Advancing ticket pool DB to tip via diffs...
2022-12-15 19:43:29.710 [INF] SKDB: Pre-populating live ticket cache and computing pool value...
2022-12-15 19:43:35.005 [INF] DATD: Loaded StakeDatabase at height 720253

ukane-philemon avatar Dec 14 '22 14:12 ukane-philemon

While badger is running fine, I've been getting these logs. Do you think we need to increase the block cache beyond the default?

2022-12-22 05:03:28.474 [WRN] SKDB: badger: Block cache might be too small. Metrics: hit: 2 miss: 111653 keys-added: 68018 keys-updated: 0 keys-evicted: 43257 cost-added: 268497841 cost-evicted: 172258160 sets-dropped: 0 sets-rejected: 177 gets-dropped: 9216 gets-kept: 102336 gets-total: 111655 hit-ratio: 0.00
2022-12-22 05:03:28.475 [WRN] SKDB: badger: Cache life expectancy (in seconds): 
 -- Histogram: 
Min value: 0 
Max value: 2 
Count: 16 
50p: 2.00 
75p: 2.00 
90p: 4.00 
[0, 2) 12 75.00%
[2, 4) 4 25.00%

ukane-philemon avatar Dec 22 '22 05:12 ukane-philemon

While badger is running fine, I've been getting these logs. Do you think we need to increase the block cache beyond the default?

2022-12-22 05:03:28.474 [WRN] SKDB: badger: Block cache might be too small. Metrics: hit: 2 miss: 111653 keys-added: 68018 keys-updated: 0 keys-evicted: 43257 cost-added: 268497841 cost-evicted: 172258160 sets-dropped: 0 sets-rejected: 177 gets-dropped: 9216 gets-kept: 102336 gets-total: 111655 hit-ratio: 0.00
2022-12-22 05:03:28.475 [WRN] SKDB: badger: Cache life expectancy (in seconds): 
 -- Histogram: 
Min value: 0 
Max value: 2 
Count: 16 
50p: 2.00 
75p: 2.00 
90p: 4.00 
[0, 2) 12 75.00%
[2, 4) 4 25.00%

To determine that, we'll have to deploy to see a real use case, otherwise it's just append-only with no gets.

Try testing the "full" ticket pool API endpoint, traversing to pool snapshots at distant heights. Compare performance with badger v1 and with different cache settings for v3.

chappjc avatar Dec 22 '22 05:12 chappjc 

2022/12/22 06:55:30 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:29560 - 200 2731123B in 824.332317ms
2022/12/22 06:55:47 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:30039 - 200 2731123B in 708.798579ms
2022/12/22 06:56:01 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:30430 - 200 2731123B in 797.757222ms

Don't know how long for badger v1 cuz I've upgraded already. @chappjc, can you check how long for v1?

ukane-philemon avatar Dec 22 '22 07:12 ukane-philemon

To specify a snapshot at a given block, use the endpoint: /stake/pool/b/{idxorhash}/full

On Thu, Dec 22, 2022, 1:09 AM Philemon Ukane @.***> wrote:

2022/12/22 06:55:30 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:29560 - 200 2731123B in 824.332317ms 2022/12/22 06:55:47 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:30039 - 200 2731123B in 708.798579ms 2022/12/22 06:56:01 "GET http://134.209.25.156:7777/api/stake/pool/full HTTP/1.1" from 105.113.40.37:30430 - 200 2731123B in 797.757222ms

Don't know how long for badger v1 cuz I've upgraded already. @chappjc https://github.com/chappjc, can you check how long for v1?

— Reply to this email directly, view it on GitHub https://github.com/decred/dcrdata/pull/1948#issuecomment-1362491685, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACHQOSKHYUG6GDNNTG7ZHWDWOP5CDANCNFSM6AAAAAAS6RT66U . You are receiving this because you were mentioned.Message ID: @.***>

chappjc avatar Dec 22 '22 14:12 chappjc

Okay. Thanks. I changed BlockCacheSize to 1<<29 and I no longer see those log messages.

Edit: 2022/12/22 21:17:14 "GET http://134.209.25.156:7777/api/stake/pool/b/200/full HTTP/1.1" from 105.113.41.229:24906 - 200 3B in 839.002419ms 2022/12/22 21:17:45 "GET http://134.209.25.156:7777/api/stake/pool/b/5000/full HTTP/1.1" from 105.113.41.229:25173 - 200 2590356B in 806.305193ms 2022/12/22 21:18:04 "GET http://134.209.25.156:7777/api/stake/pool/b/10000/full HTTP/1.1" from 105.113.41.229:25321 - 200 2839194B in 787.385809ms 2022/12/22 21:18:25 "GET http://134.209.25.156:7777/api/stake/pool/b/50000/full HTTP/1.1" from 105.113.41.229:25490 - 200 2862644B in 778.152198ms 2022/12/22 21:18:42 "GET http://134.209.25.156:7777/api/stake/pool/b/500000/full HTTP/1.1" from 105.113.41.229:25718 - 200 2771725B in 1.197912796s. // took so long? 2022/12/22 21:19:21 "GET http://134.209.25.156:7777/api/stake/pool/b/700000/full HTTP/1.1" from 105.113.41.229:26204 - 200 2745327B in 939.924622ms 2022/12/22 21:19:37 "GET http://134.209.25.156:7777/api/stake/pool/b/1/full HTTP/1.1" from 105.113.41.229:26467 - 200 3B in 784.223715ms 2022/12/22 21:19:50 "GET http://134.209.25.156:7777/api/stake/pool/b/3000/full HTTP/1.1" from 105.113.41.229:26654 - 200 1689206B in 755.562555ms 2022/12/22 21:20:05 "GET http://134.209.25.156:7777/api/stake/pool/b/2000/full HTTP/1.1" from 105.113.41.229:26849 - 200 1414841B in 613.220104ms

I don't know if these results could be affected by the cloud machine am running dcrdata on.

ukane-philemon avatar Dec 22 '22 21:12 ukane-philemon