Last Comment Bug 850893 - Main B2G process using 120 MiB RSS after opening and closing email app 400 times
: Main B2G process using 120 MiB RSS after opening and closing email app 400 times
Status: RESOLVED WONTFIX
[MemShrink:P1]
:
Product: Core
Classification: Components
Component: General (show other bugs)
: unspecified
: All All
: -- normal (vote)
: ---
Assigned To: Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
:
Mentors:
Depends on: 852010
Blocks: 836891
  Show dependency treegraph
 
Reported: 2013-03-13 15:30 PDT by Nicholas Nethercote [:njn] (on vacation until July 11)
Modified: 2013-04-15 20:36 PDT (History)
37 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
-
+


Attachments
memory reporter dump (JSON) (866.62 KB, application/json)
2013-03-13 15:30 PDT, Nicholas Nethercote [:njn] (on vacation until July 11)
no flags Details
about memory dump after 10 iterations of open/close email (56.24 KB, application/x-gzip)
2013-03-18 13:33 PDT, Robert Wood [:rwood]
no flags Details
Memory dump Launching Email App 100 times and killing it 100times (401.64 KB, text/plain)
2013-03-24 21:56 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
Memory Dump just after rebooting device without launching any App. (385.63 KB, text/plain)
2013-03-24 21:58 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
Memory dump after 25 launch of Email app using script (512.41 KB, text/plain)
2013-03-29 07:52 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
memory dump after 25 manual laucnh of Email App (399.13 KB, text/plain)
2013-03-29 07:53 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
b2gperf.py script log with 'about_memory.py --minimize' (973.59 KB, application/x-bzip)
2013-03-29 16:18 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
Email launched 50 times manually _procrank and app start time log (3.04 KB, text/plain)
2013-04-04 10:49 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
50timesEmailLaunchScript (240.67 KB, text/plain)
2013-04-04 10:51 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details
Adb logcat for 50times manual launch . (243.41 KB, text/plain)
2013-04-04 10:52 PDT, Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)
no flags Details

Description Nicholas Nethercote [:njn] (on vacation until July 11) 2013-03-13 15:30:11 PDT
Created attachment 724641 [details]
memory reporter dump (JSON)

In bug 837187 comment 56, Michael Schwartz wrote:

> I am using a modified version of the
> http://hg.mozilla.org/users/tmielczarek_mozilla.com/b2gperf script to start
> the Email application, kill all apps, and repeat over and over.  After ~400,
> the b2g process is now ~110MB and Email boots to a black screen.

The about:memory dump is attached.  The most obvious thing about it is this:

   ├──8,314,880 B (07.76%) ── string(length=9114, "data:image//png;base64,iVBORw0KG...") [406]

The "[406]" means that the same path is being reported 406 times.  So it looks like a PNG in a data URL is being leaked every time the email app opens or closes.  That's the most obvious thing to try to fix.

Beyond that, there are a lot of strings in the system compartment:

│   │  │  ├──57,888,692 B (54.01%) -- compartment([System Principal])
│   │  │  │  ├──23,724,004 B (22.13%) -- string-chars
│   │  │  │  │  ├──15,200,228 B (14.18%) ── non-huge

but it's hard to say much about where they're coming from.
Comment 1 Dave Hunt (:davehunt) 2013-03-13 15:47:28 PDT
(In reply to Nicholas Nethercote [:njn] from comment #0)
> > I am using a modified version of the
> > http://hg.mozilla.org/users/tmielczarek_mozilla.com/b2gperf script to start
> > the Email application, kill all apps, and repeat over and over.  After ~400,
> > the b2g process is now ~110MB and Email boots to a black screen.

Just FYI, the latest version of that script is now hosted on github: https://github.com/mozilla/b2gperf
Comment 2 Andrew Overholt [:overholt] 2013-03-15 10:35:00 PDT
Is it possible to get a smaller STR?

Does anyone have time to investigate more here?
Comment 3 Nicholas Nethercote [:njn] (on vacation until July 11) 2013-03-15 13:32:20 PDT
> Is it possible to get a smaller STR?

Presumably if you only do this 10 times instead of 400 you'll still see 10 leaked images, which should be enough to investigate.
Comment 4 cmtalbert 2013-03-15 16:23:39 PDT
Rwood, could you use your endurance scripts to open the email application about 10 times and then do a about memory dump and see if we have 10 of those images reported (see comment 0 for the image reference).

As a secondary question, how many messages were in the email application when this test was originally run? Did you do any experiments to see if that matters? I know it seems that we just leak an image per startup, but it may be that this particular image only shows up with a certain number of messages (i.e. it could be a scrolling widget or some such).
Comment 5 Michael Schwartz [:m4] 2013-03-15 16:45:18 PDT
I ran the tests with a fresh build so no messages should have been there.
Comment 6 Justin Lebar (not reading bugmail) 2013-03-17 19:54:12 PDT
> but it's hard to say much about where [these strings are] coming from.

Why don't we add a feature to the about:memory dumping that dumps all strings?  We keep running into this, so maybe we should just make it the default.

For each string we'd ideally indicate

 * its compartment, and
 * whether it's garbage.

We could add it to the existing about:memory JSON data, or we could put it elsewhere.  We'd need to be a bit careful with this since strings can carry sensitive data.
Comment 7 Justin Lebar (not reading bugmail) 2013-03-17 20:15:12 PDT
I filed bug 852010 on dumping the strings.  I think that would be a good place to start.
Comment 8 Robert Wood [:rwood] 2013-03-18 13:33:58 PDT
Created attachment 726317 [details]
about memory dump after 10 iterations of open/close email

Ran endurance test that starts the email app, waits for load, then closes it (zero messages in the inbox). Ran for 10 iterations.  B2g nightly/latest Mar 18 eng build, Unagi. Did an about_memory after the last iteration.  The "data:image" text doesn't appear in the about_memory output (attached) at all. Do I need to do a debug build perhaps instead of using the nightly?
Comment 9 Joe Cheng [:jcheng] 2013-03-19 02:50:34 PDT
ahuang: any insight into this?
Comment 10 Nicholas Nethercote [:njn] (on vacation until July 11) 2013-03-19 16:35:19 PDT
I'd like to know if this is some kind of test harness artifact.  Michael, can you try opening and closing the email app multiple times manually to see if it reproduces?
Comment 11 Andrew Overholt [:overholt] 2013-03-20 10:26:56 PDT
ni(m4) based on comment 10
Comment 12 Kevin Grandon :kgrandon 2013-03-21 13:36:09 PDT
Adding myself to the cc here because I recently did some work to cache app screenshots for faster task switcher startup times. We should be revoking these on app exit though.

Nicholas - can you confirm that your modified script is calling WindowManager.kill to kill the app?
Comment 13 Nicholas Nethercote [:njn] (on vacation until July 11) 2013-03-21 15:52:54 PDT
> Nicholas - can you confirm that your modified script is calling
> WindowManager.kill to kill the app?

It's not my script, it's Michael's.  Michael?
Comment 14 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-24 21:56:33 PDT
Created attachment 728832 [details]
Memory dump Launching Email App 100 times and killing it 100times

I launched Email App 100 times and killed it 100 times manually on device. After that I have taken memory dump for b2g process.
Comment 15 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-24 21:58:54 PDT
Created attachment 728833 [details]
Memory Dump just after rebooting device without launching any App.

I have taken this memory dump just after rebooting device without launching any app.
Comment 16 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-24 22:08:06 PDT
I followed following steps to take memory dump for b2g process :

1) adb shell rm /data/local/tmp/*
2) adb shell killer SIGRT0 <b2g process id>
3) adb pull /data/local/tmp/<b2g process memory dump json file>

I have taken logs for following two cases:
1) I have taken logs after rebooting device without launching any apps.
2) I launched Email App 100 times and killed it 100 times manually on device. After that I have taken memory dump for b2g process.

I have not found any such image string (length=9114, "data:image//png;base64" ) in memory dump for both cases. I also didn't find any suspicious memory leakage.

I am unable to produce the case for manual launching Email App 100 times. I am using 1.0.1 .
Comment 17 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-24 22:10:01 PDT
I will mark it as resolved if no one can produce this issue again.
Comment 18 Alex Keybl [:akeybl] 2013-03-25 10:42:10 PDT
Let's add qawanted and make sure this is re-opened and re-nominated for tef+ if this is reproduced.
Comment 19 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-25 12:23:17 PDT
Need to verify it with Michael Schwartz [:m4]. There is another bugzilla "App start problem" which depends on this.
Comment 20 Mike Habicher [:mikeh] (high bugzilla latency) 2013-03-27 11:16:28 PDT
We're seeing something similar in bug 846903 after taking hundreds of photos with the Camera app.
Comment 21 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 07:52:06 PDT
Created attachment 731156 [details]
Memory dump after 25 launch of Email app using script
Comment 22 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 07:53:27 PDT
Created attachment 731159 [details]
memory dump after 25 manual laucnh of Email App

I am observing an Big difference in memory dump for script launch using (using '/cygdrive/c/Python27/python.exe b2gperf.py --iterations=25 Email' ) and manual launch. 

I launched b2gperf.py 25 times both manually on device and using b2gperf script. 

In case of manual launch, we see B2G process is using 35 MB and RSS is 53MB after 25 launch consecutively. 

But in case of script launch (), we see B2G process is using 47MB and RSS is 69MB
Comment 23 Justin Lebar (not reading bugmail) 2013-03-29 07:56:46 PDT
> I am observing an Big difference in memory dump for script launch using (using '/cygdrive/c/Python27
> /python.exe b2gperf.py --iterations=25 Email' ) and manual launch. 

In the past when we've seen something like this, it's been because the automated test script goes so fast we avoid GC'ing.

You can test this theory by doing get_about_memory.py --minimize after the automated test.  This will force a GC.
Comment 24 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 08:02:36 PDT
oh thats sound great. I will do it and update. thanks
Comment 25 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 12:57:51 PDT
(In reply to Justin Lebar [:jlebar] from comment #23)
> > I am observing an Big difference in memory dump for script launch using (using '/cygdrive/c/Python27
> > /python.exe b2gperf.py --iterations=25 Email' ) and manual launch. 
> 
> In the past when we've seen something like this, it's been because the
> automated test script goes so fast we avoid GC'ing.
> 
> You can test this theory by doing get_about_memory.py --minimize after the
> automated test.  This will force a GC.

I just tried a script like this :

#!/bin/bash
for i in {1..25}
do
   python b2gperf.py --iterations=1 Email 
   sleep 10
   /local/mnt/workspace/c_tkundu/28thMarch/device/qcom/b2g_common/mozilla-b2g/tools/get_about_memory.py --minimize
   sleep 10
done

But still i see B2G process is using 46MB and RSS is 64MB. In case of manual launch, I see B2G process is using 35 MB and RSS is 53MB after 25 launch consecutively. 

So there is a big difference of these two numbers.
Comment 26 Justin Lebar (not reading bugmail) 2013-03-29 13:15:06 PDT
Sounds like the test script may be causing a leak.  We've seen this a few times in the past as well.  :)

Another possibility is that your manual testing is doing something different than the automated testing, and that's somehow causing this.  For example, if you're killing the e-mail app via the cards view in one instance and sending SIGKILL to it in another instance, that could be a significant difference.

Unfortunately about:memory isn't helping much here.  The difference between the memory dumps in comment 21 and comment 22 is mostly in compartment([System Principal]), which is opaque due to some memory optimizations we did.

Could you attach the memory report after automated testing with --minimize?  I don't think that's going to tell us where the memory is going either, but looking at that might help us get an idea of how to proceed debugging this.  For example, if that memory report has more strings than the one from comment 22 (as is the case comparing the one from comment 22 with the one from comment 21), we could dump all the strings and see if that tells us where the additional memory is coming from.

> But still i see B2G process is using 46MB and RSS is 64MB.

What is the 46mb, exactly?
Comment 27 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 16:18:30 PDT
Created attachment 731367 [details]
b2gperf.py script log with 'about_memory.py --minimize'

This is the output of below script:


#!/bin/bash
for i in {1..37}
do
   python b2gperf.py --iterations=1 Email 
   sleep 10
   /local/mnt/workspace/c_tkundu/28thMarch/device/qcom/b2g_common/mozilla-b2g/tools/get_about_memory.py --minimize
   sleep 10
done

Here we see a collection of "about-memory-<number>" folders inside compressed log file.  For example:-
about-memory-0 contains logs for 'python get_about_memory --minimize' after 1st time launch of EMAIL app. 

about-memory-1 contains logs for 'python get_about_memory --minimize' after 2nd time launch of EMAIL app etc.
Comment 28 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-29 16:19:57 PDT
(In reply to Justin Lebar [:jlebar] from comment #26)
> Sounds like the test script may be causing a leak.  We've seen this a few
> times in the past as well.  :)
> 
> Another possibility is that your manual testing is doing something different
> than the automated testing, and that's somehow causing this.  For example,
> if you're killing the e-mail app via the cards view in one instance and
> sending SIGKILL to it in another instance, that could be a significant
> difference.
> 
> Unfortunately about:memory isn't helping much here.  The difference between
> the memory dumps in comment 21 and comment 22 is mostly in
> compartment([System Principal]), which is opaque due to some memory
> optimizations we did.
> 
> Could you attach the memory report after automated testing with --minimize? 
> I don't think that's going to tell us where the memory is going either, but
> looking at that might help us get an idea of how to proceed debugging this. 
> For example, if that memory report has more strings than the one from
> comment 22 (as is the case comparing the one from comment 22 with the one
> from comment 21), we could dump all the strings and see if that tells us
> where the additional memory is coming from.
> 
> > But still i see B2G process is using 46MB and RSS is 64MB.
> 
> What is the 46mb, exactly?

See attachment 731367 [details] . It has logs for '--minimize' option.
Comment 29 Justin Lebar (not reading bugmail) 2013-03-29 17:14:23 PDT
> > But still i see B2G process is using 46MB and RSS is 64MB.
> 
> What is the 46mb, exactly?
Comment 30 Justin Lebar (not reading bugmail) 2013-03-30 06:14:33 PDT
This bug's summary indicates that the B2G main process was using 120mb of RSS.  But iteration 36 of the attachment from comment 28 has the B2G main process using ~67mb of memory, a far cry from 120mb.  It would likely be helpful to know where that additional 53mb of memory is going when we hit 120mb.

Anyway there are still additional strings in the --minimize logs.  So dumping all the strings seems like an option we could pursue.
Comment 31 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-03-30 09:35:50 PDT
(In reply to Justin Lebar [:jlebar] from comment #30)
> This bug's summary indicates that the B2G main process was using 120mb of
> RSS.  But iteration 36 of the attachment from comment 28 has the B2G main
> process using ~67mb of memory, a far cry from 120mb.  It would likely be
> helpful to know where that additional 53mb of memory is going when we hit
> 120mb.
> 
> Anyway there are still additional strings in the --minimize logs.  So
> dumping all the strings seems like an option we could pursue.

If we run script for 400 times then it hits 120 MB. I just run it for 36 times to see what is happening inside.
Comment 32 Justin Lebar (not reading bugmail) 2013-03-30 16:27:35 PDT
I understand, but the 36 times doesn't actually give us a lot of insight into what's going on.  Unless you see something in the logs that I don't.

Anyway I think we need to get you string dumping in order to continue investigating this.
Comment 33 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-04-04 10:49:10 PDT
Created attachment 733440 [details]
Email launched 50 times manually _procrank and app start time log

I did following steps to launch Email 50 times consecutively on device:

step 1. Reboot QRD and flash it .
step 2. Pan in home screen till I see Email App icon in App list

step 3. launch Email App by manually touching Email App icon
s
step 4. Wait till Email login Screen comes.

step 5. Press and hold HomeButton for long time and then kill Email App manually.

step 6: Repeat step 3 and step 4 for 50 times. Collect both Adb logcat and adb procrank log for this.

step 7: Run 'python.exe b2gperf.py Email' and see average case launch latency after 50 launch.

I collected 'adb shell procrank' , 'adb logcat' log and app start time log for this use case. It shows that nsMemoryPressureObserver:sGCOnMemoryPressure is called 300 times in this use case and also* RSS , PSS, USS* of b2g process is only .57800kb, 48016kb, 44192kb respectively.
Comment 34 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-04-04 10:51:32 PDT
Created attachment 733442 [details]
50timesEmailLaunchScript

I tested Email by rebooting device and running 'b2gperf.py ---iterations=50 Email' 

It shows nsMemoryPressureObserver:sGCOnMemoryPressure is called 150 times for this script and RSS PSS USS of b2g process see almost 10 MB increase compare to earlier use case. I attached adb logcat for this use case. I also see 100 ms launch latency increase for this use case.
Comment 35 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-04-04 10:52:38 PDT
Created attachment 733443 [details]
Adb logcat for 50times manual launch .

it shows adb logcat for 50 times manual launch
Comment 36 Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me) 2013-04-04 10:53:20 PDT
My conclusion is that we are getting more frequent GC SHRINK and CC calls with manual launch . Script is launch is causing less GC and CC calls. So RSS PSS USS is increased over time and it affects app launch time.

Note You need to log in before you can comment on or make changes to this bug.