100% CPU utilization

[u-abramchuk]

Hi,

we've faced an issue when metamask extension together with IdentityServer4's js make Chrome tab to utilize 100% CPU. The reason is in the way metamask extension uses messaging via window.addEventListener('message', ...) and window.postMessage.

It looks like the reason is that metamask extension subscribes to all window objects it can find, including IdentityServer's iframe.

Link to the original issue: https://github.com/IdentityServer/IdentityServer4/issues/3238

Is this the intended behavior?

[danfinlay]

MetaMask does create a listener for each window opened, to make its provider API available to that site. I'm surprised to hear that it would add up to 100% CPU though, because a single listener doesn't create this load.

You can see in our background.js file that we use extension-port-stream to wrap the message listener as a stream, and it seems to clean up its listener, so it doesn't seem like a listener leak on first look, but maybe we should look more closely.

Can you give us some insight into how you concluded this was listeners bringing CPU usage to 100%, and how you concluded those were the listeners responsible?

[u-abramchuk]

Here is callstack of metamask extension _write function calling handler in IdentityServer4 Checksession js: https://drive.google.com/open?id=1Wy3Wy_QkfNG_w-n9VoYjecp08-fXCV77

During debug I found out window.addEventListener("message", this._onMessage.bind(this), !1) calling twice: one time for the top window, and the second time for iframe.

[brockallen]

Just so @danfinlay is aware, the check session iframe mentioned here is from the OpenID Connect specification here: https://openid.net/specs/openid-connect-session-1_0.html#RPiframe. So it's not specifically an IdentityServer issue -- it's if the plugin is running on any page that uses OIDC.

[m17kea]

@danfinlay have you had a chance to look at this?

[danfinlay]

No, I have not. Maybe @tmashuang could check if he can verify this issue.

[logicethos]

I see this in bursts on Chrome/Ubuntu. 100% CPU on one core for up to 16 seconds at a time. I typically have a lot of tabs open (about 100 at the moment, across several screens). It makes the whole Chrome UI laggy, so when i'm not using Metamask, I disable it. As i type this now, sometimes the characters take a while to catch up.

[danfinlay]

I see this in bursts on Chrome/Ubuntu.

Any extra context about your usage could be helpful. Do you use many dapps? Does the slowness build up over time? Does it happen when you have a particular dapp or wallet open? Any favorite dapps could possibly help, too.

[logicethos]

It does seem to get progressively worse over time. I just disabled, and re-enabled the plugin, and it's ok now. I know if I leave this PC on overnight, it will be showing up in the task manager again in the morning.

Currently using instadapp.io although I don't think it's app related.

[logicethos]

Metamask started crashing, and became unusable. I had a transaction in a permanent state of "pending". I removed Metamask completely, and reinstalled with my seed.

It's fine now. 24 hours later, the CPU is not maxing out, and no lag.

[danfinlay]

Any info on that transaction to help us narrow the scope of the cause could help:

• Was this with a hardware wallet?
• Was this also using instadapp?
• Were you connected to the default Infura provider?

[uxt-exe]

I have extensive lag in the metamask extension UI. Currently, doing a normal activity (open metamask from icon, modify tx speed, press accept, press send) takes about 3 minutes of lag.

Basically unusable as it stands; even opening the display to copy my address takes 30-40 seconds.

• I'm on a high-end desktop, so should not be hitting any hardware resource limitations.
• this problem occurs regardless of if I have one tab open or many.
• this problem seems to be a little better during the first couple interactions (literally) after quitting and reopening the browser.
• the UI responds quickly when not logged in (password request form)
• "resetting account" - clearing tx history in account settings does not help.
• uninstalling and reinstalling metamask does not help.
• I am vanilla - connected to default provider and not connected to any hardware wallet etc.
• my account is only notable for having a lot of erc721 contract interactions.
• profiler looks like the hangs are on snapshotFromTxMeta and replayHistory functions. That is, compute lag - not waiting on network or anything. I've included a screenshot. I believe each set of snapshotFromTxMeta and replayHistory corresponds to a UI interaction.
• it has progressively gotten worse over last month.
• other extensions: uBlock Origin, Dark Reader. Disabling them does not improve the lag.

If you have suggestions I'd be happy to try them.

[uxt-exe]

looking into this a bit cause it's causing me headaches.

here's the function we seem to be hanging on: https://github.com/MetaMask/metamask-extension/blob/c1453c75282e450ad063e9fff4cd3d0939ddde31/app/scripts/controllers/transactions/tx-state-manager.js#L193

examining just the first call inside this function that's causing most of the lag: https://github.com/MetaMask/metamask-extension/blob/c1453c75282e450ad063e9fff4cd3d0939ddde31/app/scripts/controllers/transactions/tx-state-manager.js#L200

snapShotFromTxMeta is defined here (notice the deep copy): https://github.com/MetaMask/metamask-extension/blob/4136209f3dfbdf1056b7589eee4a94a08f7f2262/app/scripts/controllers/transactions/lib/tx-state-history-helper.js#L68-L74

I examined txMeta when it's passed to updateTx... My txMeta.history has 102621 entries, and many of those entries are themselves nested arrays. It's not clear to me why we need the snapshot and history replay yet, but could something be done rather than an expensive deep copy for every interaction? Cached state that gets updated as we go? we deep copy this large history array and delete it immediately after. unused!

My current limited view on this is that this deep copy and history replay are degrading performance, a lightweight and fast solution is needed since these "web wallets" get a lot of use. I consider myself an average Metamask user.

thanks

[danfinlay]

@uxt-exe Thank you very much for the detailed analysis & diagnosis!

This history feature has been very useful for debugging issues users have had that were hard to track, but if it's the cause of this performance issue, than we need to find another approach to it.

I'll be raising this with the extension team today. Thanks again!

[whymarrh]

@uxt-exe would you mind sharing the context around that snapshot? Is that while a transaction is pending?

Re: the transaction with the 102621 history entries, is that your most recent transaction or is that an older transaction?

[whymarrh]

@uxt-exe a few more bits of context that would be useful:

• uninstalling and reinstalling metamask does not help.

  Do you go through the onboarding after this re-install?

• I am vanilla - connected to default provider and not connected to any hardware wallet etc.

  When you say default provider, are you connected to Mainnet? If not, can you share what network you're connected to and what the avg. block time might be for the network?

Edit: actually, would you mind sending your state logs to [email protected] and referencing this issue number?

[uxt-exe]

@uxt-exe would you mind sharing the context around that snapshot? Is that while a transaction is pending?

The snapshot corresponds to the actions I mentioned: open metamask from icon, modify tx speed, press accept, press send. No transaction is pending. Each UI interaction (click) corresponds to one of the four sets of snapshotFromTxMeta and replayHistory

Re: the transaction with the 102621 history entries, is that your most recent transaction or is that an older transaction?

The history array of txMeta has 102621 entities. I checked it out when I was debugging yesterday so it should be my most recent. There snapshot was taken a couple days before so there have been a few transactions in between (they aren't from the exact same event.)

Do you go through the onboarding after this re-install?

I recovered my accounts using my previous mnemonic. Making a totally new account does fix the problem.

When you say default provider, are you connected to Mainnet? If not, can you share what network you're connected to and what the avg. block time might be for the network?

Yes, I'm on vanilla ethereum mainnet, so average block time is about 13 seconds lately.

[whymarrh]

@uxt-exe thanks, that is clearer—would you mind sending your state logs to [email protected] and referencing this issue number? I'm trying to understand what would cause the history to bloat to 100k+ items, as it should only be appended to while the tx hasn't been confirmed.

[uxt-exe]

I'm sorry @whymarrh but I did indeed have a pending transaction in an account I haven't used in a while.

I understand the problem now:

• Some account (not necessarily the active account!) has a "bad" pending transaction(s) that cannot succeed. In my case the throwaway account was used for Decentraland name registration and the final tx to empty the account used more eth than was available.
• With every block, _onLatestBlock tries to resubmit bad tx with resubmitPendingTxs.
• Bad transaction always fails so tx:warning is always emitted.
• With each emission, pendingTxTracker fires, calling txStateManager.updateTx()
• updateTx pushes entry to txMeta.history, increasing its size.
• Since the transaction is never resolved, history keeps growing with identical entries.
• With each entry, the deep copy from snapshotFromTxMeta and replayHistory gets more intensive.

to replicate:

• send yourself a transaction with a very low fee so it's never confirmed.
• break on updateTx and watch e.history grow as blocks pass. Make it really big by emitting latest with artificial block data, or just expanding history with entries directly.
• have lag.
• clear e.history
• lag is fixed.

some potential solutions:

• recognize the transaction was very unlikely to succeed and stop trying after some number of attempts.

• Alternatively, scanning the history for an identical pending-tx-tracker#event and just updating the timestamp rather than adding another entry might be easiest. Would this have other implications?

• A red banner or warning icon in the UI telling the user they have a long pending transaction could help people understand what was going on.

thank you

[afmsavage]

Not sure if this is related, but my Metamask extension in Chrome has been pegging my CPU lately for no reason. I do not have any web3 tabs open for it to connect to but I came back to my computer and my fan is screaming for some reason. Here are some screenshots of what I'm seeing and please let me know if there is any other data I can collect to help. This happens about once a week to me lately. I have to End the Metamask Extension process in Chrome for it to stop.

Win10 ver2004 Chrome Version 80.0.3987.163 (Official Build) (64-bit) MetaMask 7.7.8

[whymarrh]

@afmsavage would you mind selecting the Call Tree in that devtools screenshot and sharing a picture of that? Do any of your accounts have pending transactions? Are you connected to mainnet?

Would you mind sharing that profile and/or statelogs with [email protected] (i.e. Save a recording or state logs)

[afmsavage]

@whymarrh I sadly have closed out of that devtools and killed the Metamask process. I will email in a copy of the statelogs from Metamask and email that in to support. If/when this happens again, I will grab that other info from Chrome.

I did not have any pending transactions on my account and yes i was connected to mainnet. Something to note, I did have a failed transaction with a contract earlier this evening. That tx failed right away though and wasn't in a pending state for any period of time.

[whymarrh]

@uxt-exe @afmsavage we've fixed what we believe to be the root causes of the these perf issues, largely centred around how we handle pending transactions (refs #8377; @afmsavage I understand you did not have any pending txs but the snapshot performance was bad in many cases and that fix is still an improvement). These fixes will be out in 7.7.9 early this week.

If either of you are interested in testing the release candiate (RC) for 7.7.9, @metamaskbot adds builds to https://github.com/MetaMask/metamask-extension/pull/8444.

[martinkrung]

I still have this problem on google chrome 81.0 on ubunut and Version 7.7.9. Metamaks is very slow and takes a lot of CPU power. This is the reason I changed to firefox to use metamaks, because its so leggy. I experience this on two machine with same software. I think this started with chrome 81. (I do have a lot of open tabs, maybe this is a problem?)

[brad-decker]

@martinkrung -- out of curiosity do you get better/worse performance on chrome with the popup UI versus the fullscreen UI? We have noticed some differences in these experiences internally. This is purely for research purposes, not a suggestion to use or the other to bypass performance problems. Genuinely interested in hearing your experience

[martinkrung]

No difference, full screen UI fires up CPU as well. 100%!

[samscalet]

hello i got high cpu usage and lagging,same as comment above i got pending tx from 2 of my account, when open that account i got my entire chrome langging sometime it freeze my desktop. i had to force shutdown. its getting worse everyday.

[martinkrung]

"resetting account" and deleting history did fixed it for me!

[brad-decker]

Hmmm... @martinkrung how many transactions did you have in your history, rough order of magnitude is perfectly fine. @samscalet -- same question?

[samscalet]

got 60 account, one with 134 tx history the other i could say around 10-20. hey, just speedup that long pending transactions on 2 of my account the lag just gone too bad it took me almost 20 minutes to send 1 speedup transactions. now everything back to normal no more lag

[afmsavage]

This is currently happening again to me. The thing I noticed, and somehow remember from last time is I had a failed transaction sometime recently before it started to peg my CPU. I have grabbed the profile from chrome devtools for you guys.

https://gist.githubusercontent.com/afmsavage/4fd5be0c3afb3303046d6547a9917ebc/raw/089b7b24b96be0145b33b43dacd1b58fc9506752/metamask-hotcpu-Profile-20200728T215546.json