Pending Transaction Performance Problems

[whymarrh]

This issue details a possible performance issue that exists with pending transactions are handled.

Setup:

1. Load MetaMask
2. Onboarding, create wallet, get Ropsten Ether, etc.
3. Enable "Customize transaction nonce"
   • Under Advanced Settings
4. Copy account address
5. Send transaction to the same account with nonce of 1 (pictured below)
   • This is supposed to be incorrect
6. Confirm that transaction
7. The transaction should be pending

Screenshot

On master @ a7bcc17f9/v7.7.8

Result:

• The transaction is stuck in pending (as expected)
• The txMeta.history for the transaction will grow unbounded at two rates:

  • Regularly/slowly as the transaction is retried with exponential backoff

    • 1 new entry each ((2^x) * (block time in seconds)) seconds
    • An example txMeta.history: v778-slow-history.log

  • Rapidly if the call to eth_getTransactionReceipt fails/throws

    • e.g. blocking the URL in devtools (pictured below)
      • https://api.infura.io/v1/jsonrpc/ropsten/eth_getTransactionReceipt?params=%5B%220x…%22%5D
    • An example txMeta.history: v778-fast-history.log

Screenshots

Once this history has grown significantly large, snapshotting the txMeta becomes prohibitvely expensive. (This is v7.7.8, before we added #8363.)

The rapid case—the worse one—is primarily the following loop:

• Update a transaction via updateTx(…)
• The transaction update is committed to memory via _saveTxList (tx-state-manager.js:466)
• TransactionController#_updateMemstore is run via this.txStateManager.store.subscribe(…) (index.js:111)
• Pending txs are updated via updatePendingTxs (pending-tx-tracker.js:43)
• A pending tx update fails, emitting a warning via this.emit('tx:warning', txMeta, err) (pending-tx-tracker.js:186)
• updateTx(…) is called via this.pendingTxTracker.on('tx:warning', …) (index.js:613)
• Rinse, repeat

Full stack trace

v778-network-fail-stacktrace-pathological.txt

updateTx (tx-state-manager.js:195) // Line 195 here is simply where I had the breakpoint
(anonymous) (index.js:613) // this.pendingTxTracker.on('tx:warning', ...)
safeApply (index.js:70)
SafeEventEmitter.emit (index.js:56)
_checkPendingTx (pending-tx-tracker.js:186) // this.emit('tx:warning', txMeta, err)

--- await in _checkPendingTx (async) ---

(anonymous) (pending-tx-tracker.js:43) // await Promise.all(pendingTxs.map((txMeta) => this._checkPendingTx(txMeta)))
updatePendingTxs (pending-tx-tracker.js:43)

--- await in updatePendingTxs (async) ---

_updateMemstore (index.js:727)
(anonymous) (index.js:111) // this.txStateManager.store.subscribe(() => this._updateMemstore())
safeApply (index.js:70)
SafeEventEmitter.emit (index.js:62)
putState (index.js:22)
updateState (index.js:30)
_saveTxList (tx-state-manager.js:466)
updateTx (tx-state-manager.js:205)
(anonymous) (index.js:613) // this.pendingTxTracker.on('tx:warning', ...)
safeApply (index.js:70)
SafeEventEmitter.emit (index.js:56)
_checkPendingTx (pending-tx-tracker.js:186)

--- await in _checkPendingTx (async) ---

(anonymous) (pending-tx-tracker.js:43) // await Promise.all(pendingTxs.map((txMeta) => this._checkPendingTx(txMeta)))
updatePendingTxs (pending-tx-tracker.js:43)

--- await in updatePendingTxs (async) ---

_onLatestBlock (index.js:712)
safeApply (index.js:70)
SafeEventEmitter.emit (index.js:62)
_setCurrentBlock (base.js:131)
_newPotentialLatest (base.js:125)
_updateLatestBlock (polling.js:65)

--- await in _updateLatestBlock (async) ---

_performSync (polling.js:48)

I believe the behaviour described here is as old as 507397f (#5431) which first shipped in v4.14.0.

On develop @ d90810263

Result:

• The transaction is stuck in pending (as expected)
• The txMeta.history for the transaction will grow unbounded at one rate:
  • Rapidly always
    • An example txMeta.history: develop-fast-history.log

This is all worse on develop where we essentially hit the pathological case with each pending transaction. As of #8351, _checkPendingTx will always emit a warning for a pending transaction. Admittedly this is also related to #7483, where the fallback for a null transaction receipt was originally mismanaged.

---

Notes:

• This investigation was spurred on by 100% CPU utilization #6547
• v778-slow-history.log
• v778-fast-history.log
• v778-network-fail-stacktrace-pathological.txt
• develop-fast-history.log

[whymarrh]

cc @danfinlay @rekmarks @Gudahtt

[rekmarks]

This is wonderful work!

The rapid case—the worse one—is primarily the following loop:

Just to confirm: your use of "primarily" here is to indicate that the most relevant steps of the loop are those you describe, not that you have reason to believe that there's some other, unknown cause?

[whymarrh]

Yes, I cut a few frames out of the stack trace in describing it

[whymarrh]

These fixes are slated for 7.7.9: #8444