897627 - Run orangutan apps test on leo and reproduce memory leaks

Status: RESOLVED WONTFIX

(Testing :: General, defect)

Description

[Robert Wood [:rwood]]

Run the orangutan test script (found in bug 889261) on a DMD-enabled leo device with b2g18-v1-train, and check for memory leaks.

Comment 1

[Robert Wood [:rwood]]

Did a b2g18-v1-train build for leo with DMD-enabled, at the following commit (before the fix to bug 889261 landed):

https://hg.mozilla.org/releases/mozilla-b2g18/rev/09368ed138e9

Did a 'get_about_memory.py', then ran the 'runningapps' orangutan test on the device for > 12 hours.

Attempted to do another 'get_about_memory.py' after running the test for > 12 hours, but the script failed to finish with error "/data/local/tmp/memory-reports/dmd-137462508-1-69.txt.gz; echo -n "\n$?'" returned non-zero exit status 255". Some reports were copied though. 'Adb shell df' shows space left on device (813M alone in /data).

About-memory-0 is from before starting the test:

http://people.mozilla.com/~rwood/about-memory-0.tar.gz

About-memory-1 is from after running the test > 12 hours, and when about_memory_py didn't finish:

http://people.mozilla.com/~rwood/about-memory-1.tar.gz

Before running the test, the b2g-ps vsize value for 'b2g' was 199380, after > 12 hours it was just 210232, so only an 11k increase. If there was a memory leak wouldn't it be reflected in the main b2g process vsize value? Or do the about_memory results above show a leak?

Comment 2

[Justin Lebar (not reading bugmail)]

vsize is not the right metric to look at.

vsize measures how much virtual memory a process is using.  But on 32-bit Linux, a process can use 4gb of virtual memory before it crashes, even if the device only has 256mb (or less) physical memory.

The only time we care about vsize is when a process uses so much virtual memory that it runs out and crashes.  This happens sometimes (particularly on Windows, which doesn't have a lot of vmem available to processes), but it's not a common issue.

The right metric to use for "process size" is RSS (resident set size) or USS (unique set size).  RSS measures "how much memory the process is using," while USS measures "how much memory would be freed if this process were killed right now."  The difference between the two is essentially that RSS counts shared pages, while USS doesn't.

Comment 3

[Justin Lebar (not reading bugmail)]

> 'adb shell df' shows space left on device (813M alone in /data).

a) Isn't there a separate partition for /data/local/tmp?

b) Was /data/local/tmp empty when you measured this?  Obviously if we ran out of space, then pulled the files off the device, then deleted them, and then measured how much disk space was free, that would not give us the result we wanted.

Comment 4

[Robert Wood [:rwood]]

I don't know re: partition.

No, the files were/are still in /data/local/tmp. Here is the full 'adb shell df' output:

Filesystem             Size   Used   Free   Blksize
/dev                   192M    48K   192M   4096
/mnt/asec              192M     0K   192M   4096
/mnt/obb               192M     0K   192M   4096
/mnt/extasec           192M     0K   192M   4096
/mnt/extobb            192M     0K   192M   4096
/system                342M    99M   242M   4096
/data                 1007M   194M   813M   4096
/persist                11M     4M     7M   4096
/cache                 228M     4M   224M   4096
/persist-lg              7M     4M     3M   4096
/mpt                    15M     4M    11M   4096

Comment 5

[Justin Lebar (not reading bugmail)]

It looks like there isn't a separate /data/local/tmp partition, so I guess you're right that it's not running out of disk space.

Another reason you might see this error is if processes OOM while dumping their info.

Do you keep getting this error when you run the script multiple times?

Comment 6

[Justin Lebar (not reading bugmail)]

I just pushed a change to get_about_memory.py that lets you pass --no-dmd, which prevents the script from pulling dmd logs.

This may let you get further here.

Comment 7

[Justin Lebar (not reading bugmail)]

Also, you may want to update your tree; it looks like you're not building with bug 893242. That will help us catch a certain class of leak that otherwise takes many hours to observe.

Comment 8

[Robert Wood [:rwood]]

Thanks Justin, I updated my B2G/tools. I am running the test again overnight tonight on the emulator and on leo. Yes I am using an older b2g18 tree that doesn't have the fix for bug 889261, as I am trying to reproduce the memory leak seen there, on my local setup.

Comment 9

[Justin Lebar (not reading bugmail)]

Bug 893242 is helpful because it's a memory reporter that makes these leaks more obvious.  Without this you may have to run the test for a /long/ time to see a significant increase in memory usage.  Leo's test runs for more than a day on a fast device.

Comment 10

[Robert Wood [:rwood]]

Even with --no-dmd, the get_about_memory script fails after running it after the test has been running. Yes the error keeps happening when the script is run multiple times.

/data/local/tmp/memory-reports/dmd-1374760064-2753.txt.gz; echo -n "|$?"'' returned non-zero exit status 255

Comment 11

[Justin Lebar (not reading bugmail)]

Although I got an emulator build to start up, that was all I got -- it didn't even boot into Gaia.

So this may be easier if I can ssh into your box and see what's going on.  If that's OK with you, ping me offline to set up a time that works for you.  We can try to figure out a way to do screen sharing.

Comment 12

[Justin Lebar (not reading bugmail)]

ni? for comment 11, so this doesn't get lost.

Comment 13

[Robert Wood [:rwood]]

Hey, I'm going to sync up and do a new build with the latest, and give it a try again

Comment 14

[Robert Wood [:rwood]]

I did a new build for Leo with b2g18 v1-train (DMD-enabled) on Friday July 26th. I let the orangutan 'runningapps' test run from Friday until today (Monday July 29th). The test ran for a total of 68 hours.

The starting b2g-process memory after 1 iteration of the test: 230540
The b2g-process memory after 68 hours of running the test: 246548
Total b2g-memory increase of: 16008 KB

The b2g-ps memory values were grabbed each hour and are attached.

About_memory logs can be found here, '0' is from the start, '1' is after 68 hours:

http://people.mozilla.com/~rwood/leo_jul29_about_memory.tar.gz

Justin, can you have a look please and see if there is a memory leak here?

Note that the about_memory script still fails with "returned non-zero exit status 255" on the 2nd and all following tries.

Comment 15

[Robert Wood [:rwood]]

Attachment: b2g-ps-values.txt

Comment 16

[Justin Lebar (not reading bugmail)]

I'm currently on a metered internet connection, so I can't download big files for another few hours.

Can I teach you to fish in the meantime?

Compare, say, 1hr to 68 hr.  First, diff the memory reports in about:memory -- there's a diff button if you open about:Memory in nightly.  Which entry/entries increased?

If heap-unclassified increased significantly, then look at the DMD reports.  You have to compare these by hand.

If memory usage increased by 16mb, that seems like it's probably a leak.

Comment 17

[Robert Wood [:rwood]]

(In reply to Justin Lebar [:jlebar] from comment #2)
> vsize is not the right metric to look at.
> 
> vsize measures how much virtual memory a process is using.  But on 32-bit
> Linux, a process can use 4gb of virtual memory before it crashes, even if
> the device only has 256mb (or less) physical memory.
> 
> The only time we care about vsize is when a process uses so much virtual
> memory that it runs out and crashes.  This happens sometimes (particularly
> on Windows, which doesn't have a lot of vmem available to processes), but
> it's not a common issue.
> 
> The right metric to use for "process size" is RSS (resident set size) or USS
> (unique set size).  RSS measures "how much memory the process is using,"
> while USS measures "how much memory would be freed if this process were
> killed right now."  The difference between the two is essentially that RSS
> counts shared pages, while USS doesn't.

I missed this comment until now, thanks Justin. The values I listed in comment 14 are not really valid then as they are vsize and not RSS. Thanks for the info in comment 16 also, appreciated.

Comment 18

[Robert Wood [:rwood]]

Hi Justin, I'm unsure as to which memory_reports to compare.

In about-memory-0, there is just the one "memory-reports" text file, so that's fine, however in about-memory-1 (after the test finished), there are no files in the root folder. There are dozens of memory-report-*.json.gz files. Is this because the get_about_memory.py script failed and didn't finish correctly?

I diffed the one file in about-memory-0 with a few of the .gz files, they have varying results. Is there one .gz file in particular that I should diff? They are all named memory-report-1375106598-nnnn.json.gz. Do I just chose the one with the highest value for the '-nnnn' part, is that a time value? Thanks.

Comment 19

[Justin Lebar (not reading bugmail)]

> Is this because the get_about_memory.py script failed and didn't finish correctly?

Yes.

When we pull memory reports from the device, we send the main B2G process a signal.  It lets X equal the current UNIX time, then asks every one of its child processes to dump a memory report with X as the "identifier".  The main process also prints a memory report with X as the identifier.

Thus if we have N child processes running, we get N+1 files named memory-report-X-P.json.gz, where P is the pid of the process which created the report.

After the script finishes pulling the memory reports, it merges them into one JSON file, called memory-reports.

Since we care only about the main process's memory usage here, you could diff two memory reports for which cover only the main process, if you have that.  You can identify the main process's pid by looking at the output of b2g-ps, if the script got far enough to capture that.  Or you can look at the memory report itself; it should say "main process".  But it sounds like you only took two memory reports here, and one got merged.

If you have one merged memory report and one set of unmerged memory reports, you have some options.  You could

a) Convert about-memory-0/memory-reports into a file which covers only the main process.  You'd need to parse the memory-reports file and pick only the objects in the |reports| list which have right value for "process".

b) Merge about-memory-1/memory-report-N-*.json.gz into an about-memory-1/memory-reports file.  The code to do this is in get_about_memory.py::merge_files; it's pretty simple.

c) Diff about-memory-0/memory-reports against the main-process about-memory-1/memory-report-N.p.json.gz.  This might just work, because we're only concerned with the main-process diff.

I'd love to figure out why the script isn't working for you so you don't regularly have to go through this pain.

Comment 20

[Robert Wood [:rwood]]

Thanks Justin. I am going to do an up-to-date build of the emulator b2g18-v1train with DMD enabled, and try the get_about_memory.py script again with that. If it fails on the second and following tries like before, then I'll ping you on IRC so we can try to connect so you can have a look.

Comment 21

[Justin Lebar (not reading bugmail)]

Ping on this bug?  I'm happy to help, particularly with figuring out this issue with all but the first pull failing.  Just let me know.

Comment 22

[Robert Wood [:rwood]]

Thanks Justin, appreciated. I'm at a work week this week so may not have a chance, if not then next week for sure.

Comment 23

[Robert Wood [:rwood]]

Sorry for the delay. I did a new build of the B2G emulator from Mozilla central. The first time I do a get_about_memory.py it works fine. Then I ran the orangutan 'runningApps' test which starts and minimizes all the apps one at a time. Then after the test, I tried another get_about_memory.py, and it fails with:

Got 24/24 files.
Pulled files into about-memory-1.
Command adb shell '/system/bin/toolbox "rm" /data/local/tmp/memory-reports/dmd-1376417563-45.txt.gz /data/local/tmp/memory-reports/dmd-1376417563-1296.txt.gz
... <lots more files> ...
/data/local/tmp/memory-reports/memory-report-1376417563-1232.json.gz /data/local/tmp/memory-reports/memory-report-1376417563-1413.json.gz /data/local/tmp/memory-reports/dmd-1376417563-1226.txt.gz; echo -n "|$?"' failed with error code 255
error: service name too long

Traceback (most recent call last):
  File "get_about_memory.py", line 289, in <module>
    get_and_show_info(args)
  File "get_about_memory.py", line 182, in get_and_show_info
    (out_dir, merged_reports_path, dmd_files) = get_dumps(args)
  File "get_about_memory.py", line 179, in get_dumps
    return utils.run_and_delete_dir_on_exception(do_work, out_dir)
  File "/home/rwood/B2G/tools/include/device_utils.py", line 147, in run_and_delete_dir_on_exception
    return fun()
  File "get_about_memory.py", line 164, in do_work
    optional_outfiles_prefixes=['dmd-'])
  File "/home/rwood/B2G/tools/include/device_utils.py", line 221, in notify_and_pull_files
    _remove_files_from_device(all_outfiles_prefixes, old_files)
  File "/home/rwood/B2G/tools/include/device_utils.py", line 326, in _remove_files_from_device
    remote_toolbox_cmd('rm', ' '.join([str(f) for f in files_to_remove]))
  File "/home/rwood/B2G/tools/include/device_utils.py", line 56, in remote_toolbox_cmd
    return remote_shell('/system/bin/toolbox "%s" %s' % (cmd, args))
  File "/home/rwood/B2G/tools/include/device_utils.py", line 25, in remote_shell
    out = shell(r"""adb shell '%s; echo -n "|$?"'""" % cmd)
  File "/home/rwood/B2G/tools/include/device_utils.py", line 78, in shell
    raise subprocess.CalledProcessError(proc.returncode, cmd, err)

Comment 24

[Justin Lebar (not reading bugmail)]

If you look through the lines in the stack trace, there's even a relevant comment:

> include/device_utils.py:
>
>    # Hopefully this command line won't get too long for ADB.
>    remote_toolbox_cmd('rm', ' '.join([str(f) for f in files_to_remove]))

Can you try changing this to a loop that calls |rm| once for each entry in files_to_remove and send a pull request if that works?

It's interesting that we've never seen this on a device.  Maybe the emulator is able to load more apps at once than a real phone (e.g. because the emulator's firmware has less overhead than our actual devices').

Comment 25

[Robert Wood [:rwood]]

Hi Justin,

Thanks, that change worked the first time I tried it, but the second time when running get_about_memory.py (again on emulator) where there were 48 GC/CC logs and 24 DMD dumps, the script ran for over 40 minutes, basically freezing my VM, and then failed during the "Process DMD Files" stage with:

OSError: [Error 12] cannot allocate memory

Comment 26

[Justin Lebar (not reading bugmail)]

I think I suggested this on IRC, but maybe it got lost: The DMD dumps are merely nice to have, and we could work on getting them to work after we get everything else working.  What happens if you don't pull DMD dumps?  There's a flag you can pass to get_about_memory.py.

Comment 27

[Robert Wood [:rwood]]

Hi Justin, yes when using the --no-dmd flag, the script works fine each time and the memory reports are pulled off and removed from the device. I will submit a pull request for the change that you noted in comment 24.

Comment 28

[Robert Wood [:rwood]]

Update re: comment 24, a pull request was submitted and merged, see bug 889747