850893 - Main B2G process using 120 MiB RSS after opening and closing email app 400 times

Status: RESOLVED WONTFIX

(Core :: General, defect)

Description

[Nicholas Nethercote [inactive]]

Attachment: 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] [he/him] ⌚BST]

(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]]

Is it possible to get a smaller STR?

Does anyone have time to investigate more here?

Comment 3

[Nicholas Nethercote [inactive]]

> 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]

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]]

I ran the tests with a fresh build so no messages should have been there.

Comment 6

[Justin Lebar (not reading bugmail)]

> 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)]

I filed bug 852010 on dumping the strings.  I think that would be a good place to start.

Comment 8

[Robert Wood [:rwood]]

Attachment: 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] (please needinfo)]

ahuang: any insight into this?

Comment 10

[Nicholas Nethercote [inactive]]

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]]

ni(m4) based on comment 10

Comment 12

[Kevin Grandon :kgrandon]

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 [inactive]]

> 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)]

Attachment: 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)]

Attachment: 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)]

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)]

I will mark it as resolved if no one can produce this issue again.

Comment 18

[Alex Keybl [:akeybl]]

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)]

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)]

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)]

Attachment: Memory dump after 25 launch of Email app using script

Comment 22

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Attachment: 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)]

> 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)]

oh thats sound great. I will do it and update. thanks

Comment 25

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(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)]

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)]

Attachment: 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)]

(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)]

> > 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)]

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)]

(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)]

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)]

Attachment: 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)]

Attachment: 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)]

Attachment: 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)]

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.