TorBrowser 8.0 high cpu usage while idle, in whonix

tatertot · September 7, 2018, 2:17am

Edit: added more testing
Edit: replace old versions with new ones

Has anyone else observed this?

An idle torbrowser 8.0 with no addons and just the home page open, running in whonix-ws-14, eventually uses 50%-150% cpu. This occurs after torbrowser is running for a while. Often occurs after resuming from suspend, but suspending is not necessary.

TorBrowser 8.0.3/8.5a2: affected
TorBrowser 8.0.1 with extensions.torbutton.versioncheck_enabled := false: affected
TorBrowser 8.0 manually downloaded from torproject.org running in a debian-9 VM: not affected
firefox-60.2.0esr on whonix-14: not affected

strace excerpt:

strace: Process 1236 attached
strace: [ Process PID=1236 runs in x32 mode. ]
strace: [ Process PID=1236 runs in 64 bit mode. ]
write(21, "M", 1)                       = 1
futex(0x77eec4968b08, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({tv_sec=1536281272, tv_usec=371176}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=747749190}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=747800286}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=747856121}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=747912515}) = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}, {fd=33, events=POLLIN}, {fd=53, events=POLLIN}, {fd=71, events=POLLIN}], 6, 0) = 1 ([{fd=33, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748119767}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748175956}) = 0
read(33, "\372", 1)                     = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748289733}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748345557}) = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}, {fd=33, events=POLLIN}, {fd=53, events=POLLIN}, {fd=71, events=POLLIN}], 6, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748523610}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748579429}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=748636882}) = 0
gettimeofday({tv_sec=1536281272, tv_usec=372185}, NULL) = 0
ioctl(60, FIONREAD, [0])                = 0
ioctl(60, FIONREAD, [0])                = 0
recvfrom(60, "", 0, 0, NULL, NULL)      = 0
write(21, "M", 1)                       = 1
futex(0x77eec4968b08, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({tv_sec=1536281272, tv_usec=372585}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749156071}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749212254}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749268018}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749324779}) = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}, {fd=33, events=POLLIN}, {fd=53, events=POLLIN}, {fd=71, events=POLLIN}], 6, 0) = 1 ([{fd=33, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749516152}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749573911}) = 0
read(33, "\372", 1)                     = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749691617}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749748225}) = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}, {fd=33, events=POLLIN}, {fd=53, events=POLLIN}, {fd=71, events=POLLIN}], 6, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749928040}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=749984307}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=750062799}) = 0
gettimeofday({tv_sec=1536281272, tv_usec=373612}, NULL) = 0
ioctl(60, FIONREAD, [0])                = 0
ioctl(60, FIONREAD, [0])                = 0
recvfrom(60, "", 0, 0, NULL, NULL)      = 0
write(21, "M", 1)                       = 1
futex(0x77eec4968b08, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({tv_sec=1536281272, tv_usec=374010}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=750580684}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=750636687}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=750692549}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=9668, tv_nsec=750749224}) = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}, {fd=33, events=POLLIN}, {fd=53, events=POLLIN}, {fd=71, events=POLLIN}], 6, 0) = 1 ([{fd=33, revents=POLLIN}])

strace -c after about 5 seconds:

user@host:~$ ps -A | grep firefox
 1236 ?        03:58:59 firefox.real
user@host:~$ sudo strace -cp 1236
strace: Process 1236 attached
^Cstrace: Process 1236 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0      2285           read
  0.00    0.000000           0      2281           write
  0.00    0.000000           0      4567           poll
  0.00    0.000000           0      4536           ioctl
  0.00    0.000000           0      2268           recvfrom
  0.00    0.000000           0      4568      4567 recvmsg
  0.00    0.000000           0      4578           gettimeofday
  0.00    0.000000           0      2296           futex
  0.00    0.000000           0     25513           clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                 52892      4567 total

Patrick · September 7, 2018, 5:09am

Could you try please if you can reproduce this without Tor Browser being involved at all?

tatertot · September 7, 2018, 6:33am

Meaning, try to reproduce using Firefox 60.2.0esr on whonix-ws-14?

Patrick · September 7, 2018, 3:20pm

tatertot:

Patrick:

Could you try please if you can reproduce this without Tor Browser being involved at all?

Meaning, try to reproduce using Firefox 60.2.0esr on whonix-ws-14?

Can do.

But I meant just suspend without anything. Could be sclockadj issue.
That’s why.

To check if sclockadj is running.

ps aux | grep sclockadj

tatertot · September 8, 2018, 6:05am

sclockadj (installed at /usr/lib/sdwdate/sclockadj) doesn’t appear in ps.

whonix-installed torbrowser-8.0 on whonix-ws-14 - affected
manually-installed torbrowser-8.0 on debian stretch - can’t reproduce
firefox-60.2.0esr on whonix-ws-14 - can’t reproduce

Patrick · September 8, 2018, 9:10am

Can you reproduce this issue while sclockadj does not appear in ps?

tatertot · September 8, 2018, 5:18pm

Yes. Actually, I’ve never seen sclockadj appear in ps, even though it is installed at /usr/lib/sdwdate/sclockadj

Patrick · September 8, 2018, 5:41pm

This one?

A nine years unresolved old bug in Firefox but that doesn’t explain why it gets triggered in Whonix only.

0brand · September 19, 2018, 11:28pm

Having problems with the same bug on my system. Have this issue when clockadj is running and when it is not. This bug was triggered at VM start so not sure of the reason why this would start all of a sudden

0brand · September 20, 2018, 10:12am

This bug seems to only affect my disp-anon-whonix VMs that use a sys-whonix (based on Template Tor Versioning) as netvm?

When firfox.real CPU starts to spike I switch NetVM to a non-sys-whonix Tor Version VM and the problem is gone. It may have nothing to do with the NetVM that is used. Problem may subside just because NetVM is changed. Or maybe just by coincident.

Note: No problems with any anon-whonix VM that use default sys-whonix VMs as NetVM.

0brand · September 21, 2018, 8:57pm

Was searching though Tor trac for High CPU bug reports and came across this older one which was solved by using about:config to toggle extensions.torbutton.versioncheck_enabled to false. Although its a different bug, the solution works for me.

https://trac.torproject.org/projects/tor/ticket/8560

tatertot · September 23, 2018, 5:36pm

Unfortunately it didn’t work for me : (.

unmkwa · October 25, 2018, 12:33pm

Same problem to me after update. 70-80% CPU usage.
extensions.torbutton.versioncheck_enabled to false don’t help

0brand · March 8, 2019, 11:04pm

Having the same issue with different hardware. Running top shows CPU and MEM spike about 20-30 seconds after Tor Browser is started. The spike would be consistent with what I might expect to see when first browsing to a new web page, CPU 90-120% and MEM 30-35%. Like my previous post I was able to fix the issue by typing about:config in the address bar then toggle extensions.torbutton.versioncheck_enabled to false.

It takes about 45 minutes before my laptop starts getting to hot and my fans kick in before I would even know there is an issue so it would not surprise me if more users are having this issue but are not aware of it.

0brand · March 11, 2019, 11:45pm

I believe I found the reason that setting extensions.torbutton.versioncheck_enabled to false works for me and no one else. I use a custom script to update my VMs so I always disable qubes-update-check in my VMs since it is not needed. Disabling both qubes-update-check (in sys-whonix) and torbutton.versioncheck (in anon-whonix) is required to prevent high cup in Tor Browser. I’ve tested this quite extensively with newly created sys-whonix and anon-whonix VMs.

Where to submit a bug report? Would this be a Qubes specific issue?

To fix this issue:

Disable qubes-update-check in sys-whonix.

In a dom0 terminal, run.

qvm-service -d sys-whonix qubes-update-check
Disble torbutton.versioncheck in anon-whonix Tor Browser.

In dom0 terminal, run Tor Browser.

qvm-run anon-whonix torbrowser

Next, type about:config in Tor Browser address bar.

Then type extensions.torbutton.versioncheck_enabled in the search bar and “toggle” to false.

Patrick · March 12, 2019, 6:15am

Good thought. Perhaps try change from one sys-whonix to another sys-whonix2?

Good question, next question.

This is a very difficult case.

Since “Disable qubes-update-check in sys-whonix .” is part of the workaround, it could be a Qubes specific issue. But something qubes-update-check does could just be the trigger and it could be a bug in Tor Browser or Firefox.

Commented on 100% CPU usage in Tor Browser? (#8560) · Issues · Legacy / Trac · GitLab. Please join if useful.

0brand · March 12, 2019, 10:00pm

I might have found something easier. Killing firefox.real in the anon-whonix VM, then restarting Tor Browser can be used as a workaround for that particular session. When this is done the %cpu and %mem are normilized. If using a DispVM users can (1) start a konsole (2) start Tor Browser from the konsole (3)) kill firefox.real (4) start Tor Browser from the konsole. This would allow for killing the process without shutting down the DispVM.

Note: I would suspect killing Tor Browser in the konsole (press Ctrl + C ) would work instead of killing firefox.real. I will find out when I start testing again.

Its odd that changes in both sys-whonix and anon-whonix are needed for a persistent workaround. I wouldn’t be surprised if there was something else that was responsible for this behavior (Tor Browser related)

I haven’t been able to reproduce this in Debian Tor Browser but myabe the right conditions need to be set. I’ll keep going with this and maybe I"ll get lucky. Otherwise it might be best that i not comment on this issue since I might unintentionally say something to get this labeled a Qubes-Whonix bug.

0brand · March 31, 2019, 5:29pm

I might have found what is triggering this in Qubes-Whonix. During testing I started trying to isolate the issue and I come across something interesting. I no longer have problems with high cpu when I remove sys-corridor from my setup. This means that even with both qubes-update-check enabled and extensions.torbutton.versioncheck_enabled = true I had no high cup issues.

If you recall corridor was not functional for a time in Debian 9. These problems did not start until right after corridor was fixed.

Corridor was fixed by rustybird for Debian 9 in the beginning of December 2019 (https://github.com/rustybird/corridor). This correlates with the time users started having issues with high cpu. (if I go by the time this problem was reported by tatertot)

Could anyone that experienced this problem please confirm that they use corridor in their setup. Then try testing without sys-corridor as Netvm for sys-whonix

Note: This problem is caused by an underlying issue with Tor Browser. Its possible there could be multiple triggers that can cause this high CPU issues.

awokd · March 31, 2019, 5:45pm

I might have found what is triggering this in Qubes-Whonix. During testing I started trying to isolate the issue and I come across something interesting. I no longer have problems with high cpu when I remove sys-corridor from my setup. This means that even with both qubes-update-check enabled and extensions.torbutton.versioncheck_enabled = true I had no high cup issues.

I’m not using sys-corridor but have experienced that high CPU often.
Might be one of those other causes, like you said.

tatertot · April 6, 2019, 5:54pm

I’ve tested disabling both and the issue still occurs.

Never used corridor.

Quitting and relaunching torbrowser also temporarily fixes it.

Speaking about the issue in general, I think this issue is under-reported because:

torbrowser remains responsive (not a hard freeze)
per-VM CPU usage is not displayed in qubes manager in Qubes 4.0

Unless you have per-VM CPU monitoring (e.g. xentop), it is not immediately obvious you are suffering from this issue.