1183361 - After days working, FirefoxOS go really slow

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Performance, defect)

Description

[Guillermo Movia [:deimidis]]

Attachment: dev-log-main.log

After almost one week without restarting th e phone, Firefox OS begun to work really slow. Before restarting I generate these logs files (restarting solve the issue).

Comment 1

[Guillermo Movia [:deimidis]]

Attachment: dev-log-radio.log

Comment 2

[Guillermo Movia [:deimidis]]

Attachment: dev-log-system.log

Comment 3

[Guillermo Movia [:deimidis]]

Attachment: proc-cmdline.log

Comment 4

[Guillermo Movia [:deimidis]]

Attachment: proc-kmsg.log

Comment 5

[Guillermo Movia [:deimidis]]

Attachment: proc-meminfo.log

Comment 6

[Guillermo Movia [:deimidis]]

Attachment: proc-uptime.log

Comment 7

[Guillermo Movia [:deimidis]]

Attachment: proc-version.log

Comment 8

[Guillermo Movia [:deimidis]]

Attachment: proc-vmallocinfo.log

Comment 9

[Guillermo Movia [:deimidis]]

Attachment: properties.log

Comment 10

[Guillermo Movia [:deimidis]]

Attachment: proc-vmstat.log

Comment 11

[Guillermo Movia [:deimidis]]

Attachment: system-b2g-application.ini

Comment 12

[Māris Fogels [:mars] (please needinfo)]

I've encountered the same issue.  After 2 weeks of use the device got really slow.  After closing all applications the phone still suffers from a 500-900ms lag when using the touchscreen.  The lockscreen and call answer sliders don't animate any more, and the lag makes answering inbound calls impossible.

Comment 13

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

about:memory reports would be helpful here.

Comment 14

[Michael Henretty [:mikehenrty][:mhenretty]]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #13)
> about:memory reports would be helpful here.

Yes please. Here is how you collect that data:
https://developer.mozilla.org/en-US/Firefox_OS/Debugging/Debugging_OOMs#Step_2.3A_Collect_memory_reports

Comment 15

[Māris Fogels [:mars] (please needinfo)]

Link to about-memory-0.zip from my foxfood device suffering from lag: https://app.box.com/s/i67x2qlliihcddne3frqnout9508iyj5

Comment 16

[Guillermo Movia [:deimidis]]

(In reply to Michael Henretty [:mhenretty] from comment #14)
> (In reply to Kyle Huey [:khuey] ([e-mail]) from comment #13)
> > about:memory reports would be helpful here.
> 
> Yes please. Here is how you collect that data:
> https://developer.mozilla.org/en-US/Firefox_OS/Debugging/
> Debugging_OOMs#Step_2.3A_Collect_memory_reports

Silly question, step 2 mention git repository, but it's not clear to me which one should I have to clone.

Comment 17

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to Māris Fogels [:mars] from comment #15)
> Link to about-memory-0.zip from my foxfood device suffering from lag:
> https://app.box.com/s/i67x2qlliihcddne3frqnout9508iyj5

Thanks.  The system app is leaking a ton of nodes, which are likely slowing GC/CCs.  I'll file some bugs.

Comment 18

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #17)
> (In reply to Māris Fogels [:mars] from comment #15)
> > Link to about-memory-0.zip from my foxfood device suffering from lag:
> > https://app.box.com/s/i67x2qlliihcddne3frqnout9508iyj5
> 
> Thanks.  The system app is leaking a ton of nodes, which are likely slowing
> GC/CCs.  I'll file some bugs.

I filed bug 1183848 on the most obvious leak.  There may be other things hidden by that, but we'll have to fix it first to see.

Comment 19

[Michael Henretty [:mikehenrty][:mhenretty]]

(In reply to Guillermo Movia [:deimidis] from comment #16)
> (In reply to Michael Henretty [:mhenretty] from comment #14)
> > (In reply to Kyle Huey [:khuey] ([e-mail]) from comment #13)
> > > about:memory reports would be helpful here.
> > 
> > Yes please. Here is how you collect that data:
> > https://developer.mozilla.org/en-US/Firefox_OS/Debugging/
> > Debugging_OOMs#Step_2.3A_Collect_memory_reports
> 
> Silly question, step 2 mention git repository, but it's not clear to me
> which one should I have to clone.

https://github.com/mozilla-b2g/B2G

Comment 20

[Māris Fogels [:mars] (please needinfo)]

The lag has returned on my foxfood device.  Here's the about:memory snapshot: https://app.box.com/s/liiblsaddol1lfusaf2d2qpsq9zvnho0

All apps are closed.  I see 5000ms of lag between finishing my PIN on the lockscreen to the homescreen appearing.  There is noticeable lag using the device for regular stuff.

/proc/uptime says it's been 14 days since I restarted the phone.

Comment 21

[[:fabrice] Fabrice Desré]

Looks like we fail to remove observers and pref listeners:

6,623 (100.0%) -- observer-service-suspect
├──1,183 (17.86%) ── referent(topic=volume-state-changed)
├──1,182 (17.85%) ── referent(topic=file-watcher-update)
├──1,178 (17.79%) ── referent(topic=disk-space-watcher)
├────678 (10.24%) ── referent(topic=copypaste-docommand)
├────627 (09.47%) ── referent(topic=ask-children-to-execute-copypaste-command)
├────600 (09.06%) ── referent(topic=audio-channel-process-changed)
├────493 (07.44%) ── referent(topic=inner-window-destroyed)
├────273 (04.12%) ── referent(topic=activity-closed)
├────273 (04.12%) ── referent(topic=activity-opened)
└────136 (02.05%) ── referent(topic=xpcom-shutdown)


1,173 (100.0%) -- preference-service-suspect
└──1,173 (100.0%) ── referent(pref=device.storage.writable.name)

Comment 22

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

11,082 (100.0%) -- dom-media-stream-urls
├──11,081 (99.99%) ++ owner(app://system.gaiamobile.org/index.html)

Also

71,248 (100.0%) -- message-manager
└──71,248 (100.0%) -- referent
   ├──71,005 (99.66%) -- child-process-manager
   │  ├──71,005 (99.66%) ── strong

Comment 23

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Although there are other issues here, I suspect that bug 1204426 is the primary cause of the performance problems you are seeing.  Because we are leaking objects we are doing approximately 9000 (sadly not over) times the work we should be every time the settings API is used on the device.  That's likely to have a considerable negative impact on the performance of the device.

Thanks for the logs, this was quite helpful.  I'll try to file bugs on a few other issues I saw.

Comment 24

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to [:fabrice] Fabrice Desré from comment #21)
> Looks like we fail to remove observers and pref listeners:
> 
> 6,623 (100.0%) -- observer-service-suspect
> ├──1,183 (17.86%) ── referent(topic=volume-state-changed)
> ├──1,182 (17.85%) ── referent(topic=file-watcher-update)
> ├──1,178 (17.79%) ── referent(topic=disk-space-watcher)
> ├────678 (10.24%) ── referent(topic=copypaste-docommand)
> ├────627 (09.47%) ──
> referent(topic=ask-children-to-execute-copypaste-command)
> ├────600 (09.06%) ── referent(topic=audio-channel-process-changed)
> ├────493 (07.44%) ── referent(topic=inner-window-destroyed)
> ├────273 (04.12%) ── referent(topic=activity-closed)
> ├────273 (04.12%) ── referent(topic=activity-opened)
> └────136 (02.05%) ── referent(topic=xpcom-shutdown)
> 
> 
> 1,173 (100.0%) -- preference-service-suspect
> └──1,173 (100.0%) ── referent(pref=device.storage.writable.name)

All of the ones above 1000 are DeviceStorage, which is leaky by design :(

Comment 25

[:gerard-majax]

We fixed several leaks in Gaia for content settings listener leaking since the first report, and we have new leaks that landed recently and that are not fixed yet. Also "observer-service-suspect" is not the Settings API.

Comment 26

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #25)
> We fixed several leaks in Gaia for content settings listener leaking since
> the first report, and we have new leaks that landed recently and that are
> not fixed yet. Also "observer-service-suspect" is not the Settings API.

That being said, bug 1204426 seems like a legit one. I just don't think it explain the whole slowdown, given my experience is that most of it would come from system app's level leaking: each time my device got that slow (and I experienced the 5 secs report), fixing system app leaks would make it compltely disappear after more than a week of uptime when the device got unusable before after four days.

Comment 27

[:gerard-majax]

With the latest FOTA being released, all those issues should have been killed: my dogfooding experience shows that I can keep my device up for more than 7 days without anymore slowdown. Please reopen with about:memory (logshake produces it) if you still hit that after applying the latest FOTA. That FOTA might contain bug 1212759 but that is easy to check: killing Calendar app should get back to faster device.