Last Comment Bug 531396 - APIs for tracking garbage-collector activities
: APIs for tracking garbage-collector activities
Status: RESOLVED FIXED
[firebug-p3]
: dev-doc-needed
Product: Core
Classification: Components
Component: XPCOM (show other bugs)
: Trunk
: All All
: -- normal with 2 votes (vote)
: mozilla14
Assigned To: Terrence Cole [:terrence]
:
Mentors:
Depends on: 735916 735994 736429 748397
Blocks: 720595 752861
  Show dependency treegraph
 
Reported: 2009-11-27 07:33 PST by Jan Honza Odvarko [:Honza] PTO 07/23 - 08/08
Modified: 2012-05-08 06:03 PDT (History)
14 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
patch to add JSON GC+CC reporting (5.88 KB, patch)
2012-02-03 15:19 PST, Bill McCloskey (:billm)
bugs: feedback+
Details | Diff | Splinter Review
patch to memchaser (2.60 KB, patch)
2012-02-03 15:22 PST, Bill McCloskey (:billm)
no flags Details | Diff | Splinter Review
v0: Allow arbitrary sized strings and support printing as JSON. (21.82 KB, patch)
2012-03-02 16:55 PST, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v1: add missing comma and use correct format string for CC printer (22.09 KB, patch)
2012-03-05 14:21 PST, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v2: Prints numbers as numbers with units on the console. (23.06 KB, patch)
2012-03-05 15:35 PST, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v3: Format the stats as json. (19.66 KB, patch)
2012-03-09 11:10 PST, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v3: The nsIRunnable bits. (5.67 KB, patch)
2012-03-09 11:10 PST, Terrence Cole [:terrence]
bugs: review-
Details | Diff | Splinter Review
v5: Address review comments. (5.66 KB, patch)
2012-03-12 11:12 PDT, Terrence Cole [:terrence]
bugs: review+
Details | Diff | Splinter Review
v6: Made formatMessage return jschar * and fixed one bug in formatJSString. (19.60 KB, patch)
2012-03-12 13:43 PDT, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
With final review comments applied. (5.68 KB, patch)
2012-03-12 13:48 PDT, Terrence Cole [:terrence]
terrence: review+
Details | Diff | Splinter Review
v7: isblank is not present on windows (19.92 KB, patch)
2012-03-12 14:18 PDT, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v8: With review feedback applied. (19.17 KB, patch)
2012-03-12 17:17 PDT, Terrence Cole [:terrence]
wmccloskey: review+
Details | Diff | Splinter Review
Use the new API in memchaser. (2.68 KB, patch)
2012-03-14 15:11 PDT, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review
v1: With full support for older and newer browsers. (4.71 KB, patch)
2012-03-16 12:06 PDT, Terrence Cole [:terrence]
no flags Details | Diff | Splinter Review

Description Jan Honza Odvarko [:Honza] PTO 07/23 - 08/08 2009-11-27 07:33:47 PST
It would be incredibly useful to have some APIs that allow tracking garbage collector activities such as: memory allocation, clean up, amount of allocated memory, etc.

Each event should also specify a time stamp.

All this information could be displayed in Firebug and help to profile web-app performance.

(not sure if XPCOM is the proper component for this)

Honza
Comment 1 Henrik Skupin (:whimboo) 2012-01-16 12:50:04 PST
Looks like that this is already a kinda old request. With our current work on the memchaser extension [1] we also kinda would like to get such an API.

As given by Andrew and Bill we could get an observer notification implemented. But for further details I would like to let one of them answer directly.


[1] https://wiki.mozilla.org/QA/Automation_Services/Projects/Addons/MemChaser
Comment 2 Bill McCloskey (:billm) 2012-01-24 10:28:54 PST
I'll work on this next week. Right now, we pass a string to the GC finished callback that eventually ends up in the error console. The easiest way to fix this bug is to pass similar data in JSON format as well. We could include extra information about bytes allocated before and after the GC. This string would be posted to some sort of GC observer, and then could make its way to JS code through XPCOM. I'm a little unsure of how the last part will work, but I'm kind of interested in learning more about it.
Comment 3 Nicholas Nethercote [:njn] 2012-01-24 15:14:57 PST
Bug 720595 could be wrapped up as part of this.
Comment 4 Henrik Skupin (:whimboo) 2012-01-24 21:57:36 PST
Thanks Bill for taking it! That sounds awesome. Whenever you need help I will try to give input as best as I can. I agree that passing a JSON object through the observer makes the most sense. We can enhance the amount of data passed through at any time. 

For the last part I think it should work similar to what we have for the 'http-on-modify-request' observer topic. Probably it will help you with the implementation.

http://mxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/nsIHttpProtocolHandler.idl#119
Comment 5 Jan Honza Odvarko [:Honza] PTO 07/23 - 08/08 2012-01-24 23:17:31 PST
Awesome, as soon as the APIs are available I can test them with Firebug and provide feedback.

Thanks!
Honza
Comment 6 Bill McCloskey (:billm) 2012-02-03 15:19:08 PST
Created attachment 594325 [details] [diff] [review]
patch to add JSON GC+CC reporting

This is more of a proof of concept, but I wanted to make some progress on this. It just adds some simple JSON reporting along the lines suggested by Henrik. The actual format of the JSON data is almost certainly going to change, especially with incremental GC.

Mainly I'm hoping to get feedback on the nsJSEnvironment side. Did I do the observer thing right? Is there a better way to handle the ASCII to UTF conversion? The incremental GC patches will change how the JSON data is passed to the DOMGCFinished callback, so don't pay much attention to that.
Comment 7 Bill McCloskey (:billm) 2012-02-03 15:22:39 PST
Created attachment 594327 [details] [diff] [review]
patch to memchaser

This is a patch to memchaser to show how it would use the new observer stuff. I did this just for testing.
Comment 8 Andrew McCreight [:mccr8] 2012-02-03 16:22:54 PST
The cycle collector notifies observers of the beginning of a CC with  obs->NotifyObservers(nsnull, "cycle-collector-begin", nsnull).  I was thinking of doing a similar thing for the garbage collector, for similar reasons as it is needed in the CC.  You just put it in the DOM gc callback.  Bill knows how to do that, as he was the one who suggested it to me.  I don't know if that would be useful for your purposes or not.
Comment 9 Jan Honza Odvarko [:Honza] PTO 07/23 - 08/08 2012-02-04 01:23:12 PST
Any chance we could have a time stamp of when the event has been really fired? Similarly to what nsIHttpActivityObserver has
https://developer.mozilla.org/en/nsIHttpActivityObserver
(see aTimestamp)

Since the event is posted to the UI thread getting the time in the handler doesn't have to produce accurate timings.

If we have accurate timings we could combine (and compare) collected data into existing graphs.

Honza
Comment 10 Henrik Skupin (:whimboo) 2012-02-04 03:17:20 PST
(In reply to Andrew McCreight [:mccr8] from comment #8)
> The cycle collector notifies observers of the beginning of a CC with 
> obs->NotifyObservers(nsnull, "cycle-collector-begin", nsnull).  I was

Nice. I haven't known about it yet. So I would propose we are adjusting the observer topics in the patch above to align to the already existing ones.

(In reply to Jan Honza Odvarko from comment #9)
> If we have accurate timings we could combine (and compare) collected data
> into existing graphs.

Jan, it looks like that we have similar ideas for our extensions. We should probably sit together and talk a bit about it.
Comment 11 Jan Honza Odvarko [:Honza] PTO 07/23 - 08/08 2012-02-04 06:19:29 PST
(In reply to Henrik Skupin (:whimboo) from comment #10)
> Jan, it looks like that we have similar ideas for our extensions. We should
> probably sit together and talk a bit about it.
Yep, good idea, I am based in GMT+1 (Czech), we could arrange a conf coll next week.

Honza
Comment 12 Henrik Skupin (:whimboo) 2012-02-27 03:23:29 PST
Bill, do you have an update for us regarding this patch? Is there anything you need help with?
Comment 13 Bill McCloskey (:billm) 2012-02-27 20:47:17 PST
I'll try to have a patch up tomorrow.
Comment 14 Terrence Cole [:terrence] 2012-03-02 16:55:44 PST
Created attachment 602540 [details] [diff] [review]
v0:  Allow arbitrary sized strings and support printing as JSON.

I still have to hook this up to memchaser.  Putting this out here to get feedback, since it looks like I won't get to it until Monday.
Comment 15 Henrik Skupin (:whimboo) 2012-03-04 14:43:34 PST
Hey Terrence, great to see that you have had time to work on the JS side of the patch. Would you mind showing us a JSON example for a full vs. incremental GC and a CC? I would kinda appreciate that. Thanks!
Comment 16 Terrence Cole [:terrence] 2012-03-05 14:17:32 PST
Excellent idea!

Note that all values in the GC printer are treated as strings, even ones we know are numbers.  I can change this with a bit more code, but I'm not sure how important it is.  This also simplifies the printing since some of the numbers have units.

Sorry for the lack of formatting.

JSON for a non-incremental GC:
{"TotalTime": "21.9ms", "Type": "compartment", "MMU(20ms)": "0%", "MMU(50ms)": "56%", "Reason": "TOO_MUCH_MALLOC", "NonIncrementalReason": "requested", "+chunks": "0", "-chunks": "0", "Totals": ["mark": "4.8", "mark-roots": "0.9", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "17.0", "sweep-obj": "6.6", "sweep-string": "9.3", "sweep-script": "0.0", "sweep-shape": "0.1", "discard-code": "0.2", "discard-analysis": "0.6", "xpconnect": "0.0", "deallocate": "0.0"]}

JSON for an incremental GC: 
{"TotalTime": "263.0ms", "Type": "global", "MMU(20ms)": "0%", "MMU(50ms)": "0%", "MaxPause": "89.5", "NonIncrementalReason": "requested", "+chunks": "0", "-chunks": "0", "slices": [{"Slice": "0", "@": "11.8ms", "Pause": "11.8", "Reason": "MAYBEGC", "times": ["mark": "11.5", "mark-roots": "1.5", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "1", "@": "60.3ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "2", "@": "105.9ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "3", "@": "151.8ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "4", "@": "198.5ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "5", "@": "244.1ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "6", "@": "289.9ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "7", "@": "336.3ms", "Pause": "10.0", "Reason": "REFRESH_FRAME", "times": ["mark": "10.0", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "8", "@": "383.2ms", "Pause": "10.8", "Reason": "REFRESH_FRAME", "times": ["mark": "10.7", "mark-roots": "0.0", "mark-delayed": "3.6", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "9", "@": "431.5ms", "Pause": "11.9", "Reason": "REFRESH_FRAME", "times": ["mark": "11.8", "mark-roots": "0.0", "mark-delayed": "5.8", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "10", "@": "477.7ms", "Pause": "10.3", "Reason": "REFRESH_FRAME", "times": ["mark": "10.3", "mark-roots": "0.0", "mark-delayed": "0.6", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "11", "@": "526.0ms", "Pause": "12.4", "Reason": "REFRESH_FRAME", "times": ["mark": "12.3", "mark-roots": "0.0", "mark-delayed": "8.5", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "12", "@": "572.8ms", "Pause": "10.5", "Reason": "REFRESH_FRAME", "times": ["mark": "10.5", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "13", "@": "623.2ms", "Pause": "13.5", "Reason": "REFRESH_FRAME", "times": ["mark": "13.5", "mark-roots": "0.0", "mark-delayed": "7.4", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "14", "@": "650.7ms", "Pause": "11.5", "Reason": "ALLOC_TRIGGER", "times": ["mark": "11.5", "mark-roots": "0.0", "mark-delayed": "0.0", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "15", "@": "661.4ms", "Pause": "10.7", "Reason": "ALLOC_TRIGGER", "times": ["mark": "10.7", "mark-roots": "0.0", "mark-delayed": "0.8", "mark-other": "0.0", "sweep": "0.0", "sweep-obj": "0.0", "sweep-string": "0.0", "sweep-script": "0.0", "sweep-shape": "0.0", "discard-code": "0.0", "discard-analysis": "0.0", "xpconnect": "0.0", "deallocate": "0.0"]}, {"Slice": "16", "@": "751.0ms", "Pause": "89.5", "Reason": "LAST_DITCH", "Reset": "requested", "times": ["mark": "85.3", "mark-roots": "2.1", "mark-delayed": "0.0", "mark-other": "0.5", "sweep": "3.3", "sweep-obj": "0.5", "sweep-string": "0.0", "sweep-script": "0.1", "sweep-shape": "0.6", "discard-code": "0.1", "discard-analysis": "0.9", "xpconnect": "0.4", "deallocate": "0.0"]}], "Totals": ["mark": "258.2", "mark-roots": "3.5", "mark-delayed": "26.7", "mark-other": "0.5", "sweep": "3.3", "sweep-obj": "0.5", "sweep-string": "0.0", "sweep-script": "0.1", "sweep-shape": "0.6", "discard-code": "0.1", "discard-analysis": "0.9", "xpconnect": "0.4", "deallocate": "0.0"]}

And JSON for CC's:
{ "duration": 20, "suspected": 180, "visited-RCed": 5291, "visited-GCed": 2733, "collected-RCed": 4090, "collected-GCed": 1205, "waiting-for-gc": 5295, "forget-skippable": 1196357216, "min": 3, "max": 0, "total": 1, "removed": 0 }
Comment 17 Terrence Cole [:terrence] 2012-03-05 14:21:50 PST
Created attachment 603057 [details] [diff] [review]
v1: add missing comma and use correct format string for CC printer
Comment 18 Bill McCloskey (:billm) 2012-03-05 14:25:40 PST
At this point, it probably makes sense to clean up the field names a little bit. If we make them all lowercase, and we convert dashes to underscores, then it would be easier to access them via json.sweep_obj rather than json['sweep-obj'].

Also, I think all the times should just be JSON numbers. And I don't like using "@" as a field name.

If this means that the error console output has to get a little uglier, I'm okay with that. We should still be able to print the units there, though.
Comment 19 Andrew McCreight [:mccr8] 2012-03-05 14:33:34 PST
What is that giant number for forget-skippable?  It would probably make sense to combine everything that is in the second line into a subobject, because it is all stuff about forget-skippable. (the number of times, min, max, avg, total, removed).
Comment 20 Terrence Cole [:terrence] 2012-03-05 14:58:09 PST
Andrew: That's an off-by-one error :-).  I've fixed that bug and updated the CC format to:

{ "duration": 11, "suspected": 582, "visited": { "RCed": 1379, "GCed": 2234 }, "collected": { "RCed": 264, "GCed": 929 }, "waiting_for_gc": 1193, "message": "", "forget_skippable": { "times_before_cc": 5, "min": 0, "max": 2, "avg": 0, "total": 4, "removed": 2527 } }

Bill: I'll rework the GC formatter and get a new patch up.
Comment 21 Andrew McCreight [:mccr8] 2012-03-05 15:02:16 PST
Looks good!  Thanks for working on this.
Comment 22 Terrence Cole [:terrence] 2012-03-05 15:35:40 PST
Created attachment 603078 [details] [diff] [review]
v2: Prints numbers as numbers with units on the console.

Okay new formatting looks like this in XML (manually eliding the middle 17 slices):

{"TotalTime": 295.2, "Type": "global", "MMU_20ms": 0, "MMU_50ms": 0, "MaxPause": 90.2, "NonIncrementalReason": "requested", "ChunksAdded": 0, "ChunksRemoved": 0, "Slices": [{"Slice": 0, "Time": 11.7, "Pause": 11.7, "Reason": "MAYBEGC", "Times": ["mark": 11.4, "mark_roots": 1.4, "mark_delayed": 0.0, "mark_other": 0.0, "sweep": 0.0, "sweep_obj": 0.0, "sweep_string": 0.0, "sweep_script": 0.0, "sweep_shape": 0.0, "discard_code": 0.0, "discard_analysis": 0.0, "xpconnect": 0.0, "deallocate": 0.0]}, ..., {"Slice": 18, "Time": 784.9, "Pause": 90.2, "Reason": "LAST_DITCH", "Reset": "requested", "Times": ["mark": 87.1, "mark_roots": 2.2, "mark_delayed": 0.0, "mark_other": 0.7, "sweep": 2.4, "sweep_obj": 0.2, "sweep_string": 0.0, "sweep_script": 0.1, "sweep_shape": 0.5, "discard_code": 0.2, "discard_analysis": 0.5, "xpconnect": 0.3, "deallocate": 0.0]}], "Totals": ["mark": 291.5, "mark_roots": 3.6, "mark_delayed": 33.0, "mark_other": 0.7, "sweep": 2.4, "sweep_obj": 0.2, "sweep_string": 0.0, "sweep_script": 0.1, "sweep_shape": 0.5, "discard_code": 0.2, "discard_analysis": 0.5, "xpconnect": 0.3, "deallocate": 0.0]}

And like this on the console:

GC(T+7.6) TotalTime: 308.4ms, Type: global, MMU_20ms: 0%, MMU_50ms: 0%, MaxPause: 89.2ms, NonIncrementalReason: requested, ChunksAdded: 0, ChunksRemoved: 0
    Slice: 0, Time: 11.7ms (Pause: 11.7, Reason: MAYBEGC): mark: 11.4ms, mark_roots: 1.4ms
    Slice: 14, Time: 682.9ms (Pause: 14.0, Reason: ALLOC_TRIGGER): mark: 14.0ms, mark_delayed: 8.9ms
    Slice: 15, Time: 745.5ms (Pause: 62.6, Reason: ALLOC_TRIGGER): mark: 62.6ms, mark_delayed: 21.0ms
    Slice: 16, Time: 834.7ms (Pause: 89.2, Reason: LAST_DITCH, Reset: requested): mark: 85.9ms, mark_roots: 2.1ms, mark_other: 0.6ms, sweep: 2.5ms, sweep_obj: 0.3ms, sweep_string: 0.0ms, sweep_script: 0.1ms, sweep_shape: 0.5ms, discard_code: 0.2ms, discard_analysis: 0.5ms, xpconnect: 0.3ms, deallocate: 0.0ms
    Totals: mark: 304.5ms, mark_roots: 3.5ms, mark_delayed: 36.2ms, mark_other: 0.6ms, sweep: 2.5ms, sweep_obj: 0.3ms, sweep_string: 0.0ms, sweep_script: 0.1ms, sweep_shape: 0.5ms, discard_code: 0.2ms, discard_analysis: 0.5ms, xpconnect: 0.3ms, deallocate: 0.0ms
Comment 23 Henrik Skupin (:whimboo) 2012-03-06 06:23:41 PST
Great improvements. I have some questions:

* Whenever a 'Slices' array exists it will be an incremental GC, right?
* Are all the timing values which are used as numbers are actually in ms?
* Can you submit another round of JSON output for both GC and CC types?
* Does it mean we now have observers for GC start/end and CC start/end?
* Can we get a Tryserver build to play around with the new observer messages?
Comment 24 Andrew McCreight [:mccr8] 2012-03-06 07:43:49 PST
(In reply to Henrik Skupin (:whimboo) from comment #23)
> * Whenever a 'Slices' array exists it will be an incremental GC, right?

I think that's not true. An incremental GC can fail partway through and become a regular GC, but it still shows slice information.
Comment 25 Henrik Skupin (:whimboo) 2012-03-06 08:04:24 PST
Ah, right. So it is MaxPause as Bill told me. Would it make sense to also add a flag for it so we could get rid of checking different properties for their existence?
Comment 26 Terrence Cole [:terrence] 2012-03-06 13:28:41 PST
https://tbpl.mozilla.org/?tree=Try&rev=f9f7bc06c1ce
Comment 27 Bill McCloskey (:billm) 2012-03-07 15:04:35 PST
Comment on attachment 603078 [details] [diff] [review]
v2: Prints numbers as numbers with units on the console.

Review of attachment 603078 [details] [diff] [review]:
-----------------------------------------------------------------

Let's do one more iteration.

::: dom/base/nsJSEnvironment.cpp
@@ +3268,5 @@
> +              "\"collected\": { "
> +                  "\"RCed\": %lu, "
> +                  "\"GCed\": %lu }, "
> +              "\"waiting_for_gc\": %lu, "
> +              "\"message\": \"%s\", "

The message field doesn't make sense to me. It would be better if you made it look like:
  "forced_gc": 0|1
where the data comes from ccResults.mForcedGC.

@@ +3292,5 @@
> +                                        sTotalForgetSkippableTime / PR_USEC_PER_MSEC,
> +                                        sRemovedPurples));
> +    nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
> +    if (observerService) {
> +      observerService->NotifyObservers(nsnull, "cc-completed", json.get());

Please change this to cycle-collector-end.

@@ +3525,5 @@
>      }
>  
>      NS_NAMED_LITERAL_STRING(kFmt, "GC(T+%.1f) %s");
>      nsString msg;
> +    char *cstr = aDesc.formatMessage(aRt);

You need a NULL check on cstr. Please test the patch if you artificially return NULL from formatMessage and formatJSON.

@@ +3557,5 @@
>      sCleanupSinceLastGC = false;
>  
> +    nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
> +    if (observerService) {
> +      jschar *json = aDesc.formatJSON(aRt);

You need a NULL check on json.

@@ +3558,5 @@
>  
> +    nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
> +    if (observerService) {
> +      jschar *json = aDesc.formatJSON(aRt);
> +      observerService->NotifyObservers(nsnull, "gc-end", json);

And change this to 'garbage-collector-end'.

::: js/src/gc/Statistics.cpp
@@ +59,5 @@
> +
> +class StatisticsSerializer
> +{
> +    typedef Vector<jschar, 128, SystemAllocPolicy> CharBuffer;
> +    CharBuffer buf_;

As long as we're not using StringBuffer, it seems like it would be easier to store this as chars and only inflate at the end, if needed.

@@ +62,5 @@
> +    typedef Vector<jschar, 128, SystemAllocPolicy> CharBuffer;
> +    CharBuffer buf_;
> +    bool asJSON_;
> +    bool needComma_;
> +    bool taint_;

Could you call this oom_ instead of taint_?

@@ +67,5 @@
> +
> +    const static int MaxFieldValueLength = 128;
> +
> +  public:
> +    StatisticsSerializer(bool asJSON)

Could you make an enum for this?

@@ +91,5 @@
> +            p(str);
> +        }
> +    }
> +
> +    void appendString(const char *name, const char *vfmt, ...) {

Every single use of appendString passes %s for the format. I don't think this needs to be an argument. And then you could call put directly, and you could remove the valIsString argument from append.

@@ +98,5 @@
> +        append(true, name, vfmt, va, "");
> +        va_end(va);
> +    }
> +
> +    void appendNumber(const char *name, const char *vfmt, const char *postfix, ...) {

Can you change the name postfix to units?

@@ +179,5 @@
> +    void append(bool valIsString, const char *name, const char *vfmt,
> +                va_list va, const char *postfix)
> +    {
> +        char val[MaxFieldValueLength];
> +        memset(val, 0, MaxFieldValueLength);

I don't think this memset is necessary. JS_vsnprintf will always NULL-terminate.

@@ +258,2 @@
>  {
> +    ss.beginArray(name);

The elements that follow have keys ('mark', etc.), so this is an object, not an array.

@@ +286,5 @@
>      double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
>      double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
>  
> +    ss.beginObject();
> +    ss.appendNumber("TotalTime",    "%.1f",   "ms", t(total));

Here's my new thought on the key names (like TotalTime). We should write them out in normal English, with spaces, like "Total Time". That's how they would appear in the error console. And for JSON, we will convert to lowercase and replace spaces with underscores.

Also, please don't use extra spaces to line things up.

@@ +388,5 @@
>      if (fp) {
>          if (fullFormat) {
> +            StatisticsSerializer ss(false);
> +            formatPhases(ss, "", phaseTotals);
> +            char *tmp = ss.finishCString();

You need to check if tmp is NULL. Also, please call it msg.

@@ +408,5 @@
>  void
>  Statistics::printStats()
>  {
>      if (fullFormat) {
> +        char *tmp = formatMessage();

Need to check if tmp is NULL. Also, please call it msg.
Comment 28 Henrik Skupin (:whimboo) 2012-03-07 15:57:40 PST
Quick question so that we are consistent. In this patch I cannot find a gc-begin or garbage-collector-begin observer notification. Even MXR doesn't show a single entry for it. Could it be that you missed that notification in your patch?

Bill, would you mind checking my comment 25?

I'm away this week, so I will check this bug randomly for updates, but will probably not be able to test a tryserver build before Monday. Sorry.
Comment 29 Bill McCloskey (:billm) 2012-03-07 16:15:25 PST
Henrik, there is no GC begin notification. Would this be useful? 

One thing I left out of my review is that I would like the JSON to include some of the fields (like MaxPause and Slices) unconditionally. That should make parsing it a little easier.

To tell if a GC is incremental, you can check for the NonIncrementalReason field. I guess we could always have this field, but it would be "none" if the GC is incremental. Would that be better?
Comment 30 Henrik Skupin (:whimboo) 2012-03-07 23:17:33 PST
(In reply to Bill McCloskey (:billm) from comment #29)
> Henrik, there is no GC begin notification. Would this be useful? 

Yes, absolutely. We already have cycle-collector-begin:
http://mxr.mozilla.org/mozilla-central/search?string=cycle-collector-begin

It would give us the chance to do more nifty things.

> One thing I left out of my review is that I would like the JSON to include
> some of the fields (like MaxPause and Slices) unconditionally. That should
> make parsing it a little easier.

With the JSON object I don't have to worry about parsing anymore. :) Checking for the existence of one of those fields is a simple boolean if condition. But yes, sounds good.

> To tell if a GC is incremental, you can check for the NonIncrementalReason
> field. I guess we could always have this field, but it would be "none" if
> the GC is incremental. Would that be better?

Hm, so the examples in comment 16 and comment 22 are wrong, right? Because there a normal and an incremental GC contain this field both times. Are there different reasons beside 'requested' possible or could this be a simple boolean flag? In any way it would be way better, yes.
Comment 31 Bill McCloskey (:billm) 2012-03-08 09:15:49 PST
(In reply to Henrik Skupin (:whimboo) from comment #30)
> (In reply to Bill McCloskey (:billm) from comment #29)
> > Henrik, there is no GC begin notification. Would this be useful? 
> 
> Yes, absolutely. We already have cycle-collector-begin:
> http://mxr.mozilla.org/mozilla-central/search?string=cycle-collector-begin
> 
> It would give us the chance to do more nifty things.

Are you sure? In many cases the begin notification wouldn't fire until after the GC is over. So it seems kind of redundant with the end notification.

> Hm, so the examples in comment 16 and comment 22 are wrong, right? Because
> there a normal and an incremental GC contain this field both times. Are
> there different reasons beside 'requested' possible or could this be a
> simple boolean flag? In any way it would be way better, yes.

It's possible for a GC to start out incremental and then finish non-incrementally. That's what happened to the GCs in comments 16 and 22 with multiple slices. In the last slice, they were converted to non-incremental GCs. That's why all the GCs shown there have the NonIncrementalReason field. This field is not always 'requested'. Sometimes it has other values.
Comment 32 Henrik Skupin (:whimboo) 2012-03-08 13:32:23 PST
(In reply to Bill McCloskey (:billm) from comment #31)
> > Yes, absolutely. We already have cycle-collector-begin:
> > http://mxr.mozilla.org/mozilla-central/search?string=cycle-collector-begin
> > 
> > It would give us the chance to do more nifty things.
> 
> Are you sure? In many cases the begin notification wouldn't fire until after
> the GC is over. So it seems kind of redundant with the end notification.

Can you please give us a bit more information about those cases? I'm really not familiar with that underlying code and kinda would like to know what's going on. 

> It's possible for a GC to start out incremental and then finish
> non-incrementally. That's what happened to the GCs in comments 16 and 22
> with multiple slices. In the last slice, they were converted to
> non-incremental GCs. That's why all the GCs shown there have the
> NonIncrementalReason field. This field is not always 'requested'. Sometimes
> it has other values.

Interesting. So how does it correlate to the MaxPause vs. TotalTime values? If some incremental GC happen and then it gets reverted to a non-incremental GC is the TotalTime value still correct?
Comment 33 Bill McCloskey (:billm) 2012-03-08 14:15:09 PST
(In reply to Henrik Skupin (:whimboo) from comment #32)
> Can you please give us a bit more information about those cases? I'm really
> not familiar with that underlying code and kinda would like to know what's
> going on.

The GC can happen from arbitrary places in the JS engine. In some of those places, it isn't safe to just start executing the JS code for the observer. The best thing to do is to post an event so that the garbage-collection-begin/end signal is sent the next time we spin the event loop. However, that means that it won't actually happen until the current GC slice is over. In a GC with multiple slices, this can still be before the GC is completely finished. But in a single-slice GC, it will always be after the GC is done.

Terrence, this brings up a problem. I had assume that calling NotifyObservers was posting an event, like I described above. However, it's actually running the observers right away, as far as I can tell. This is unsafe. Instead, we need to post an event to run later. It looks like there's an example of how to do this in nsConsoleService.cpp (the LogMessage method).

> Interesting. So how does it correlate to the MaxPause vs. TotalTime values?
> If some incremental GC happen and then it gets reverted to a non-incremental
> GC is the TotalTime value still correct?

Yes, the times for MaxPause and TotalTime will still be correct. TotalTime is always the sum of the time taken by the slices. MaxPause is always the time taken by the longest slice.
Comment 34 Terrence Cole [:terrence] 2012-03-09 10:57:51 PST
Output for cycle-collector-end:
{ "duration": %llu,
  "suspected": %lu,
  "visited": {
      "RCed": %lu,
      "GCed": %lu },
  "collected": {
      "RCed": %lu,
      "GCed": %lu },
  "waiting_for_gc": %lu,
  "forced_gc": %d,
  "forget_skippable": {
      "times_before_cc": %lu,
      "min": %lu,
      "max": %lu,
      "avg": %lu,
      "total": %lu,
      "removed": %lu }
}

The overall format for output for garbage-collector-end is:
{ ...misc stuff like total_time, type, mmus's, etc...
  "slices": [
     { "slice": 0,
       ...slice specific stuff like time, pause, reason, etc...
       "times": {
            ...each gc phase as a pair "phase": time_in_ms...
       }
     },
     ...the rest of the slices in order...     
  ],
  "totals": {
     ...Total times spent in each gc phase for this gc:
        e.g. the sums of the per-phase times in the slices.
        The sum of these may not add up to the total_time
        as there are still some parts we don't track, but
        the difference should be small.
     ...
  }
}

More information about the phase times: all fields are from a single phase, except for "mark" and "sweep" which aggregate the total "mark_" and "sweep_" times (and may be larger because of slop in the accounting).

The slices list may be either absent or present in any circumstance.  If it is absent, we finished the GC's work in a single slice.  This may be because we were requested to do a non-incremental GC or because we finished all incremental GCing in the time allocated for a single slice.  You should check that "nonincremental_reason" is not "none" to see when we have done a non-incremental GC.  In this case, there still may be a slices list, since a running incremental GC may have been forced to finish.  In this case we will still show all of the slices we completed, with the last "slice" being a full GC.

If we have elided the slices list because we only had a single slice, then the "reason" field of the single slice will be displayed in the main section.

If there is more than one slice we will also add a "max_pause" field to the main section.  If there is only one slice, then this is equivalent to "total_time".

Example for a non-incremental garbage-collector-end:
{ "total_time": 110.0,
  "type": "global",
  "mmu_20ms": 0,
  "mmu_50ms": 0,
  "reason": "CC_FORCED",
  "nonincremental_reason": "requested",
  "added_chunks": 0,
  "removed_chunks": 0,
  "totals": {
    "mark": 67.7,
    "mark_roots": 7.4,
    "mark_delayed": 0.0,
    "mark_other": 6.0,
    "sweep": 34.8,
    "sweep_object": 6.9,
    "sweep_string": 0.5,
    "sweep_script": 1.1,
    "sweep_shape": 7.9,
    "discard_code": 1.0,
    "discard_analysis": 9.0,
    "xpconnect": 1.3,
    "deallocate": 0.0
  }
}

Here is an example of an incremental GC:
{ "total_time": 227.8, "type": "global", "mmu_20ms": 0, "mmu_50ms": 0,
  "max_pause": 121.9,
  "nonincremental_reason": "none", "added_chunks": 0, "removed_chunks": 0,
  "Slices": [
    { "slice": 0, 
      "time": 23.4,
      "pause": 23.4,
      "reason": "MAYBEGC",
      "times": {
        "mark": 21.7, "mark_roots": 11.1, "mark_delayed": 0.0, "mark_other": 0.0,
        "sweep": 0.0, "sweep_object": 0.0, "sweep_string": 0.0, "sweep_script": 0.0,
        "sweep_shape": 0.0, "discard_code": 0.0, "discard_analysis": 0.0, 
        "xpconnect": 0.0, "deallocate": 0.0
      }
    },
    { "slice": 1, 
      "time": 104.5,
      "pause": 10.3,
      "reason": "REFRESH_FRAME",
      "times": {...}
    },
    .....
    {"slice": 9, ... }
  ],
  "totals": {
    "mark": 114.6, "mark_roots": 11.1, "mark_delayed": 1.8, "mark_other": 10.6,
    "sweep": 20.6, "sweep_object": 3.1, "sweep_string": 0.1, "sweep_script": 0.6,
    "sweep_shape": 5.3, "discard_code": 0.4, "discard_analysis": 4.1,
    "xpconnect": 1.2, "deallocate": 0.1
  }
}

Hopefully, this should be enough information to get started with.  If you have further questions about the meanings of the various fields, I'd be happy to dig deeper and find out what they are doing.  Patches to actually make this work in-browser should be posted in a few minutes.
Comment 35 Terrence Cole [:terrence] 2012-03-09 11:07:24 PST
Discussed a bit with Bill, and I've changed the format to be easier to parse:

1) The slices list will always be present.  If there is a single slice the phase times will be identical with those listed in "totals", but this isn't a big deal.

2) The max pause will always be listed.  This will be identical with "total_time" if there is a single slice, but whatever.

3) The reason for the first slice will always be on the first slice and never included in the general section.

More information:
  The "reset" field in the individual slices will be set when we transition from an incremental to a non-incremental GC in the middle of a GC.  It will simply be absent if not set.
Comment 36 Terrence Cole [:terrence] 2012-03-09 11:10:06 PST
Created attachment 604466 [details] [diff] [review]
v3: Format the stats as json.
Comment 37 Terrence Cole [:terrence] 2012-03-09 11:10:49 PST
Created attachment 604467 [details] [diff] [review]
v3: The nsIRunnable bits.
Comment 38 Olli Pettay [:smaug] 2012-03-09 11:38:25 PST
Comment on attachment 604467 [details] [diff] [review]
v3: The nsIRunnable bits.


>+    NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
>+      NS_LL("{ \"duration\": %llu, "
>+              "\"suspected\": %lu, "
>+              "\"visited\": { "
>+                  "\"RCed\": %lu, "
>+                  "\"GCed\": %lu }, "
>+              "\"collected\": { "
>+                  "\"RCed\": %lu, "
>+                  "\"GCed\": %lu }, "
>+              "\"waiting_for_gc\": %lu, "
>+              "\"forced_gc\": %d, "
>+              "\"forget_skippable\": { "
>+                  "\"times_before_cc\": %lu, "
>+                  "\"min\": %lu, "
>+                  "\"max\": %lu, "
>+                  "\"avg\": %lu, "
>+                  "\"total\": %lu, "
>+                  "\"removed\": %lu } "
>+            "}"));
Does this compile/work on all the platforms? Or should you use NS_LL for each line.



>+    nsString json;
>+    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(),
>+                                        (now - start) / PR_USEC_PER_MSEC, suspected,
>+                                        ccResults.mVisitedRefCounted, ccResults.mVisitedGCed,
>+                                        ccResults.mFreedRefCounted, ccResults.mFreedGCed,
>+                                        sCCollectedWaitingForGC,
>+                                        ccResults.mForcedGC,
>+                                        sForgetSkippableBeforeCC,
>+                                        sMinForgetSkippableTime / PR_USEC_PER_MSEC,
>+                                        sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
>+                                        (sTotalForgetSkippableTime / cleanups) /
>+                                          PR_USEC_PER_MSEC,
>+                                        sTotalForgetSkippableTime / PR_USEC_PER_MSEC,
>+                                        sRemovedPurples));
>+    nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
>+    if (observerService) {
>+      observerService->NotifyObservers(nsnull, "cycle-collector-end", json.get());
Could we call this something else. This doesn't catch all the cyclecollect runs (those during shutdown), 
and cycle collector itself notifies cycle-collector-begin, so it is a bit strange the have the -end here.



>+class NotifyGCEndRunnable : public nsRunnable
>+{
>+  NotifyGCEndRunnable(const NotifyGCEndRunnable &other) MOZ_DELETE;
aOther
>+  NotifyGCEndRunnable &operator=(const NotifyGCEndRunnable &other) MOZ_DELETE;
aOther, and please bind & to the type, not to the name.

>+
>+public:
>+  NotifyGCEndRunnable(jschar *message) : mMessage(message) {}
aMessage

>+  ~NotifyGCEndRunnable() {
{ should be in the next line.

>+  jschar *mMessage;
Could you please use normal nsString here.
That way you don't need malloc/free manually.


>+NotifyGCEndRunnable::Run()
>+{
>+  MOZ_ASSERT(NS_IsMainThread());
>+
>+  nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
>+  if (!observerService)
>+    return NS_OK;
if (expr) {
  stmt;
}


>+  observerService->NotifyObservers(nsnull, "garbage-collector-end", toSend);
I don't quite like this notification name either.
Could we call them cycle-collect-log / garbage-collect-log or
cycle-collect-statistics / garbage-collect-statistics or
cycle-collection-description / garbage-collection-description
or something like what which doesn't indicate "-end", since especially because of this
async notification, it is possible that another GC has already run when observer is notified about the gc.
Comment 39 Henrik Skupin (:whimboo) 2012-03-09 12:07:34 PST
(In reply to Olli Pettay [:smaug] from comment #38)
> >+  observerService->NotifyObservers(nsnull, "garbage-collector-end", toSend);
> I don't quite like this notification name either.
[..]
> async notification, it is possible that another GC has already run when
> observer is notified about the gc.

So we should also remove the cycle-collector-begin notifications which are already in place, right?
Comment 40 Olli Pettay [:smaug] 2012-03-09 12:09:56 PST
No. cycle-collector-begin is just fine, since it describes what is happening: CC is about to begin.
And cycle-collector-begin is notified by CC itself.
Comment 41 Henrik Skupin (:whimboo) 2012-03-09 12:16:43 PST
Hm. So given your comment above and taking one of those examples we would have notifications like the following?

* cycle-collect-begin
* cycle-collect-log
* garbage-collect-log
Comment 42 Olli Pettay [:smaug] 2012-03-09 12:19:56 PST
Yes. Though, I might prefer
cycle-collect-begin
cycle-collection-statistics
garbage-collection-statistics

I would expect external tools, like memchaser to use only the two latter ones.
Comment 43 Olli Pettay [:smaug] 2012-03-09 12:22:53 PST
...because cycle-collect-begin is kind of Gecko internal thing where cyclecollector notifies
nsCCUncollectableMarker that it can mark various things to be in CCGeneration.
If someone does something during cycle-collect-begin, it may affect to the cycle collection results.
Comment 44 Terrence Cole [:terrence] 2012-03-12 11:12:04 PDT
Created attachment 605014 [details] [diff] [review]
v5: Address review comments.
Comment 45 Olli Pettay [:smaug] 2012-03-12 11:54:35 PDT
Comment on attachment 605014 [details] [diff] [review]
v5: Address review comments.


>     NS_NAMED_LITERAL_STRING(kFmt, "GC(T+%.1f) %s");
>     nsString msg;
>+    char *cstr = aDesc.formatMessage(aRt);
>     msg.Adopt(nsTextFormatter::smprintf(kFmt.get(),
>                                         double(delta) / PR_USEC_PER_SEC,
>-                                        aDesc.logMessage));
>+                                        cstr));
>+    js_free(cstr);
You could Adopt cstr to a nsString object and remove this js_free

>+    nsString json;
>+    jschar *tmp = aDesc.formatJSON(aRt);
>+    json.Adopt(tmp);
>+    js_free(tmp);
double free here?


Those fixed, r+
Comment 46 Henrik Skupin (:whimboo) 2012-03-12 12:33:27 PDT
Would be nice if we could a final tryserver build to check before the code gets landed. Otherwise I will come up with follow-up bugs when I find issues.
Comment 47 Terrence Cole [:terrence] 2012-03-12 13:38:51 PDT
https://tbpl.mozilla.org/?tree=Try&rev=f1de3ce7df25

I tested this against trunk memchaser with the changes from Bill's patch applied.  Appears to work nicely, at least against this build.  I'm sure you'll probably want to do some more work to make it work against older browsers as well.
Comment 48 Terrence Cole [:terrence] 2012-03-12 13:43:14 PDT
Created attachment 605089 [details] [diff] [review]
v6: Made formatMessage return jschar * and fixed one bug in formatJSString.

Would be nice to get this into FF13.
Comment 49 Terrence Cole [:terrence] 2012-03-12 13:48:44 PDT
Created attachment 605091 [details] [diff] [review]
With final review comments applied.
Comment 50 Terrence Cole [:terrence] 2012-03-12 14:18:36 PDT
Created attachment 605123 [details] [diff] [review]
v7: isblank is not present on windows

I think I obsoleted the wrong patch with my last attachment.  Sorry for the confusion!
Comment 51 Bill McCloskey (:billm) 2012-03-12 15:03:29 PDT
Comment on attachment 605123 [details] [diff] [review]
v7: isblank is not present on windows

Review of attachment 605123 [details] [diff] [review]:
-----------------------------------------------------------------

Almost ready. I promise a quick review for the next one.

::: js/src/gc/Statistics.cpp
@@ +69,5 @@
> +
> +  public:
> +    enum Mode {
> +        AsJSON = true,
> +        AsString = false

Maybe call this AsText, since they're both really strings?

@@ +80,5 @@
> +    bool isJSON() { return asJSON_; }
> +
> +    bool isOOM() { return oom_; }
> +
> +    void resetCommaState() { needComma_ = false; }

It would be nice if this didn't have to be public. And if you can remove the one outside use, as I commented on later, then you should be able to remove this method.

@@ +152,5 @@
> +
> +        size_t nchars = strlen(buf);
> +        jschar *out = (jschar *)js_malloc(sizeof(jschar) * (nchars + 1));
> +        if (!out) {
> +            oom_ = true;

Need to free buf here, as well as if the Inflate fails.

@@ +184,5 @@
> +             capacity - length > length / 4) ||
> +            capacity <= length)
> +        {
> +            size_t bytes = sizeof(char) * (length + 1);
> +            char *tmp = (char *)js_realloc(buf, bytes);

Why can't you just do buf_.append(0), and then return the result of extractRawBuffer?

@@ +215,5 @@
> +        if (!buf_.growByUninitialized(cstrlen)) {
> +            oom_ = true;
> +            return;
> +        }
> +        strncpy(buf_.begin() + lengthBefore, cstr, cstrlen);

I realized that append can take a pointer and a length. So you should just be able to do the following:
  if (!buf_.append(cstr, cstrlen)) {
    oom_ = true;
    return;
  }

@@ +227,5 @@
> +        if (!buf_.growByUninitialized(1)) {
> +            oom_ = true;
> +            return;
> +        }
> +        *(buf_.begin() + lengthBefore) = c;

Better just to use append here, since it's only one character.

@@ +257,5 @@
> +        pJSON("\"");
> +    }
> +
> +    bool isblank(char c) {
> +        return 

?

@@ +267,5 @@
> +            return;
> +        }
> +
> +        p("\"");
> +        char *c = const_cast<char *>(str);

Why not just declare c as a const char * and get rid of the cast?

@@ +279,5 @@
> +            else if (*c == '+')
> +                p("added_");
> +            else if (*c == '-')
> +                p("removed_");
> +            else

Can you change this to (*c != '(' && *c != ')') and get rid of the earlier branch?

@@ +351,5 @@
> +    if (slices.length() > 1 || ss.isJSON())
> +        ss.appendNumber("Max Pause", "%.1f", "ms", t(longest));
> +    else
> +        ss.appendString("Reason", ExplainReason(slices[0].reason));
> +    ss.appendString("Nonincremental Reason", nonincrementalReason ? nonincrementalReason : "none");

Can you guard this line by |if (nonincrementalReason || ss.isJSON())| ?

@@ +377,4 @@
>              if (slices[i].resetReason)
> +                ss.appendString("Reset", slices[i].resetReason);
> +            if (!ss.isJSON())
> +                ss.resetCommaState();

Won't the extra call below already do resetCommaState?

@@ +444,5 @@
>      if (fp) {
>          if (fullFormat) {
> +            StatisticsSerializer ss(StatisticsSerializer::AsString);
> +            formatPhases(ss, "", phaseTotals);
> +            char *msg = ss.finishCString();

I still would rather have a NULL check here for msg. We're just asking for future bugs otherwise. Same below.
Comment 52 Terrence Cole [:terrence] 2012-03-12 17:17:21 PDT
Created attachment 605237 [details] [diff] [review]
v8: With review feedback applied.

(In reply to Bill McCloskey (:billm) from comment #51)
> @@ +80,5 @@
> > +    bool isJSON() { return asJSON_; }
> > +
> > +    bool isOOM() { return oom_; }
> > +
> > +    void resetCommaState() { needComma_ = false; }
> 
> It would be nice if this didn't have to be public. And if you can remove the
> one outside use, as I commented on later, then you should be able to remove
> this method.

|extra()| did not originally reset the comma state.  It looks like I just missed this one when updating it.  I've completely removed the resetCommaState method now.
 
> @@ +152,5 @@
> > +
> > +        size_t nchars = strlen(buf);
> > +        jschar *out = (jschar *)js_malloc(sizeof(jschar) * (nchars + 1));
> > +        if (!out) {
> > +            oom_ = true;
> 
> Need to free buf here, as well as if the Inflate fails.

Good catch.  I think we need to free |buf| even if the Inflate succeeds?
 
> @@ +184,5 @@
> > +             capacity - length > length / 4) ||
> > +            capacity <= length)
> > +        {
> > +            size_t bytes = sizeof(char) * (length + 1);
> > +            char *tmp = (char *)js_realloc(buf, bytes);
> 
> Why can't you just do buf_.append(0), and then return the result of
> extractRawBuffer?

No idea.  I cargo-culted it (and the two |p()| methods) in from StringBuffer, since I couldn't use it directly.  Rewriting these as you suggested seems to work fine.

> @@ +257,5 @@
> > +        pJSON("\"");
> > +    }
> > +
> > +    bool isblank(char c) {
> > +        return 
> 
> ?

/me makes note to save *before* qreffing, rather than after.
Comment 53 Bill McCloskey (:billm) 2012-03-12 17:36:11 PDT
Comment on attachment 605237 [details] [diff] [review]
v8: With review feedback applied.

Review of attachment 605237 [details] [diff] [review]:
-----------------------------------------------------------------

Looks great. Thanks.

::: js/src/gc/Statistics.cpp
@@ +172,5 @@
> +    char *finishCString() {
> +        if (oom_)
> +            return NULL;
> +
> +        buf_.append('\0');

Extra line after this one, please.

@@ +320,5 @@
> +    if (slices.length() > 1 || ss.isJSON())
> +        ss.appendNumber("Max Pause", "%.1f", "ms", t(longest));
> +    else
> +        ss.appendString("Reason", ExplainReason(slices[0].reason));
> +    if (nonincrementalReason || ss.isJSON())

Braces here, since it's a multi-line conditional.
Comment 54 Terrence Cole [:terrence] 2012-03-13 10:16:46 PDT
http://hg.mozilla.org/integration/mozilla-inbound/rev/4fa4374cf9de
Comment 55 Ed Morley [:emorley] 2012-03-14 14:40:06 PDT
https://hg.mozilla.org/mozilla-central/rev/4fa4374cf9de
Comment 56 Terrence Cole [:terrence] 2012-03-14 15:11:49 PDT
Created attachment 605977 [details] [diff] [review]
Use the new API in memchaser.

This is the patch I used to memchaser to test that the new API works.
Comment 57 Terrence Cole [:terrence] 2012-03-16 12:06:55 PDT
Created attachment 606666 [details] [diff] [review]
v1: With full support for older and newer browsers.

This version should apply cleanly against memchaser head.  It uses the new observer api where available and the older parsing method in older browsers.
Comment 58 Bill McCloskey (:billm) 2012-03-16 16:18:43 PDT
Filed bug 736643 to add a timestamp.

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