845677 - high number of events /s reported by powertop when idle

Status: UNCONFIRMED

(Core :: Performance: General, defect)

Description

[Matthieu Patou]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:19.0) Gecko/20100101 Firefox/19.0
Build ID: 20130218103317

Steps to reproduce:

Start firefox with new profile, open search google.com for hackers news daily.

Wait for the result to appear, do nothing else


Actual results:

In powertop 2.0 I see ~250 events per seconds causing the CPU not to be able to go in deep power saving.


Expected results:

A very low number of events per second.

Comment 1

[Matthieu Patou]

I think there is a couple of problems, if I strace firefox I have this pattern that keeps repeating, even when my only tab is hacker news daily (http://www.daemonology.net/hn-daily/) which is a static web page.



poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, events=POLLIN}, {fd=30, events=POLLIN}, {fd=13, events=POLLIN|POLLPRI}], 9, 0) = 0 (Timeout)
read(4, 0x7fffcd88f740, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fed52de4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, events=POLLIN}, {fd=30, events=POLLIN}, {fd=13, events=POLLIN|POLLPRI}], 9, 0) = 0 (Timeout)
read(4, 0x7fffcd88f740, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fed52de4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, events=POLLIN}, {fd=30, events=POLLIN}, {fd=13, events=POLLIN|POLLPRI}], 9, 0) = 0 (Timeout)
read(4, 0x7fffcd88f740, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fed52de4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)

First I'm a bit surprised that firefox is not leveraging the epoll capabilities of Linux, but maybe for a limited set of FDs it's not so important. Next thing is why there is a 0 timeout, as it means basically no timeout. Also it seems that the result of poll is not checked because if poll returns because of a timeout there is no need to read from fd 4 and fd 7 as they don't have any data (otherwise poll would have returned something else).

This could be seen in the new_profile file attached to this report.

When the open page is google.com on the result page the previous pattern is present but there is also 2 threads that seems to be active and the main thread keeps on receiving data from another thread:

futex(0x7fb024073fcc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb024073fc8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
read(27, "\372", 1)                     = 1                                     
futex(0x7fb024073fcc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb024073fc8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, 0x7fb0323e4074, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, even#
read(4, 0x7fff3db11810, 16)             = -1 EAGAIN (Resource temporarily unavailable)
read(27, "\372", 1)  
^^^^^^^ 
FD 27 is the read fd from the pipe with the other thread as we can see:

pipe([27, 28])                          = 0                                     
fcntl(27, F_GETFL)                      = 0 (flags O_RDONLY)                    
fcntl(27, F_SETFL, O_RDONLY|O_NONBLOCK) = 0                                     
fcntl(28, F_GETFL)                      = 0x1 (flags O_WRONLY)                  
fcntl(28, F_SETFL, O_WRONLY|O_NONBLOCK) = 0                                     
fstat(27, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0                           
fcntl(27, F_GETFL)                      = 0x800 (flags O_RDONLY|O_NONBLOCK)     
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8                                     
sched_get_priority_min(SCHED_OTHER)     = 0                                     
sched_get_priority_max(SCHED_OTHER)     = 0                                     
mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb01b061000
mprotect(0x7fb01b061000, 4096, PROT_NONE) = 0                                   
sched_get_priority_min(SCHED_OTHER)     = 0                                     
sched_get_priority_max(SCHED_OTHER)     = 0                                     
clone(child_stack=0x7fb01b860fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETT

Comment 2

[Matthieu Patou]

Attachment: strace on http://www.daemonology.net/hn-daily/

Comment 3

[Matthieu Patou]

Attachment: strace on the result page for google.com

Comment 4

[Virgil Dicu [:virgil] [QA]]

Similar to bug 407325, you may want to check that bug as well. I'll move this to Core:General - lacking a better component.

Comment 5

[holgbert]

Build ID: 20170928135459
User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:56.0) Gecko/20100101 Firefox/56.0

I can confirm this and I have an observation about triggering this:

After startup and a few seconds of settling, I get ~10-20 wakeups/s on an empty or static page.
High wakeups ~120/s are triggered by input in url-bar or search-bar and persist until restart. 
Matching behaviour can be observed via strace or powertop.
When browsing without using the url/search bar, ff settles down to the low value after a few seconds.
So this does not seem to be a tab issue.

Steps to reproduce:
 Open firefox with a restored session to allow loading pages without using search/url bar.
    low W/s
 activate more tabs, let it settle for a few seconds
    low W/s
 input 1 character in search bar or URL bar
    persistent high W/s

Comment 6

[Frederik Braun [:freddy]]

I think this needs to be re-triaged by someone in the performance team.

Comment 7

[Greg Mierzwinski [:sparky]]

The Performance Impact Calculator has determined this bug's performance impact to be low. If you'd like to request re-triage, you can reset the Performance Impact flag to "?" or needinfo the triage sheriff.

Resource impact: Some
[x] Bug affects multiple sites
[x] Multiple reporters