805366 - Optimize iCAL parser

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::Calendar, defect, P1)

Description

[James Lal [:lightsofapollo]]

Attachment: Memory Report (use about:memory)

A staggering amount of memory is being used in the ical parser during sync.
Given the relatively small size of each caldav response something must be going really wrong here.

Comment 1

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Huzzah!

Comment 2

[Justin Lebar (not reading bugmail)]

In case it's not clear, when about:memory says something like

│  │  │  │  ├───0.94 MB (02.28%) ── string(length=3227, "ParserError@app:////calendar.gaia...") [120]

That means there are 120 occurrences of a length-3227 string which begins with "ParserError@app:////calendar.gaia...".

Comment 3

[Justin Lebar (not reading bugmail)]

An interesting data-point would be to collect an about:memory dump as you did, and then to collect another one with --minimize.  That would tell us whether the problem is that we're leaking memory, or just not collecting it aggressively enough.

Comment 4

[Nicholas Nethercote [inactive]]

James, can you answer the question from comment 3?

Comment 5

[Justin Lebar (not reading bugmail)]

Can someone paste in the highlights from this memory report, so we don't get the false impression from comment 2 that we're talking about 1mb of memory here?  (I'm on a 3G connection right now.)

Comment 6

[Justin Lebar (not reading bugmail)]

Okay, connected to the real Internet again.  Here we go:

41.16 MB (100.0%) -- explicit
├──26.86 MB (65.27%) -- workers/workers(gaiamobile.org)/worker(/caldav_worker.js?time=1351153005062, 436c4400)
│  ├──18.06 MB (43.87%) -- compartment(web-worker)
│  │  ├──13.10 MB (31.82%) -- string-chars
│  │  │  ├──11.09 MB (26.95%) -- huge
│  │  │  │  ├───4.49 MB (10.91%) ++ (43 tiny)
│  │  │  │  ├───0.94 MB (02.28%) ── string(length=3227, "ParserError@app:////calendar.gaia...") [120]
│  │  │  │  ├───0.94 MB (02.28%) ── string(length=3147, "expectRE@app:////calendar.gaiamob...") [120]
│  │  │  │  ├───0.87 MB (02.11%) ── string(length=2818, "expectRE@app:////calendar.gaiamob...") [111]
│  │  │  │  ├───0.87 MB (02.11%) ── string(length=2898, "ParserError@app:////calendar.gaia...") [111]
│  │  │  │  ├───0.78 MB (01.90%) ── string(length=3224, "ParserError@app:////calendar.gaia...") [100]
│  │  │  │  ├───0.78 MB (01.90%) ── string(length=3144, "expectRE@app:////calendar.gaiamob...") [100]
│  │  │  │  ├───0.72 MB (01.75%) ── string(length=2815, "expectRE@app:////calendar.gaiamob...") [92]
│  │  │  │  └───0.71 MB (01.73%) ── string(length=2895, "ParserError@app:////calendar.gaia...") [91]
│  │  │  └───2.00 MB (04.87%) ── non-huge

I guess one way to approach this would be to figure out what these strings are.

Comment 7

[James Lal [:lightsofapollo]]

Attachment: With --minimize

Comment 8

[Nicholas Nethercote [inactive]]

Minimizing gets rid of all the string chars, and the space taken by the worker drops from 27 MiB to 11 MiB:

├──11.17 MB (27.02%) -- workers/workers(gaiamobile.org)/worker(/caldav_worker.js?time=1342627067940, 446d4800)
│  ├───4.87 MB (11.78%) -- gc-heap
│  │   ├──4.78 MB (11.56%) ── decommitted-arenas [2]
│  │   └──0.09 MB (00.23%) ++ (3 tiny)
│  ├───3.25 MB (07.85%) -- compartment(web-worker)
│  │   ├──1.34 MB (03.24%) ── analysis-temporary [2]
│  │   ├──0.86 MB (02.07%) ++ gc-heap
│  │   ├──0.62 MB (01.50%) -- (6 tiny)
│  │   │  ├──0.24 MB (00.59%) ++ type-inference
│  │   │  ├──0.18 MB (00.43%) ── jaeger-data [2]
│  │   │  ├──0.07 MB (00.16%) ── other-sundries [4]
│  │   │  ├──0.06 MB (00.15%) ── objects/slots [2]
│  │   │  ├──0.06 MB (00.14%) ++ shapes-extra
│  │   │  └──0.01 MB (00.03%) ── string-chars/non-huge
│  │   └──0.43 MB (01.04%) ── script-data [2]
│  ├───2.68 MB (06.49%) -- runtime
│  │   ├──1.18 MB (02.86%) ── script-sources [2]
│  │   ├──0.79 MB (01.90%) ── jaeger-code [2]
│  │   └──0.72 MB (01.73%) ++ (12 tiny)

So it's a collection issue, though you could also argue that it'd be nice not to generate all these strings in the first place.

Comment 9

[James Lal [:lightsofapollo]]

re 3:

--minimize gives me odd results, I see something like 8/4 then eventually it times out with: expected 4 but see only 8 files.  Giving up...

I can successfully run it but only during periods of inactivity.

re 6:

I know that those strings are the .ics documents that are currently being parsed.
Eventually (as in the new memory report I added) these strings are no longer present (though consumption is still bad).

I am puzzled by this in particular (─9.03 MB (21.84%) ── heap-unclassified).
What should I be looking for here?

(highlight with -m):

├──11.17 MB (27.02%) -- workers/workers(gaiamobile.org)/worker(/caldav_worker.js?time=1342627067940, 446d4800)
│  ├───4.87 MB (11.78%) -- gc-heap
│  │   ├──4.78 MB (11.56%) ── decommitted-arenas [2]
│  │   └──0.09 MB (00.23%) -- (3 tiny)
│  │      ├──0.09 MB (00.23%) ── chunk-admin [2]
│  │      ├──0.00 MB (00.00%) ── unused-arenas
│  │      └──0.00 MB (00.00%) ── unused-chunks
│  ├───3.25 MB (07.85%) -- compartment(web-worker)
│  │   ├──1.34 MB (03.24%) ── analysis-temporary [2]
│  │   ├──0.86 MB (02.07%) -- gc-heap
│  │   │  ├──0.24 MB (00.57%) ++ objects
│  │   │  ├──0.20 MB (00.48%) ── unused-gc-things [4]
│  │   │  ├──0.15 MB (00.36%) ── scripts [2]
│  │   │  ├──0.14 MB (00.34%) ++ shapes
│  │   │  ├──0.07 MB (00.18%) ── strings [2]
│  │   │  ├──0.05 MB (00.11%) ── type-objects [2]
│  │   │  └──0.01 MB (00.03%) ── sundries [4]
│  │   ├──0.62 MB (01.50%) -- (6 tiny)
│  │   │  ├──0.24 MB (00.59%) ++ type-inference
│  │   │  ├──0.18 MB (00.43%) ── jaeger-data [2]
│  │   │  ├──0.07 MB (00.16%) ── other-sundries [4]
│  │   │  ├──0.06 MB (00.15%) ── objects/slots [2]
│  │   │  ├──0.06 MB (00.14%) ++ shapes-extra
│  │   │  └──0.01 MB (00.03%) ── string-chars/non-huge
│  │   └──0.43 MB (01.04%) ── script-data [2]
│  ├───2.68 MB (06.49%) -- runtime
│  │   ├──1.18 MB (02.86%) ── script-sources [2]
│  │   ├──0.79 MB (01.90%) ── jaeger-code [2]
│  │   └──0.72 MB (01.73%) ++ (12 tiny)
│  └───0.37 MB (00.89%) ++ compartment(web-worker-atoms)
├───9.03 MB (21.84%) ── heap-unclassified
├───6.22 MB (15.05%) -- window-objects/top(app://calendar.gaiamobile.org/settings/, id=1)/active/window(app://calendar.gaiamobile.org/settings/)
│   ├──4.13 MB (09.99%) -- js/compartment(app://calendar.gaiamobile.org/index.html)
│   │  ├──2.34 MB (05.65%) -- gc-heap
│   │  │  ├──0.98 MB (02.36%) ── unused-gc-things [2]
│   │  │  ├──0.53 MB (01.28%) ++ shapes
│   │  │  ├──0.49 MB (01.18%) ++ objects
│   │  │  └──0.34 MB (00.83%) ++ (4 tiny)
│   │  ├──0.89 MB (02.16%) ++ (5 tiny)
│   │  ├──0.47 MB (01.13%) ── analysis-temporary [2]
│   │  └──0.43 MB (01.05%) ── script-data [2]
│   ├──1.32 MB (03.20%) -- layout
│   │  ├──0.78 MB (01.89%) ++ (7 tiny)
│   │  └──0.54 MB (01.31%) ── pres-shell [2]
│   └──0.77 MB (01.86%) ++ (3 tiny)

Comment 10

[Justin Lebar (not reading bugmail)]

> --minimize gives me odd results, I see something like 8/4 then eventually it times out 
> with: expected 4 but see only 8 files.  Giving up...

bug 806239, sorry.

Comment 11

[Nicholas Nethercote [inactive]]

> I am puzzled by this in particular (─9.03 MB (21.84%) ── heap-unclassified).
> What should I be looking for here?

That's heap memory that we don't have a specific reporter for, so we don't know who is allocating it.  Bug 798484 is open for reducing it.

Comment 12

[Justin Lebar (not reading bugmail)]

> I am puzzled by this in particular (─9.03 MB (21.84%) ── heap-unclassified).
> What should I be looking for here?

Hover over any line in about:memory to get a description.  heap-unclassified means "we don't know."  9mb/20% isn't particularly high for B2G; it's probably not anomalous.

Comment 13

[Justin Lebar (not reading bugmail)]

If these strings go away on GC then maybe we can just let bug 771195 fix this.

Comment 14

[James Lal [:lightsofapollo]]

I am working on some major changes to the ical lib (which lives outside of gaia).

The parser layer (which is shown above to have memory issues) has been completely rewritten with good results. I need to make major changes to the layer between the parsed object and what gaia consumes before I can take another memory screenshot but the raw numbers look a lot better:

(numbers taken with benchmark.js)

#parse v2 x 9,284 ops/sec ±2.19% (81 runs sampled)
#parse x 161 ops/sec ±5.04% (76 runs sampled)

--

I am renaming the bug to reflect the work that is actually being done though I believe we will see a substantial reduction in memory usage and a major decrease in the amount of time it takes to parse / process.

Comment 15

[James Lal [:lightsofapollo]]

jsmith: The final pieces are in testing now, I need to add the piece that makes auto-upgrade smoother (not break current dog-fooding). Other then that it is fairly complete and I have been able to sync calendars without issue. Using the patch in its current state will probably break any existing calendars.

https://github.com/lightsofapollo/gaia/tree/calendar-parser-rewrite

Comment 16

[James Lal [:lightsofapollo]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/6417

Pointer to Github pull-request

Comment 17

[James Lal [:lightsofapollo]]

Reviewed on GH.

This is not a cure-all for memory or performance problems but brings some major memory and performance improvements (will post some details of memory/parser time later)  to the iCAL parser.

Comment 18

[Jason Smith [:jsmith]]

Verified. Performance of importing large calendars seems far better now - tested with a few large yahoo and google calendars.