According to the Raptor dashboard, there has been a 2MiB memory increase (RSS, PSS, and USS) after launching the messages/sms app: http://raptor.mozilla.org/#/dashboard/script/apps-memory.js?device=flame-kk&branch=master&memory=319&panelId=8&fullscreen Consistent on the flame with the 1GB configuration also: http://raptor.mozilla.org/#/dashboard/script/apps-memory.js?device=flame-kk&branch=master&memory=1024&panelId=8&fullscreen I don't know for certain but this might be the patch that caused the increase, as this is the gaia version that shows the increase on the Raptor dashboard: https://github.com/mozilla-b2g/gaia/commit/7afe8bd5d34b70a0 Perhaps this increase is expected and acceptable because of the NGA, but thought I should flag it to be sure.

Thanks, In this patch we add both a SharedWorker and an iframe, so I think this is the cause. My expectation is that we'll go down once we use split views though :) fingers crossed. I don't know if we should leave this bug open.

This is a valid bug since we have a no regression policy. If the split views don't work out we have to fix this in another way.

I'll take a look if we can improve that.

Let's profile.

Some intermediate profiling results: * Gecko v2.2, Gaia v2.2 (build id 20151007032507, gaia commit 885647d92208fb67574ced44004ab2f29d23cb45), light workload, raptor v1.4.4 | Metric | Mean | Median | Min | Max | StdDev | p95 | | ----------------------| -------- | -------- | -------- | -------- | ------ | -------- | | navigationLoaded | 900.850 | 905.500 | 846.000 | 938.000 | 26.889 | 937.000 | | willRenderThreads | 937.350 | 941.500 | 876.000 | 971.000 | 27.242 | 970.500 | | navigationInteractive | 941.300 | 946.000 | 878.000 | 975.000 | 27.271 | 974.500 | | visuallyLoaded | 1247.150 | 1253.500 | 1159.000 | 1286.000 | 29.576 | 1282.500 | | contentInteractive | 1722.950 | 1733.500 | 1611.000 | 1779.000 | 38.803 | 1774.500 | | objectsInitEnd | 1827.750 | 1842.500 | 1714.000 | 1890.000 | 39.903 | 1886.000 | | fullyLoaded | 2979.150 | 2950.000 | 2834.000 | 3149.000 | 96.605 | 3132.000 | | uss | 16.670 | 16.800 | 16.300 | 16.900 | 0.217 | 16.900 | | pss | 20.480 | 20.600 | 20.200 | 20.700 | 0.214 | 20.700 | | rss | 34.355 | 34.500 | 34.000 | 34.600 | 0.227 | 34.600 | * Gecko v2.5, Gaia v2.5 (build id 20151007150205, gaia commit 4973f57cd8f9a62a95f783a24eac32da2bde99fc), light workload, raptor v2.0.3 | Metric | Mean | Median | Min | Max | StdDev | p95 | | --------------------- | -------- | -------- | ------ | ------ | ------ | -------- | | navigationLoaded | 1006.750 | 992.500 | 964 | 1116 | 41.464 | 1115.500 | | willRenderThreads | 1059 | 1047.500 | 1010 | 1167 | 41.140 | 1165.500 | | navigationInteractive | 1062.850 | 1052.500 | 1013 | 1170 | 41.041 | 1168 | | visuallyLoaded | 1608.500 | 1608 | 1566 | 1671 | 30.735 | 1662.500 | | contentInteractive | 2286 | 2281.500 | 2233 | 2377 | 35.957 | 2358.500 | | objectsInitEnd | 2326.250 | 2329 | 2268 | 2426 | 38.202 | 2406.500 | | fullyLoaded | 3808.850 | 3802.500 | 3701 | 3951 | 63.823 | 3944.500 | | uss | 19.362 | 19.201 | 18.766 | 20.289 | 0.388 | 20.133 | | pss | 23.862 | 23.701 | 23.240 | 24.819 | 0.406 | 24.645 | | rss | 39.786 | 39.625 | 39.188 | 40.727 | 0.390 | 40.563 | * Gecko v2.5, Gaia v2.5 (build id 20151007150205, gaia commit 4973f57cd8f9a62a95f783a24eac32da2bde99fc, Messages app from v2.2 885647d92208fb67574ced44004ab2f29d23cb45), light workload, raptor v2.0.3 | Metric | Mean | Median | Min | Max | StdDev | p95 | | --------------------- | -------- | -------- | ------ | ------ | ------ | -------- | | navigationLoaded | 903.900 | 901.500 | 800 | 970 | 32.531 | 958 | | willRenderThreads | 940.800 | 938 | 833 | 1006 | 33.390 | 992.500 | | navigationInteractive | 943.900 | 941.500 | 835 | 1009 | 33.402 | 995.500 | | visuallyLoaded | 1277.150 | 1274.500 | 1203 | 1339 | 29.081 | 1330 | | contentInteractive | 1751.600 | 1752 | 1702 | 1793 | 26.255 | 1792 | | objectsInitEnd | 1793.850 | 1797 | 1734 | 1838 | 29.071 | 1836 | | fullyLoaded | 3243.250 | 3243 | 3107 | 3367 | 51.901 | 3346.500 | | uss | 18.910 | 18.863 | 18.777 | 19.941 | 0.240 | 19.429 | | pss | 23.106 | 23.053 | 22.974 | 24.152 | 0.243 | 23.633 | | rss | 38.675 | 38.619 | 38.543 | 39.719 | 0.243 | 39.201 | * Gecko v2.2, Gaia v2.5 - doesn't work due Gecko v2.2 vs Gecko v2.5 compatibility issues (Intl api and etc.) * Gecko v2.5, Gaia v2.2 - doesn't work, Homescreen is empty. The last raptor data is the most confusing, memory usage of Messages v2.2 on Gaia/Gecko v2.5 is almost the same as Messages v2.5. I'm going to measure memory for Messages v2.5 before and after the commit mentioned in comment 0.

Since bug 1212454 is resolved, I've re-measured both v2.2 and master with the latest raptor@3.0.2 to have less variables between results (I've left only memory related numbers): Gecko v2.2, Gaia v2.2 (build id 20151011032503, gaia commit 885647d92208fb67574ced44004ab2f29d23cb45), light workload, raptor v3.0.2 | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------- | --------- | | uss | 16.720 | 16.800 | 16.400 | 16.900 | 0.147 | 16.784 | | pss | 20.575 | 20.600 | 20.200 | 20.700 | 0.141 | 20.637 | | rss | 34.390 | 34.450 | 34.100 | 34.600 | 0.145 | 34.453 | Gecko v2.5, Gaia v2.5 (build id 20151011150208, gaia commit 4560388545ab6743982bdbf1d9b39b1e5b7f6aef), light workload, raptor v3.0.2 | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 19.221 | 19.215 | 18.723 | 20.016 | 0.376 | 19.385 | | pss | 23.751 | 23.745 | 23.259 | 24.562 | 0.374 | 23.914 | | rss | 39.749 | 39.742 | 39.254 | 40.559 | 0.376 | 39.914 | Gecko v2.5, Gaia v2.5 (build id 20151011150208, gaia commit 4560388545ab6743982bdbf1d9b39b1e5b7f6aef), light workload, raptor v3.0.2 - sms v2.2 | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 18.921 | 18.859 | 18.715 | 20 | 0.278 | 19.042 | | pss | 23.142 | 23.078 | 22.948 | 24.236 | 0.281 | 23.265 | | rss | 38.793 | 38.727 | 38.582 | 39.891 | 0.282 | 38.916 | We have the following differences between v2.2 and v2.5 Messages apps running on v2.5 Gecko: USS diff is ~343KB, PSS diff is ~649KB and RSS is ~998KB. We still regressed, even that the difference is not that big. So it looks like we have Gecko/System regression here, I've tried to bisect using various builds starting from April, and could not find any _noticable single_ spike. It looks like our memory numbers were slowly growing. Not sure what we can do here, we should observe the same pattern in other apps, still not the same for all since other apps could improve their own memory consumption that can mask Gecko regression. Anyway, I went ahead and measured Messages app before and after patch that introduced both iframes and Shared Worker: Gecko v2.5, Gaia v2.5 (build id 20151011150208, gaia commit 84fc50c0b4da86de68ed82022b5f05c9968da0e5 - last commit before we've added SharedWorker and iframe) | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 17.848 | 17.799 | 17.754 | 18.797 | 0.219 | 17.944 | | pss | 22.292 | 22.248 | 22.196 | 23.259 | 0.223 | 22.390 | | rss | 38.202 | 38.151 | 38.105 | 39.160 | 0.221 | 38.298 | Gecko v2.5, Gaia v2.5 (build id 20151011150208, gaia commit c1e8a086db920e703500c6b887f7fac2f0475ed8 - first commit with SharedWorker and iframe) | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 19.001 | 18.977 | 18.887 | 19.309 | 0.106 | 19.047 | | pss | 23.542 | 23.517 | 23.412 | 23.796 | 0.098 | 23.585 | | rss | 39.534 | 39.517 | 39.426 | 39.723 | 0.082 | 39.569 | So yeah, we see ~1MB regression for all memory related metrics. Let's leave iframe, but comment SharedWorker out: Gecko v2.5, Gaia v2.5 (build id 20151011150208, gaia commit c1e8a086db920e703500c6b887f7fac2f0475ed8 - first commit with iframe, without SharedWorker) | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------- | --------- | | uss | 18.065 | 18.088 | 17.699 | 18.125 | 0.088 | 18.104 | | pss | 22.527 | 22.543 | 22.182 | 22.595 | 0.084 | 22.564 | | rss | 38.436 | 38.451 | 38.090 | 38.500 | 0.083 | 38.472 | Good, looks like Shared Worker is the main memory consumer here :) I'm not sure if it's expected, let's ask Ben. What we can do here: * we can create SharedWorker inside MessagingClient only when any of its method is called, but it doesn't sound like something that can bring value in real life - user will eventually send message and memory will grow anyway; * partially back out Shared Worker/iframe code - we'll win ~1MB max, but is this win a big one? ni? you guys to get your opinion on that.

Hey Ben, I'm not sure if it's under your umbrella, but you'll definitelly know :) We see that Shared Worker increases our memory numbers and obviously it's expected. But we're not sure about exact values that considered as reasonable. I've tried to create very basic reduced test case [1] and measured memory with raptor (20 runs) for the case when we don't create Shared Worker and when we create it (with basically empty Shared Worker file, see [1]). Here are results: Baseline - we don't create Shared Worker here. | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | ----------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 8.784 | 8.781 | 8.715 | 8.922 | 0.045 | 8.803 | | pss | 12.143 | 12.139 | 12.044 | 12.299 | 0.052 | 12.165 | | rss | 26.183 | 26.182 | 26.102 | 26.332 | 0.049 | 26.205 | Here we have Shared Worker | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | ----------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 9.426 | 9.402 | 9.363 | 9.602 | 0.064 | 9.455 | | pss | 12.927 | 12.907 | 12.854 | 13.115 | 0.068 | 12.957 | | rss | 27.206 | 27.184 | 27.145 | 27.379 | 0.064 | 27.234 | So here we see the following change: +652KB in USS, +792 in PSS and +1069 in RSS. Are these numbers expected or they should have been smaller? Thanks! [1] https://github.com/nga-crash-tests/shared-worker-memory

I would not expect adding an empty SharedWorker to create a 1MB hit to RSS. Kyle, do you have any time to look at this?

I would need before and after about:memory dumps to look at.

You could also see if the regression goes away prior to bug 1188545 landing. I think that might have touched some of the infrastructure for shared workers.

(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #9) > I would need before and after about:memory dumps to look at. Hey Kyle, please see memory dumps at [1]. It's on b2g so I've included entire output from [2] tool to be on the safe side :) (In reply to Ben Kelly [:bkelly] from comment #10) > You could also see if the regression goes away prior to bug 1188545 landing. > I think that might have touched some of the infrastructure for shared > workers. Thanks, will try this as well. [1] https://github.com/nga-crash-tests/shared-worker-memory/tree/master/about:memory [2] https://github.com/mozilla-b2g/B2G/blob/master/tools/get_about_memory.py

> ni? you guys to get your opinion on that. Is it possible to have some code that will enable/disable the workers depending on a setting we'll have in the Settings object ? Or is it too much work ?

(In reply to Julien Wajsberg [:julienw] from comment #12) > > ni? you guys to get your opinion on that. > > Is it possible to have some code that will enable/disable the workers > depending on a setting we'll have in the Settings object ? Or is it too much > work ? It seems not very difficult to do, I'm going to sketch something out today.

So I've tried build (build id is 20150929150202) almost right before PR for bug 1188545 is landed. So the diff between baseline and the version with shared worker is the same, though Gecko was a memory hog comparing to the current one :) Baseline - we don't create Shared Worker here. | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | ----------- | -------- | ------ | ------ | ------ | ------ | --------- | | uss | 14.803 | 14.803 | 14.777 | 14.871 | 0.017 | 14.809 | | pss | 19.181 | 19.181 | 19.153 | 19.251 | 0.017 | 19.187 | | rss | 35.413 | 35.410 | 35.383 | 35.484 | 0.017 | 35.419 | Here we have Shared Worker | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | ----------- | -------- | ------ | ------ | ------ | ------- | --------- | | uss | 15.444 | 15.449 | 15.383 | 15.500 | 0.024 | 15.453 | | pss | 19.922 | 19.928 | 19.861 | 19.979 | 0.024 | 19.931 | | rss | 36.333 | 36.336 | 36.273 | 36.391 | 0.025 | 36.342 |

Comment on attachment 8673524 [details] Github pull request(optional SharedWorker, WIP) Well, here is just draft of what we can do to optionally switch SharedWorker on and off, doesn't require much work, code becomes a bit more messy, but we can have something like ServiceManager from bug 1198266 that hides all these switching stuff inside. Gecko v2.5, Gaia v2.5 (build id 20151013150203, gaia commit a9ee136440a7d57c3d47ef1587e72be8e9136074) | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 19.229 | 19.195 | 18.773 | 19.938 | 0.318 | 19.368 | | pss | 23.771 | 23.727 | 23.319 | 24.485 | 0.319 | 23.911 | | rss | 39.780 | 39.740 | 39.320 | 40.492 | 0.321 | 39.920 | Gecko v2.5, Gaia v2.5 (build id 20151013150203, gaia commit a9ee136440a7d57c3d47ef1587e72be8e9136074, optional ShW - turned OFF) | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | uss | 18.114 | 18.064 | 18.004 | 18.668 | 0.171 | 18.189 | | pss | 22.579 | 22.532 | 22.447 | 23.152 | 0.178 | 22.656 | | rss | 38.505 | 38.451 | 38.391 | 39.078 | 0.176 | 38.582 | Memory numbers are basically even better than Messages v2.2 on Gecko v2.5, but still far from Gecko v2.2 :) How does it look?

Hey Ting-Yu, You said we can bother you with any performance related questions :) So can you please help us to find someone who can look at b2g about:memory reports (for Messages app specifically)? The thing that mostly bothers us is that Messages v2.2 on master Gecko consumes more memory than Messages v2.2 on Gecko v2.2 (attachment 8673814 [details] and attachment 8673812 [details]) - so it seems like a Gecko regression. I've tried to do it by myself, but it's quite difficult to say what is going on without proper experience, I see +1MB in "js-non-window -> runtime", +0.6MB in "heap-overhead" and some other increased numbers in "js-non-window". Thanks!

I am lack of experience in reading js heap report :( :njn, I read the page on MDN [1], but it explains only js-non-window, would you explain us a bit what are "js-non-window -> runtime" and "heap-overhead", or let us know if there're other documents? Thank you. [1] https://developer.mozilla.org/en-US/docs/Mozilla/Performance/about%3Amemory

I can take a look. Which memory reports file should I look at? Or should I diff two files?

Should be the two attachments in comment 20.

Thanks Ting-Yu and Nicholas (ni? Nicholas once again so that it doesn't fall off his radar)! > I can take a look. Which memory reports file should I look at? Or should I diff two files? Yeah, the diff between two attachments from comment 20 is most interesting (same app, but two different Gecko v2.2 and master). Please let me know if you need the rest of information generated by [1] (b2g-info, b2g-procrank, kgsl-b2g-mem, gc-edges.xxx.log.gz and cc-edges.xxx.log.gz). [1] https://github.com/mozilla-b2g/B2G/blob/master/tools/get_about_memory.py

If we can not fix the worker regression in platform wise, I would say that we should running the services within main window context for 2.5. Delaying the worker initialization didn't solve the problem just like you said, and back out the service is not an easy task either.

Also wanted to note that our brand new SharedWorker based service doesn't look like the main reason of memory regression, in v2.2 we had SharedWorker as well and replaced it with BroadcastChannel in v2.5. So we basically swapped one SharedWorker with another, but it's still good to know if SharedWorker can consume less memory.

Don't we have several shared workers currently? I can see 2 of them in the code, but not sure if they're used already.

(In reply to Julien Wajsberg [:julienw] from comment #27) > Don't we have several shared workers currently? I can see 2 of them in the > code, but not sure if they're used already. We don't use ConversationClient (the one that creates "second" SharedWorker) in master yet.

Comment on attachment 8673524 [details] Github pull request(optional SharedWorker, WIP) yeah, I think we can do that. But please measure the impact on the launch time as well. Also I'd like a product decision on whether 1MB saving is a big deal. Francisco, maybe you can help finding this information ? If it was me, I'd say we should ignore this. However, finding why gecko takes more memory is more important. (and maybe this is because of something we do in the app too.)

This is what I see for the Messages app when comparing the two attachments from comment 20: > 3.81 MB (100.0%) -- explicit > ├──1.74 MB (45.57%) ++ js-non-window > │ ├──1.01 MB (26.40%) -- runtime > │ │ ├──0.65 MB (17.15%) ++ script-sources > │ │ ├──0.54 MB (14.20%) ── uncompressed-source-cache > │ │ ├──-0.28 MB (-7.43%) ++ gc > │ │ ├──0.12 MB (03.25%) ── script-data > │ │ ├──0.06 MB (01.64%) ++ code > │ │ ├──-0.10 MB (-2.67%) ── temporary > │ │ └──0.01 MB (00.26%) ++ (5 tiny) > ├──0.97 MB (25.56%) ++ heap-overhead > ├──0.64 MB (16.70%) ── heap-unclassified > ├──0.40 MB (10.42%) ++ layout > ├──0.12 MB (03.10%) ++ images/content/raster/used > ├──-0.25 MB (-6.66%) ++ window-objects/top(app://sms.gaiamobile.org/index.html, id=NNN) > ├──0.07 MB (01.87%) ++ gfx > ├──-0.07 MB (-1.90%) ++ workers/workers(gaiamobile.org)/worker(js/iac/shared_worker.js, 0xNNN) > ├──0.06 MB (01.70%) ── freetype > ├──0.06 MB (01.57%) ++ xpcom > ├──0.05 MB (01.23%) ── script-namespace-manager > └──0.03 MB (00.85%) ++ (7 tiny) The JSRuntime is an internal JS engine data structure that holds various system-wide things. In this case the most significant part is the script-sources and uncompressed-source-cache. This suggests that the new version is just executing more code than the old version, and storing this code takes up space. "heap-overhead" is fragmentation in jemalloc, which we don't have any control over. "heap-unclassified" is memory not covered by memory reporters, which we don't have any insight into. Sorry, I know that's not a lot of extra detail, but it's about as much as I can determine from these files.

I would try to get the solution that allows us to swap code in shared workers or main thread, until we manage to get more information from platform. That won't put us at risk for 2.5 branching. What really worries me is the apparently regression in gecko, we can see similar numbers in contacts, where (even without using shared workers) the memory has increased without adding a lot more of code/functionalities. Anyway, 1MB out of 18MB it's 5.5% increase, how much it's coming from gecko will be the interesting part.

In b2g.js [1] we should discard the sources, so I don't know why we end up with script-sources and uncompressed-source-cache lines. [1] https://dxr.mozilla.org/mozilla-central/source/b2g/app/b2g.js#653

I've added some findings about difference in memory consumption between Gaia v2.2 on Gecko v2.2 and Gaia v2.2 on Gecko v2.5 in bug 1162535 comment 27. Comparing Messages v2.2 on Gecko v2.5 and Messages v2.5 on Gecko v2.5 I see that as Messages app we regressed in the following places [1]: * Our new SharedWorker a bit more (+200KB) expensive than the one we had in v2.2 - it's thicker and uses bridge lib; * Shim iframe introduces +200KB more; * Looks like we have more styles and javascript files so + a few more hundreds of kilobyte. [1] https://drive.google.com/folderview?id=0B_RkmK8mrD-ITGpoSDlxUElyb1E&usp=sharing#list

(In reply to Francisco Jordano [:arcturus] [:francisco] from comment #31) > I would try to get the solution that allows us to swap code in shared > workers or main thread, until we manage to get more information from > platform. Yep, we have fallback plan here, either attachment 8673524 [details] or attachment 8660400 [details]. > > That won't put us at risk for 2.5 branching. > > What really worries me is the apparently regression in gecko, we can see > similar numbers in contacts, where (even without using shared workers) the > memory has increased without adding a lot more of code/functionalities. > > Anyway, 1MB out of 18MB it's 5.5% increase, how much it's coming from gecko > will be the interesting part. Also I hope we'll be able to reduce memory pressure from SharedWorker since we're going to have several (can imagine 3+) of them at the same time in NGA...

ni'ed Kyle in dependency bug 1218811 instead.

[Blocking Requested - why for this release]: To summarize: we can do various over-optimizations on Gaia side, disable some NGA stuff to save up to <1MB in USS, but it's risky and requires effort. At the same time both Gecko bug 1218811 and bug 1219103 are not blockers anymore, so I'd propose to remove blocker status from this bug as well. Anyway we'll continue to look for more areas of _safe_ and _reasonable_ improvements we can make in the meantime.

Comms triage: Based on comment 36, Gecko work is needed and the risk of a Gaia patch is important. Removing the blocking status on 2.5.

Having fix for bug 1219301 locally, I've remeasured memory once again + collected relevant memory dumps - everything is uploaded to [1]. Here is just some excerpt from the data: Base) Gecko@2.2-Gaia@2.2, raptor test coldlaunch --app sms --runs 30 --homescreen verticalhome.gaiamobile.org | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | navigationLoaded | 918.600 | 915 | 836 | 981 | 35.522 | 931.312 | | visuallyLoaded | 1267.133 | 1268 | 1200 | 1322 | 31.082 | 1278.256 | | fullyLoaded | 2916.567 | 2928.500 | 2598 | 3090 | 93.806 | 2950.135 | | uss | 16.707 | 16.500 | 16.300 | 19.600 | 0.586 | 16.917 | | pss | 20.607 | 20.450 | 20.200 | 23.500 | 0.588 | 20.817 | | rss | 34.367 | 34.200 | 34 | 37.200 | 0.566 | 34.569 | 1) Gecko@master-Gaia@2.2, raptor test coldlaunch --app sms --runs 30 --homescreen verticalhome.gaiamobile.org | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | navigationLoaded | 981.333 | 998 | 886 | 1052 | 46.941 | 998.131 | | visuallyLoaded | 1339.233 | 1354 | 1261 | 1412 | 44.813 | 1355.269 | | fullyLoaded | 3109.433 | 3111.500 | 2987 | 3214 | 61.235 | 3131.346 | | uss | 18.819 | 18.645 | 18.453 | 19.938 | 0.473 | 18.988 | | pss | 22.928 | 22.761 | 22.548 | 24.037 | 0.475 | 23.098 | | rss | 38.279 | 38.109 | 37.906 | 39.398 | 0.477 | 38.450 | 2) Gecko@master-Gaia@master, raptor test coldlaunch --app sms --runs 30 | Metric | Mean | Median | Min | Max | StdDev | 95% Bound | | --------------------- | -------- | -------- | ------ | ------ | ------ | --------- | | navigationLoaded | 920.033 | 920.500 | 832 | 1004 | 44.625 | 936.002 | | visuallyLoaded | 1259.500 | 1264 | 1158 | 1350 | 45.708 | 1275.856 | | fullyLoaded | 3429.500 | 3429.500 | 3281 | 3651 | 80.428 | 3458.281 | | uss | 19.296 | 19.176 | 18.629 | 21.070 | 0.649 | 19.528 | | pss | 23.713 | 23.581 | 23.037 | 25.499 | 0.651 | 23.945 | | rss | 39.446 | 39.322 | 38.781 | 41.223 | 0.648 | 39.678 | And Raptor compare results: sms.gaiamobile.org base: mean 1: mean 1: delta 1: p-value 2: mean 2: delta 2: p-value --------------------- ---------- ------- -------- ---------- ------- -------- ---------- navigationLoaded 919 981 63 * 0.00 920 1 0.89 visuallyLoaded 1267 1339 72 * 0.00 1260 -8 0.46 fullyLoaded 2917 3109 193 * 0.00 3430 513 * 0.00 uss 16.707 18.819 2.113 * 0.00 19.296 2.590 * 0.00 pss 20.607 22.928 2.321 * 0.00 23.713 3.106 * 0.00 rss 34.367 38.279 3.912 * 0.00 39.446 5.080 * 0.00 Looks like difference between Base and 1 (2.113 MB) is somewhere in Gecko as full Gaia is exactly the same, difference between 1 and 2 (2.590 - 2.113 = 0.477 MB) explained in comment 33 (some portion of the impact can be decreased in bug 1218091) - it correlates well with what about:memory reports show. Per Eli Raptor forces GC before capturing memory, however waiting 10 additional seconds after fullyLoaded before Raptor captures memory decreases USS for about ~0.3-0.45 MB consistently for both Gecko@2.2 and Gecko@master. Looking at memory reports it's not clear what exactly causes this, I see that "heap-unclassified" and "heap-overhead/bin-unused" is decreased. Also Julien was wondering about memory consumed when app is moved to background, memory consumption is mainly decreased because of the fact that some memory (~1-2 MB) occupied by _images_ is freed (full memory reports at [1]) in this case. [1] https://drive.google.com/open?id=0B_RkmK8mrD-IQ3Z1UnVuOG4xOU0

> Per Eli Raptor forces GC before capturing memory, however waiting 10 additional seconds after fullyLoaded before Raptor captures memory decreases USS for about ~0.3-0.45 MB consistently for both Gecko@2.2 and Gecko@master This is wrong. Can we get Gecko/SpiderMonkey people to look into this? We force GC. There should be no way to get another 0.5mb of garbage collected in the next 10 seconds from that specific app unless we fail at GCing in which case out memory measurements are not stable. That would also help us explain multimodality of memory results that we are getting which prevents us from performing most statistical tests that we should, so maybe the way we perform forced GC sometimes works, and sometimes spidermonkey ignores the request? Or maybe it's an async operation and we don't wait for it to be finished and sometimes measure memory before GC is done?

It is an async operation, but we do wait for it: https://github.com/mozilla-raptor/raptor-cli/blob/master/lib/device/lib/marionette.js#L116 Even though we wait for fullyLoaded in the app, that doesn't necessarily mean that Gecko is done with everything it is doing, so I suppose that could be the source of issues, but it would mean profiling the device and seeing what happens after fullyLoaded.

(In reply to :Eli Perelman from comment #40) > It is an async operation, but we do wait for it: > > https://github.com/mozilla-raptor/raptor-cli/blob/master/lib/device/lib/ > marionette.js#L116 > > Even though we wait for fullyLoaded in the app, that doesn't necessarily > mean that Gecko is done with everything it is doing, so I suppose that could > be the source of issues, but it would mean profiling the device and seeing > what happens after fullyLoaded. Yeah, I'm also going to look into Messages app to double check that we don't do anything special after "fullyLoaded".

Anything special, or *anything*? Nothing should happen after fullyLoaded.

I'm wondering if a scenario like this is possible: function foo() { ... lots of memory allocations ... fireFullyLoaded(); } function fireFullyLoaded() { perf.mark('fullyLoaded'); } in that case, I believe there's a possibility that at the moment when we fire fullyLoaded, the memory from `foo` cannot be freed. But right after that, `foo` ends and all its memory can be freed. Of course the stack may be way deeper, but the idea is - if we fire fullyLoaded very deep in the stack of bootstrapping operations that allocate a lot, then maybe right after fullyLoaded there's a lot of GC available. The easiest way to test my hypothesis would be to instrument raptor to perform GC+read after 500ms after fullyLoaded (vs. performing GC instantly and reading 500ms later).

I'm not sure that is a big possibility since Raptor itself is not inside the app. Once fullyLoaded is hit, the stack should unwind to nothing, but I'm not sure how long that takes. In the time that fullyLoaded is fired: * Gecko handles the additional performance marker, then generates a log entry * Raptor sees the log entry while parsing the log, then continues to propagate events until we parse the log entry into something useful, an event * All the Promises that are waiting for the event can finally resolve and move onto triggering the GC If the app stack can't unwind in the time it takes Raptor to move onto GC-ing, then I suppose it's possible. But if the stack unwinding is fast, I don't suppose that would be a big source of problems.

(In reply to :Eli Perelman from comment #42) > Anything special, or *anything*? Nothing should happen after fullyLoaded. "Anything" :) And I see that we call "App.setReady() --> set CSS class on body (with JS prefix, there is no CSS rule for it) --> triggers MutationObserver on body --> resolves promise --> ...." right _after_ issuing "fullyLoaded" that doesn't sound right, I'll fix that and see if it solves the issue.

I've got too excited in comment 45 - actually we create MO only on demand and it's not requested in Inbox, so no MO is involved after fullyLoaded, but the rest is still valid. I've added console.log to the functions that could potentially be called after fullyLoaded and here is what I see in adb log (prettified a bit): I/Messages(19527): Content JS LOG: fullyLoaded // These [App] operations can be easily moved before we call fullyLoaded I/Messages(19527): Content JS LOG: [App] Added js-app-ready class to the body I/Messages(19527): Content JS LOG: [App] Set correct volumeControlChannel notification // [Settings] requests are more complex, we start preloading few settings once // we finish lazy loading scripts and don't wait for them to be completed. I/Messages(19527): Content JS LOG: [Settings] Setting-Retrieved operatorResource.sms.maxConcat // We fired contact picture requests before fullyLoaded, but majority of the responses // come later, as we don't wait for them to mark app as fullyLoaded - likely one of the major factors :/ W/Messages(19527): Content JS WARN: The datastore is empty and readonly I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 37 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 39 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 3 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 49 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 50 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 64 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 62 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 60 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 52 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 42 I/Messages(19527): Content JS LOG: [Inbox] Contact picture set for the thread 38 I/Messages(19527): Content JS LOG: [Settings] Setting-Retrieved ril.mms.defaultServiceId I/Messages(19527): Content JS LOG: [Settings] Setting-Retrieved ril.sms.defaultServiceId // Before fullyLoaded we also create settings lock and set setting, but this request is // not finished yet at the moment we mark app as fullyLoaded. I/Messages(19527): Content JS LOG: [Settings] Setting-Set ril.sms.maxReadAheadEntries // Here is more interesting stuff, Bridge logs, services that are located inside hidden // iframe are initialized before fullyLoaded, but it's not true for the SharedWorker service, // as we know from bug 1191926 - it takes ~300ms to just initialize SharedWorker // and only then Bridge comes into play. I/Messages(19527): Content JS LOG: [Bridge] [Message][SharedWorkerGlobalScope] - "receiver initialized" messaging-service I/Messages(19527): Content JS LOG: [Bridge] [Service][SharedWorkerGlobalScope] - "initialized" messaging-service I/Messages(19527): Content JS LOG: [Bridge] [Message][SharedWorkerGlobalScope] - "listen" I/Messages(19527): Content JS LOG: [Bridge] [PortAdaptor][SharedWorkerGlobalScope] - "creating port adaptor for" SharedWorkerGlobalScope I/Messages(19527): Content JS LOG: [Bridge] [Message][SharedWorkerGlobalScope] - "listen" I/Messages(19527): Content JS LOG: [Bridge] [PortAdaptor][SharedWorkerGlobalScope] - "creating port adaptor for" MessagePort I/Messages(19527): Content JS LOG: [Bridge] [PortAdaptor][SharedWorkerGlobalScope] - "PortAdaptor" So obviously Messages app fullyLoaded mark is not that accurate and it's quite hard to change this right now :/ I'm wondering if other apps have the same issue :) What if Raptor measure memory twice, first as usual - right after fullyLoaded and then after 10 sec and if there is a big difference rise a warning sign?

Unassigning myself as I'm not working on this at the moment. Also please note that Messages memory consumption _reflected at Raptor dashboard_ has been decreased for ~2MB for USS, PSS and RSS after 1219176 (see bug 1219176 comment 24). Nothing changed for real user though, but we'll likely have smaller diff in Raptor results between v2.2 and v2.5 because of this change.