Last Comment Bug 805366 - Optimize iCAL parser
: Optimize iCAL parser
Status: VERIFIED FIXED
[MemShrink:P2]
: perf
Product: Firefox OS
Classification: Client Software
Component: Gaia::Calendar (show other bugs)
: unspecified
: All All
: P1 normal (vote)
: B2G C1 (to 19nov)
Assigned To: James Lal [:lightsofapollo] (inactive)
: Jason Smith [:jsmith]
:
Mentors:
Depends on:
Blocks: slim-fast 796789
  Show dependency treegraph
 
Reported: 2012-10-25 01:26 PDT by James Lal [:lightsofapollo] (inactive)
Modified: 2012-12-16 09:10 PST (History)
9 users (show)
jsmith: in‑testsuite+
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
+


Attachments
Memory Report (use about:memory) (2.68 MB, text/plain)
2012-10-25 01:26 PDT, James Lal [:lightsofapollo] (inactive)
no flags Details
With --minimize (1.75 MB, text/plain)
2012-10-30 17:15 PDT, James Lal [:lightsofapollo] (inactive)
no flags Details
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/6417 (355 bytes, text/html)
2012-11-14 21:40 PST, James Lal [:lightsofapollo] (inactive)
jlal: review+
Details

Description James Lal [:lightsofapollo] (inactive) 2012-10-25 01:26:59 PDT
Created attachment 675017 [details]
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 2012-10-25 02:19:36 PDT
Huzzah!
Comment 2 Justin Lebar (not reading bugmail) 2012-10-25 06:48:47 PDT
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) 2012-10-25 06:50:41 PDT
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 [:njn] 2012-10-30 16:26:50 PDT
James, can you answer the question from comment 3?
Comment 5 Justin Lebar (not reading bugmail) 2012-10-30 16:37:24 PDT
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) 2012-10-30 16:42:09 PDT
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] (inactive) 2012-10-30 17:15:29 PDT
Created attachment 676851 [details]
With --minimize
Comment 8 Nicholas Nethercote [:njn] 2012-10-30 17:22:06 PDT
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] (inactive) 2012-10-30 17:22:23 PDT
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) 2012-10-30 17:25:39 PDT
> --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 [:njn] 2012-10-30 17:26:52 PDT
> 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) 2012-10-30 17:27:56 PDT
> 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) 2012-10-30 17:29:03 PDT
If these strings go away on GC then maybe we can just let bug 771195 fix this.
Comment 14 James Lal [:lightsofapollo] (inactive) 2012-11-05 21:34:26 PST
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] (inactive) 2012-11-12 22:58:58 PST
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] (inactive) 2012-11-14 21:40:52 PST
Created attachment 681851 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/6417

Pointer to Github pull-request
Comment 17 James Lal [:lightsofapollo] (inactive) 2012-11-19 19:29:38 PST
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] 2012-12-16 09:10:04 PST
Verified. Performance of importing large calendars seems far better now - tested with a few large yahoo and google calendars.

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