search

chaintope / tapyrus-core

Tapyrus Core
MIT License
46 stars 17 forks source link

Fix duplicates in coin cache #277

Closed Naviabheeman closed 11 months ago

Naviabheeman commented 1 year ago

Utxo cache tracepoint execution shows add events duplicated. All new utxos seem to be added twice. When we compare the expected number of entries in the cache between tapyrus and bitcoin, our cache entries are very high. This could be a bug in tapyrus coin cache. It might have been fixed in bitcoin. We need to investigate this thoroughly.

logs from python bcc script:

#  sudo python3 test/functional/interface_usdt_utxocache.py
2023-08-11T08:37:45.637000Z TestFramework (INFO): Initializing test directory /tmp/test0okux19r
2023-08-11T08:37:45.963000Z TestFramework (INFO): Test using ECDSA signature scheme
2023-08-11T08:37:45.968000Z TestFramework (INFO): testing the utxocache:uncache tracepoint API
2023-08-11T08:37:45.991000Z TestFramework (INFO): hooking into the uncache tracepoint
2023-08-11T08:37:46.290000Z TestFramework (INFO): testmempoolaccept the invalid transaction to trigger an UTXO-cache uncache
2023-08-11T08:37:46.292000Z TestFramework (INFO): handle_utxocache_uncache(): UTXOCacheChange(outpoint=b0cb7416114fc2b5eaeaec4d6e12bdb7887d86f98eaaca1f2ca359d2c9a9f24c:0, token=TPC, height=1, value=5000000000 tapyrus, is_coinbase=True)
2023-08-11T08:37:46.301000Z TestFramework (INFO): check that we successfully traced 1 uncaches
2023-08-11T08:37:46.301000Z TestFramework (INFO): test the utxocache:add and utxocache:utxocache_spent tracepoint API
2023-08-11T08:37:46.301000Z TestFramework (INFO): create an unconfirmed transaction
2023-08-11T08:37:46.317000Z TestFramework (INFO): mine and invalidate a block that is later reconsidered
2023-08-11T08:37:46.324000Z TestFramework (INFO): hook into the utxocache:utxocache_add and utxocache:utxocache_spent tracepoints
2023-08-11T08:37:46.593000Z TestFramework (INFO): reconsider the previously invalidated block
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=76e201aecc36a4db180431050a0e057a37241d7db16cbde2d9bb9e9b0568bb33:0, token=TPC, height=102, value=5000007640 tapyrus, is_coinbase=True)
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=d7c110332312ecb92894537bc8d9711988fb0efcf7b05b1e6160ea5898a9697f:0, token=TPC, height=102, value=1000000000 tapyrus, is_coinbase=False)
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=d7c110332312ecb92894537bc8d9711988fb0efcf7b05b1e6160ea5898a9697f:1, token=TPC, height=102, value=3999996180 tapyrus, is_coinbase=False)
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=ab646c06e72ac88baafa654debdb899baec8d75b4742884e9595c8c09ff47dce:0, token=TPC, height=102, value=1000000000 tapyrus, is_coinbase=False)
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=ab646c06e72ac88baafa654debdb899baec8d75b4742884e9595c8c09ff47dce:1, token=TPC, height=102, value=3999996180 tapyrus, is_coinbase=False)
2023-08-11T08:37:46.601000Z TestFramework (INFO): handle_utxocache_spent(): UTXOCacheChange(outpoint=3cb1d08a79c7f4b6459fc371d928cfa2306b2bba944ff1544564d3726df3c138:0, token=TPC, height=9, value=5000000000 tapyrus, is_coinbase=True)
2023-08-11T08:37:46.602000Z TestFramework (INFO): handle_utxocache_spent(): UTXOCacheChange(outpoint=4f9a3fa4b7848c75d1b112b586f0912eb9126578a8a4d132d21adb5953da397b:0, token=TPC, height=5, value=5000000000 tapyrus, is_coinbase=True)
2023-08-11T08:37:46.620000Z TestFramework (INFO): check that we successfully traced 5 adds and 2 spent

logs from bpftrace scripts


# bpftrace contrib/tracing/log_utxos.bt
Attaching 4 probes...
OP      Outpoint                                                          Token                                                                          Value  Height Coinbase
Added   : e9e9e489f23b3952c9dbddde579a47fa636c21f0081ae84cabc2112be6b00ef   0      TPC                                                                       5000000000       1 Yes
Added   : e9e9e489f23b3952c9dbddde579a47fa636c21f0081ae84cabc2112be6b00ef   0      TPC                                                                       5000000000       1 Yes
Added   : e9e9e489f23b3952c9dbddde579a47fa636c21f0081ae84cabc2112be6b00ef   0      TPC                                                                       5000000000       1 Yes
Added   : 963902039acf07d715f0109c7fdebe5939c350e62d6c93424f7923cd7f79faa   0      TPC                                                                       5000000000       2 Yes
Added   : 963902039acf07d715f0109c7fdebe5939c350e62d6c93424f7923cd7f79faa   0      TPC                                                                       5000000000       2 Yes

In both these logs the same utxo is logged twice.

Naviabheeman commented 11 months ago

This was a false alarm. The reason for the duplicate entries in trace logs looks like multiple levels of caching.

These logs were collected with additional debugging for this and base pointers in CCoinsViewCache. It can be seen that the pointers are different. i.e. one entry is added to two different caches. There is one level of cache in memory and the base cache with mempool and leveldb interface. I'll confirm this.

debug.log

2023-11-30T15:26:06.708398Z CreateNewBlock(): block size: 202 txs: 0 fees: 0 sigops 100
2023-11-30T15:26:06.708457Z     - Sanity checks: 0.01ms [0.00s (0.01ms/blk)]
2023-11-30T15:26:06.708471Z     - Fork checks: 0.02ms [0.00s (0.02ms/blk)]
2023-11-30T15:26:06.708486Z  [0x7f89b9ff99a0 - 0x564190031610] FetchCoin [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] 
2023-11-30T15:26:06.708497Z  [0x564190031610 - 0x56419001bac0] FetchCoin [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] 
2023-11-30T15:26:06.708527Z   [0x7f89b9ff99a0 - 0x564190031610] AddCoin utxocache_add [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] fresh: [1] flags [3] inserted [1] possible_overwrite[0] cachedCoinsUsage[64]
2023-11-30T15:26:06.708700Z       - Connect 1 transactions: 0.22ms (0.223ms/tx, 0.000ms/txin) [0.00s (0.22ms/blk)]
2023-11-30T15:26:06.708729Z     - Verify 0 txins: 0.26ms (0.000ms/txin) [0.00s (0.26ms/blk)]
2023-11-30T15:26:06.708744Z CreateNewBlock() packages: 0.01ms (0 packages, 0 updated descendants), validity: 0.35ms (total 0.36ms)
2023-11-30T15:26:06.709527Z   - Load block from disk: 0.00ms [0.00s]
2023-11-30T15:26:06.709580Z     - Sanity checks: 0.01ms [0.00s (0.01ms/blk)]
2023-11-30T15:26:06.709594Z     - Fork checks: 0.02ms [0.00s (0.02ms/blk)]
2023-11-30T15:26:06.709609Z  [0x7f89b9ff9830 - 0x564190031610] FetchCoin [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] 
2023-11-30T15:26:06.709619Z  [0x564190031610 - 0x56419001bac0] FetchCoin [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] 
2023-11-30T15:26:06.709643Z   [0x7f89b9ff9830 - 0x564190031610] AddCoin utxocache_add [98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b7-0] fresh: [1] flags [3] inserted [1] possible_overwrite[0] cachedCoinsUsage[64]

trace log

#  contrib/tracing/log_utxos.bt
Attaching 4 probes...
OP      Outpoint                                                                                        Token            Value  Height Coinbase
Spent   :eb1a46fcddd76911fef927947b61c04f5a4dd9aeb8e24a58cf439d34f246c6f 0      TPC       5000000000     100 Yes
Spent   :5f2140dedbe800ae75b5a6045c3882d3d098179ac5627da2d21578f6bdaa131 0      TPC       5000000000      99 Yes
Spent   :8721da6706af76c8602dc4be9ac7e6e4d3a77d193c6fd299ca172834f6f97c0 0      TPC       5000000000      98 Yes
Spent   :4969251b7a14e9ec7b316ee754443a4941b286e0064c5a168cd96302cb79604 0      TPC       5000000000      97 Yes
Spent   :de987dc7ebe9098a952455f62e841250512b20ec642ebcb4ad046775e1107c1 0      TPC       5000000000      96 Yes
Spent   :55bf9031729c922e94c3534568c918f17709d0f0a124e7f6b15b69e549714d8 0      TPC       5000000000      95 Yes
Added  :98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b 0      TPC       5000000000     101 Yes
Added  :98e7dbf08131787013fd91344aad772922462c03f55bde21c5adcc0f6e9196b 0      TPC       5000000000     101 Yes

Bitcoin trace must be filtering out the mempool cache entries. I'll confirm this.

Naviabheeman commented 11 months ago

I confirmed that Bitcoin generates similar add events too. Its not a bug in tapyrus.

Bitcoin:

# bpftrace contrib/tracing/log_utxos.bt
Attaching 4 probes...
OP      Outpoint                                                                           Value  Height Coinbase
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     199 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     198 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     197 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     196 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     195 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     194 Yes
Added   02030405060708090a0b0c0d0e0fbc1112131415:0            2500000000     200 Yes
Added   02030405060708090a0b0c0d0e0fbc1112131415:0            2500000000     200 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     200 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            2500000000     199 Yes
Spent   18191a1b1c1d1e1f202122232425262728292a2b:0            5000000000      99 Yes

(Transaction id in these events is not accurate. bitcoin log_utxos.bt script does not succeed due to errors in the transaction id unroll. So it was edited to generate these outputs. The number of events generated is the same)

The same test case in tapyrus generates:

Tapyrus:

Spent   :eb1a46fcddd76911fef927947b61c04f5a4dd9aeb8e24a58cf439d34f246c6f 0      TPC       5000000000     100 Yes
Spent   :5f2140dedbe800ae75b5a6045c3882d3d098179ac5627da2d21578f6bdaa131 0      TPC       5000000000      99 Yes
Spent   :8721da6706af76c8602dc4be9ac7e6e4d3a77d193c6fd299ca172834f6f97c0 0      TPC       5000000000      98 Yes
Spent   :4969251b7a14e9ec7b316ee754443a4941b286e0064c5a168cd96302cb79604 0      TPC       5000000000      97 Yes
Spent   :de987dc7ebe9098a952455f62e841250512b20ec642ebcb4ad046775e1107c1 0      TPC       5000000000      96 Yes
Spent   :55bf9031729c922e94c3534568c918f17709d0f0a124e7f6b15b69e549714d8 0      TPC       5000000000      95 Yes
Added  :73776da2bcc8b5be584ad162e011562253d3f6643f2f0bfaf2d06ed33a0e47f 0      TPC       5001000000     101 Yes
Spent   :9c51c4798826f13bc24230b912e7bd626f58946ad77fbeba0795365122c8af0 0      TPC       5000000000       1 Yes
Added  :a5feded9562eaf7c27029c04f88d4c19abd79567a520527a22ad24be96fc105 0      TPC       4999000000     101 Yes
Added  :73776da2bcc8b5be584ad162e011562253d3f6643f2f0bfaf2d06ed33a0e47f 0      TPC       5001000000     101 Yes
Spent   :9c51c4798826f13bc24230b912e7bd626f58946ad77fbeba0795365122c8af0 0      TPC       5000000000       1 Yes
Added  :a5feded9562eaf7c27029c04f88d4c19abd79567a520527a22ad24be96fc105 0      TPC       4999000000     101 Yes