"Bat Ledger Service" causing 100% CPU usage

kjozwiak commented 4 years ago

Description

We've been receiving several reports from our users that Bat Ledger Service causes the CPU to increase to 100% in some cases in 1.5.x which causes performance issues. We've had a similar issue in 1.7.x and 1.8.x that we resolved via https://github.com/brave/brave-browser/issues/8691. However, this issue has been reported on 1.3.x, 1.4.x and 1.5.x so it's a different problem.

@NejcZdovc has been debugging the issue a user and mentioned that the CPU dropped from 100% once the ballets object in ledger_state was removed.

Some links to users experiencing this issue:

There's other reports via https://community.brave.com regarding high CPU usage even after https://github.com/brave/brave-browser/issues/8691 and https://github.com/brave/brave-browser/issues/8779 have been fixed.

Steps to Reproduce

N/A (currently we don't really have any STR as @NejcZdovc still investigating)

Actual result:

77358097-3e974d80-6d17-11ea-88c8-1cf32258a4e0

Expected result:

"Bat Ledger Service" shouldn't be using 100% of the CPU.

Reproduces how often:

N/A (we still don't know enough information but there's some users experiencing this)

Brave version (brave://version info)

This has been reported on 1.3.x, 1.4.x and the latest 1.5.x. Assuming it's an issue on every channel and separate from https://github.com/brave/brave-browser/issues/8691.

Version/Channel Information:

Can you reproduce this issue with the current release? Yes, received reports from 1.5.x
Can you reproduce this issue with the beta channel? Most likely also affected
Can you reproduce this issue with the dev channel? Most likely also affected
Can you reproduce this issue with the nightly channel? Most likely also affected

Other Additional Information:

Does the issue resolve itself when disabling Brave Shields? N/A
Does the issue resolve itself when disabling Brave Rewards? Most likely would resolve the issue
Is the issue reproducible on the latest version of Chrome? N/A

Miscellaneous Information:

CCing @NejcZdovc @mandar-brave @bsclifton @rebron @jsecretan

MinisterFister commented 4 years ago

Issue started for me after the migration of everything into publisher_info_db file. I can tell because I open Resource monitor on windows, go in the disk activity section and see publisher_info_db is doing a lot of read/write operations causing CPU + drive activity to spike.

I can reproduce this when I open several profiles at the same time that haven't been open for a few days and have ads enabled; this is when I take a noticeable hit (eg 100% usage on CPU and disk) for like 30 seconds until the r/w operations are done. Everything goes to normal though when whatever operations it needs to do finish. I don't remember this being as bad before the migration. I assume people with slower/less core CPUs or HDDs must take an even bigger hit. I have a quad core + an SSD and I still notice it.

NejcZdovc commented 4 years ago

@MinisterFister this is not related to db migration. It's operation that process publisher list. It normally takes 30s to complete. We are working on new mechanism that will solve it

aleqx commented 4 years ago

I neither did a db migration nor do I have multiple profiles. Issues still exists. One core is 100% utilized (regardless of your CPU).

SephReed commented 4 years ago

I'm getting this issue as well. If I end the process, it just comes back. How do I turn this off? I've tried turning off brave rewards. I could really use my browser back!

angsto commented 4 years ago

I have also this problem. I'm waiting one week and I don't see any progress. Practically the browser is not usable now(when I open it my cooling fans start working on 100%). Very soon I'll be forced to uninstall Brave.

NejcZdovc commented 4 years ago

@aleqx @SephReed @angsto if you go to your user profile (directories listed bellow) and open ledger_state file, do you have any entries under ballots? If that is the case what I would suggest is that you do the following.

MacOS: /Users/{username}/Library/Application Support/BraveSoftware/Default/ledger_state Windows: %USERPROFILE%/AppData/Local/BraveSoftware/Brave-Browser/User Data/Default/ledger_state Linux: ~/.config/BraveSoftware/Brave-Browser/Default

close browser
back up ledger_statee file
you delete everything that is in properties ballots like this

before:

....
"ballots": [{some data}, {some data}]
....

after:

....
"ballots": []
....

mariow commented 4 years ago

@NejcZdovc I've tried this on linux (by editing ~/.config/BraveSoftware/Brave-Browser/Default ) but unfortunately after restarting Brave the Bat Ledger Services immediately starts consuming 100% cpu again.

NejcZdovc commented 4 years ago

@mariow could you please run brave from the terminal and add this flag at the end--enable-logging=stderr. Let me please know what you see

angsto commented 4 years ago

I open the file and I have ,"ballots":[],

NejcZdovc commented 4 years ago

@angsto could you also try from the terminal with logs like I suggested to @mariow?

angsto commented 4 years ago

[24284:27484:0402/125733.531:WARNING:account_consistency_mode_manager.cc(235)] Desktop Identity Consistency cannot be enabled as no OAuth client ID and client secret have been configured. [24284:27484:0402/125733.536:INFO:ads_service_impl.cc(1181)] Migrating ads preferences [24284:27484:0402/125733.537:INFO:ads_service_impl.cc(1207)] Ads preferences are up to date on version 7 [24284:27484:0402/125733.559:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [24284:27484:0402/125733.560:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [24284:27484:0402/125733.569:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [24284:27484:0402/125733.576:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [26440:30336:0402/125733.611:INFO:confirmations_impl.cc(61)] Initializing confirmations [26440:30336:0402/125733.611:INFO:confirmations_impl.cc(769)] Loading confirmations state [24284:27484:0402/125733.614:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [26440:30336:0402/125733.688:INFO:confirmations_impl.cc(788)] Successfully loaded confirmations state [26440:30336:0402/125733.688:INFO:confirmations_impl.cc(749)] Saving confirmations state [26440:30336:0402/125733.689:INFO:confirmations_impl.cc(749)] Saving confirmations state [26440:30336:0402/125733.690:INFO:confirmations_impl.cc(749)] Saving confirmations state [26440:30336:0402/125733.712:INFO:confirmations_impl.cc(765)] Successfully saved confirmations state [26440:30336:0402/125733.718:INFO:confirmations_impl.cc(765)] Successfully saved confirmations state [24284:9896:0402/125733.722:WARNING:rewards_p3a.cc(185)] Bad ledger state [26440:30336:0402/125733.725:INFO:confirmations_impl.cc(765)] Successfully saved confirmations state [24284:27484:0402/125733.735:WARNING:CONSOLE(0)] "HTML Imports is deprecated and will be removed in M80, around February 2020. Please use ES modules instead. See https://www.chromestatus.com/features/5144752345317376 and https://developers.google.com/web/updates/2019/07/web-components-time-to-upgrade for more details.", source: (0) [26440:30336:0402/125733.740:VERBOSE1:ledger_impl.cc(424)] [ REQUEST ]

url: https://publishers-distro.basicattentiontoken.org/api/v3/public/channels method: UrlMethod::GET content: contentType: header: Accept-Encoding: gzip [ END REQUEST ] [26440:30336:0402/125733.740:INFO:contribution.cc(419)] Timer will start in 158 [26440:30336:0402/125733.745:INFO:contribution.cc(419)] Timer will start in 3 [26440:30336:0402/125733.747:INFO:contribution.cc(419)] Timer will start in 18 [26440:30336:0402/125733.755:INFO:confirmations_impl.cc(844)] SetWalletInfo: [26440:30336:0402/125733.755:INFO:confirmations_impl.cc(845)] Payment id: 8bc156b8-c7d2-48d8-8495-cf59fd1d13b2 [26440:30336:0402/125733.755:INFO:confirmations_impl.cc(846)] Private key: **** [26440:30336:0402/125733.755:INFO:confirmations_impl.cc(749)] Saving confirmations state [26440:30336:0402/125733.756:INFO:ads_rewards.cc(54)] Fetch ads rewards [26440:30336:0402/125733.756:INFO:ads_rewards.cc(114)] GetPaymentBalance [26440:30336:0402/125733.756:INFO:ads_rewards.cc(116)] GET /v1/confirmation/payment/{payment_id} [26440:30336:0402/125733.756:INFO:ads_rewards.cc(119)] URL Request: [26440:30336:0402/125733.756:INFO:ads_rewards.cc(122)] URL: https://ads-serve.brave.com/v1/confirmation/payment/8bc156b8-c7d2-48d8-8495-cf59fd1d13b2 [26440:30336:0402/125733.756:INFO:ads_rewards.cc(127)] Body: {} [26440:30336:0402/125733.758:INFO:ads_rewards.cc(130)] Headers: [26440:30336:0402/125733.759:INFO:ads_rewards.cc(132)] digest: SHA-256=RBNvo1WzZ4oRRq0W9+hknpT7T8If536DEMBg9hyq/4o= [26440:30336:0402/125733.759:INFO:ads_rewards.cc(132)] signature: keyId="primary",algorithm="ed25519",headers="digest",signature="dmqX4W6Wtfxi7zpLauWWNTtbWBdfzJYNKSE7XtJwE5MxPBPPEclY2cYRl5SVlrGkskpsIGOxf/QfZlK/B682BQ==" [26440:30336:0402/125733.759:INFO:ads_rewards.cc(132)] accept: application/json [26440:30336:0402/125733.759:INFO:ads_rewards.cc(136)] Content_type: application/json [26440:30336:0402/125733.759:INFO:confirmations_impl.cc(85)] Successfully initialized confirmations [26440:30336:0402/125733.761:INFO:confirmations_impl.cc(1336)] Start paying out redeemed tokens in 31 seconds [26440:30336:0402/125733.761:INFO:refill_tokens.cc(50)] Refill [26440:30336:0402/125733.761:INFO:refill_tokens.cc(75)] RequestSignedTokens [26440:30336:0402/125733.761:INFO:refill_tokens.cc(78)] No need to refill tokens as we already have 47 unblinded tokens which is above the minimum threshold of 20 [26440:30336:0402/125733.763:INFO:confirmations_impl.cc(1283)] Start retrying failed confirmations in 56 seconds [26440:30336:0402/125733.763:INFO:confirmations_impl.cc(1190)] OnTimer: timer_id: 2 retry_getting_signed_tokens_timerid: 0 payout_redeemed_tokens_timerid: 5 [26440:30336:0402/125733.763:INFO:ads_rewards.cc(98)] OnTimer: timer_id: 2 retry_timerid: 0

[26440:30336:0402/125733.763:INFO:uphold.cc(351)] OnTimer Uphold: 2 [26440:30336:0402/125733.764:VERBOSE1:ledger_impl.cc(424)] [ REQUEST ]

url: https://grant.rewards.brave.com/v1/promotions?migrate=true&paymentId=8bc156b8-c7d2-48d8-8495-cf59fd1d13b2&platform=windows method: UrlMethod::GET content: contentType: [ END REQUEST ] [26440:30336:0402/125733.764:INFO:promotion.cc(851)] Promotion corrupted 268fc4d1-235e-460c-9ad4-0983ddfcdf10 [26440:30336:0402/125733.766:VERBOSE1:ledger_impl.cc(424)] [ REQUEST ] url: https://grant.rewards.brave.com/v1/promotions/reportclobberedclaims method: UrlMethod::POST content: {"claimIds":[""]} contentType: application/json; charset=utf-8 [ END REQUEST ] [26440:30336:0402/125733.767:VERBOSE1:ledger_impl.cc(424)] [ REQUEST ] url: https://grant.rewards.brave.com/v1/promotions/268fc4d1-235e-460c-9ad4-0983ddfcdf10/claims/ method: UrlMethod::GET content: contentType: [ END REQUEST ] [26440:30336:0402/125733.772:INFO:confirmations_impl.cc(765)] Successfully saved confirmations state [24284:27484:0402/125733.797:WARNING:CONSOLE(1)] "no tab id so cannot request shield data from window focus change!", source: chrome-extension://mnojpmjdmbbfmejpflffifhffcmidifd/out/brave_extension_background.bundle.js (1) [24284:27484:0402/125734.248:WARNING:CONSOLE(1)] "Invalid asm.js: Unexpected token", source: chrome-extension://odbfpeeihdkbihmopkbjmoonfanlbfcl/bg-libs.js (1) [24284:27484:0402/125758.871:ERROR:CONSOLE(1)] "[Shields]: Can't request shields panel data. Error: No tab url specified", source: chrome-extension://mnojpmjdmbbfmejpflffifhffcmidifd/out/brave_extension_background.bundle.js (1) [24284:27484:0402/125758.878:ERROR:CONSOLE(1)] "[Shields]: Can't request shields panel data. Error: No tab url specified", source: chrome-extension://mnojpmjdmbbfmejpflffifhffcmidifd/out/brave_extension_background.bundle.js (1) [24284:27484:0402/125758.879:WARNING:CONSOLE(0)] "HTML Imports is deprecated and will be removed in M80, around February 2020. Please use ES modules instead. See https://www.chromestatus.com/features/5144752345317376 and https://developers.google.com/web/updates/2019/07/web-components-time-to-upgrade for more details.", source: (0) [24284:27484:0402/125758.882:ERROR:CONSOLE(0)] "Unchecked runtime.lastError: Cannot access contents of url "chrome://newtab/". Extension manifest must request permission to access this host.", source: chrome-extension://mnojpmjdmbbfmejpflffifhffcmidifd/_generated_background_page.html (0) [24284:27484:0402/125804.798:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [24284:27484:0402/125804.844:ERROR:CONSOLE(0)] "Unchecked runtime.lastError: Cannot access contents of url "chrome://history/". Extension manifest must request permission to access this host.", source: chrome-extension://mnojpmjdmbbfmejpflffifhffcmidifd/_generated_background_page.html (0) [24284:27484:0402/125804.867:WARNING:CONSOLE(0)] "HTML Imports is deprecated and will be removed in M80, around February 2020. Please use ES modules instead. See https://www.chromestatus.com/features/5144752345317376 and https://developers.google.com/web/updates/2019/07/web-components-time-to-upgrade for more details.", source: (0) [24284:27484:0402/125804.977:ERROR:CONSOLE(4)] "Polymer is already defined.", source: chrome://history/app.crisper.js (4) [24284:27484:0402/125819.998:WARNING:push_messaging_service_factory.cc(37)] PushMessagingService could not be built because InstanceID is unexpectedly disabled [24284:27484:0402/125833.563:ERROR:gcm_channel_status_request.cc(145)] GCM channel request failed. [24284:27484:0402/125844.645:INFO:CONSOLE(0)] "Autofocus processing was blocked because a document already has a focused element.", source: https://github.com/brave/brave-browser/issues/8846 (0) [24284:27484:0402/125901.964:ERROR:gcm_channel_status_request.cc(145)] GCM channel request failed. [24284:27484:0402/125950.873:ERROR:gcm_channel_status_request.cc(145)] GCM channel request failed.

NejcZdovc commented 4 years ago

@angsto could you please have brave open for example 10min with this CPU problem? I see https://publishers-distro.basicattentiontoken.org/api/v3/public/channels which is quite intensive operation. Wonder if this operation just didn't finish yet. We are working on new API v4 that should fix this problem

mariow commented 4 years ago

@NejcZdovc Sure - I had a few tabs open that were causing a lot of info to be dropped into the log (e.g. Google Mail with background processes), so I've closed all tabs exccept for this github issue and produced the attached log. brave.log

Also, as per your other question to @angsto - despite the CPU usage I have continued using Brave as my standard browser and the issue has been around (at least) all day yesterday and today (several hours of usage)

angsto commented 4 years ago

Brave was opened for 20 min. with no tabs opened. Brave-20 min.txt

NejcZdovc commented 4 years ago

@mariow @angsto thank you very much for sending logs, this is helping us a lot. Could I ask you for one more favor? Could run brave again with some more flags, so that I get even more detailed logs --enable-logging=stderr --vmodule=*rewards*=6 --log-level=2 --v=1. Thank you very much

mariow commented 4 years ago

Sure, please find attached. Hope it helps. brave-additional.log

angsto commented 4 years ago

Here is also mine. brave-more flagsl.log

aleqx commented 4 years ago

I don't mean to sound harsh but this is a pretty huge bug, and it persisted since 1.4 stable, and now 1.5 stable. Effectively users cannot win rewards nor pay rewards to content creators, so the latter bunch have be markedly affected.

May I suggest a more thorough testing for the stable releases and also a little less rush to release new major stable versions?

If content creators want to rely on Brave then it has to be actually be reliable. Having the income affected for months is sending a strong message that the tool and entire platform is unreliable. Recovering from that (changing perception) takes a long time. Such failures tend to loom over a product for very long periods and it's a shame.

May I also ask what the status on this? It's been almost two months since the problem was first discovered iirc.

p.s. I'm aware that the current beta contains a fix for this bug, but users can't be expected to just switch to beta and then back, when their entire profile has been setup for stable (plugins, settings, passwords, etc) given that the Beta and Stable use different profile dirs and compatibility between profile dirs isn't guaranteed (a simple copy back and forth may break things).

mariow commented 4 years ago

One more thing I just noticed while trying to see if anything changes the behavior: any interaction with the BAT wallet is broken while Bat Ledger Service is busy consuming CPU. I can't contribute/tip (neither automatic nor manual), cannot remove pending contributions, cannot disconnect from Uphold, recovery words are not visible. Setting up a new profile and switching to it does not resolve the issue - starting the browser fresh with the same new profile will keep the cpu usage down (until I switch to the "broken" profile once) Recovering the wallet and uphold connection in the new profile does not reproduce the cpu usage, so I guess it has to be something in the history of that wallet.

aleqx commented 4 years ago

I can't contribute/tip (neither automatic nor manual), cannot remove pending contributions, cannot disconnect from Uphold, recovery words are not visible.

That's what I was talking about in my post above as well (and in the forums and other tickets).

I guess it has to be something in the history of that wallet.

No, it has nothing to do with the wallet. It's a bug in Brave since 1.4. it was fixed in beta so if you really want to use Brave with rewards right now then you need to install beta and then copy the "Default" folder from the stable profile to the beta (otherwise beta starts with a fresh profile). This is not actually advisable because beta will alter the profile and then if you want to revert the procedure and copy it back to stable then you might find various broken things - there is no guarantee.

NejcZdovc commented 4 years ago

@aleqx just so confirm, beta version is working correctly with the same profile that doesn't work in current release?

aleqx commented 4 years ago

@NejcZdovc see my message above for details. Only the "Default" subfolder is copied from stable (where it doesn't work) to beta (where it does work)

NejcZdovc commented 4 years ago

@aleqx we are releasing beta to release this week. Please let me know if version 1.7 will fix it for you. Thank you very much for helping us out

@mariow thank you for the update

pihomeserver commented 4 years ago

Not sure if it helps but i have the issue in Brave 1.5.123 After installing latest beta (1.8.65) it seems to be solved

NejcZdovc commented 4 years ago

@pihomeserver really glad that it's working now. Thank you for the update

pihomeserver commented 4 years ago

@NejcZdovc let's hope it will be integrated in the next release of the stable version. The bug raises in the last update only (for me)

angsto commented 4 years ago

@NejcZdovc @emerick When we can expect working official version? I really cant use this browser...

NejcZdovc commented 4 years ago

@angsto we are targeting to releasing new version (1.7.x) today

bsclifton commented 4 years ago

Release pushed tentatively to Monday or Tuesday. But @angsto (others welcome too) you can give our release candidate a shot. You can download it from here: https://github.com/brave/brave-browser/releases/tag/v1.7.90

If you're on Windows, the one you want is BraveBrowserStandaloneSetup.exe

pihomeserver commented 4 years ago

@bsclifton Hi. Tested and same issue for me. 1 core is used only for the BAT ledger If you need specific information feel free to ask i will try to help

NejcZdovc commented 4 years ago

@pihomeserver ok so 1.7 doesn't fix it for you, but you said 1.8.x does (latest 1.8 version https://github.com/brave/brave-browser/releases/tag/v1.8.71)?

pihomeserver commented 4 years ago

@NejcZdovc 1.8.65 fixed it. There is also another difference (could be or not important) : the dev release is a new install and does not share data with stable one. The RC version overrides the stable one so it shares previous installed files.

NejcZdovc commented 4 years ago

@pihomeserver this is important one for sure. We only see this problem on some affected profiles. So to really test this one you would need to duplicate your profile, append -Beta and then start 1.8

pihomeserver commented 4 years ago

1.8 is a fresh install with no data shared (favorites, configuration, etc.) The 1.7 opens with all previous configuration settings. I try to have it in a fresh install

angsto commented 4 years ago

Release pushed tentatively to Monday or Tuesday. But @angsto (others welcome too) you can give our release candidate a shot. You can download it from here: https://github.com/brave/brave-browser/releases/tag/v1.7.90

If you're on Windows, the one you want is BraveBrowserStandaloneSetup.exe

OK. Now one hour use, it seems that 1.7.9(Windows 10 Pro 1909) it fix my problem. Thanks

pihomeserver commented 4 years ago

@angsto during install you overrided previous version or installed it somewhere else ?

angsto commented 4 years ago

@angsto during install you overrided previous version or installed it somewhere else ?

I just download BraveBrowserStandaloneSetup.exe and run it.

pihomeserver commented 4 years ago

Ok i moved configuration data in an old folder to start from scratch (folder /Users/chris/Library/Application Support/BraveSoftware/Brave-Browser) And started the new version 1.7.90 Now bug seems to be fixed

So i have to figure out how to get my configuration back without recreating the bug

peeter123 commented 4 years ago

I had this issue in Brave 1.5.123 and previous versions. After installing latest 1.7.90 the problem seems to be resolved.

bsclifton commented 4 years ago

Huge thanks to you all that have tried the fix and came back to verify it appears to be resolved 😄 This is great feedback!

@pihomeserver with your profile in place, as you mentioned when testing 1.7.90, it seems you're still having the issue ☹️ New profiles (for example, you move the folder out of the way) may not experience this, as @NejcZdovc shared. So it might be specific to your profile

I have noticed that on affected profiles, sometimes the CPU usage for Bat Ledger is quite high... and then it goes back down to very small usage (1%, etc). I wonder if you need to use 1.7.90 with your profile for a bit longer to where it fetches the publisher list again?

aleqx commented 4 years ago

1.7.90 RC2 works for me as well with the profile that was problematic in 1.4 and 1.5 (but I already knew this as I reported above, since I have been using 1.7 while in Beta)

However, my wallet balance is wrong ... I've been using Beta for the past month on a clone of the same profile, so I was expecting both to show the same balance as the would be linked to the same internal BAT wallet address? Can someone clarify?

@NejcZdovc can you explain the -Beta flag? And is it for the stable version? I'm nto sure I understand what it's meant to be doing ...

pihomeserver commented 4 years ago

@bsclifton that works ! I switched back the old profile backup to the configuration folder of brave and after 3-4 minutes the CPU dropped to less than 20%

Thank you guys for the software, the support and reactivity !

mariow commented 4 years ago

Sorry for the delay: I can confirm that 1.7.90 (Linux) fixed the problem for me as well, thanks for all your work on this!

aquaspy commented 4 years ago

Is any update coming to stable? Thanks!

SephReed commented 4 years ago

Still broken. Version 1.7.92 on MacOS

NejcZdovc commented 4 years ago

@aquaspy we released 1.7.x yesterday

pihomeserver commented 4 years ago

Still broken. Version 1.7.92 on MacOS

@sephreed No issue here. The CPU goes up for few minutes and then comes back to nearly 2/3 %. I had to wait less than 5 minutes

SephReed commented 4 years ago

@pihomeserver I will try again. As a thought, it might be nice if (when functional) it caps at ~25%. Not sure how feasible that is, but I really dislike hearing my fans go into overdrive for this. If it wasn't for my fans being loud, I wouldn't care, but it makes this particular utility really obnoxious.

NejcZdovc commented 4 years ago

closing for now as it looks like 1.7 fixed it. Please let us know if you still see this problem

aleqx commented 4 years ago

Not sure if this is related but my Brave Beta just upgraded itself to 1.9.45 and when it came back up it now says the wallet is disconnected. Is this known? If I click on it, it takes me to Uphold.com to verify my identity ... which I don't want to do, and I certainly hope that's not a new requirement.

I have a feeling that Brave got more and more unreliable lately :(

brave / brave-browser