Bug 37025 – Web Inspector: GC Run event should be added to Timeline Panel

• Status: RESOLVED
• Resolution: FIXED
• Component: Web Inspector (Deprecated)

[Ilya Tikhonovsky]

The JS code can be not optimal from memory usage point of view. As example generate a lot of garbage.
js engine will free that garbage and with GC Run event we will see information about this internal work of js engine.

[Ilya Tikhonovsky]

Created attachment 52489 [details]
Screenshot of Popup with Heap Size property.

[Ilya Tikhonovsky]

Created attachment 52490 [details]
Screenshot of GCRun event

[Ilya Tikhonovsky]

Created attachment 52491 [details]
[patch] Initial version.

GC Run event and heap usage info can be added to Safari.
The only thing required for that is a non empty implementation of GCEventHelper class methods in WebCore/bindings/js/GCEventHelper.h

1) new class GCEventHelper is introduced in bindings;
2) new type of events GCRun was added to Timeline;
3) minor changes in Timeline panel.

[Ilya Tikhonovsky]

patch has binary changes in localizedStrings.

[Timothy Hatcher]

Comment on attachment 52491 [details]
[patch] Initial version.

> +            recordContentTable.appendChild(this._createRow(WebInspector.UIString("Heap Size"), Number.bytesToString(this.usedHeapSize) + "(" + Number.bytesToString(this.totalHeapSize) + ")"));

Consider spliting there onto two lines, I didn't know what the two numbers where telling me until I looked at the patch. At least put a space befor the open paren " (".

[Timothy Hatcher]

To clarify, I mean split them in the UI not the code.

[Pavel Feldman]

Comment on attachment 52491 [details]
[patch] Initial version.

- GCEventHelper.* are missing in the patch.
- Files that abstract us from the engine should start with Script* in case they do not inherit common interface. It could be that ScriptDebugServer or ScriptController should have the new methods.

[Ilya Tikhonovsky]

Created attachment 52498 [details]
[patch] second iteration.

1) Used Heap Size and Total Heap Size properties were added instead of single Heap Size property;
2) GCEventHelper.* were renamed and added to the patch.

[Pavel Feldman]

Comment on attachment 52498 [details]
[patch] second iteration.

> +        static void pushCollectedGCEvents(InspectorTimelineAgent*) {}
> +        static void getHeapSize(size_t&, size_t&) {}

- The fact that same tests are passing for JSC and V8 with no instrumentation for JSC is confusing. What would WebKit user see in the UI?
- If we anyways create an instance of this ScriptGCEventHelper object, then these methods should probably be instance methods. In fact, I can see pushCollectedGCEvents being invoked on the instance already.
- Bi-directional dependency between InspectorTimelineAgent and ScriptGCEventHelper bothers me. In theory, it should exist: you query for heap size and push gc events (i.e. pass control both ways). But I can see that your push is not really a push - it is accumulating events and timeline is actually queryign for them. So there really is a TimelineAgent -> ScriptGCEventHelper dependency only.

> +        v8::V8::AddGCPrologueCallback(gcPrologueCallback);
> +        v8::V8::AddGCEpilogueCallback(gcEpilogueCallback);

How expensive is being a callback?

> +
> +void ScriptGCEventHelper::pushCollectedGCEvents(InspectorTimelineAgent* agent)
> +{
> +    if (s_gcRunEvents.size()) {
> +        for (GCRunEvents::iterator i = s_gcRunEvents.begin(); i != s_gcRunEvents.end(); ++i)
> +            agent->didGCRun(i->startTime, i->endTime, i->collectedBytes);
> +        s_gcRunEvents.clear();
> +    }

So you are polling for gc runs, not pushing them actually. So your GC events are not in line with other records time-wise. Is that a problem? Another thing is that you are polling for GC records in random places to my taste: on willSendResourceRequest, didFinishLoadingResource, addRecordToTimeline, pushCurrentRecord. I realize that it might be related to the helper method structure in the timeline agent, but I'd like to see it fixed since it really start looking random to me.
> +
> +namespace WebCore {
> +    class InspectorTimelineAgent;
> +

We should not indent class declarations according to new style.

FYI: some time ago we agreed that we should create jsc and v8 folders under WebCore/inspector where we would put things like ScriptGCEventHelper. Unlike bindings, in our case, they would share same interface header located under WebCore/inspector. You can be the first guy to do that. Or we will move these guys at once, so not a strict requirement to do it now.

[Ilya Tikhonovsky]

(In reply to comment #9)

>> +        static void pushCollectedGCEvents(InspectorTimelineAgent*) {}
>> +        static void getHeapSize(size_t&, size_t&) {}

> - The fact that same tests are passing for JSC and V8 with no instrumentation
> for JSC is confusing. What would WebKit user see in the UI?

The users will see standard popups without Heap Size info. Also GC Run event will not appear until somebody write an implementation of these methods for JSC. The usedHeapSize/totalHeapSize properties at frontend side are defined but zero in JSC case.

> - Bi-directional dependency between InspectorTimelineAgent and
> ScriptGCEventHelper bothers me. In theory, it should exist: you query for heap
> size and push gc events (i.e. pass control both ways). But I can see that your
> push is not really a push - it is accumulating events and timeline is actually
> queryign for them. So there really is a TimelineAgent -> ScriptGCEventHelper
> dependency only.

It is not possible to call TimelineAgent from GC directly but I can push GCRun events to the agent 
each time when agent ask GCEventHelper about HeapSize info.
In case of pull design scheme, the agent will have to know about internal structure of GCEventHelper.

>> +        v8::V8::AddGCPrologueCallback(gcPrologueCallback);
>> +        v8::V8::AddGCEpilogueCallback(gcEpilogueCallback);

> How expensive is being a callback?

These callbacks will be called once per garbage collector run if TimelineAgent is in operation.
Helper for V8 is using vector for events data. Usually it will be small constant time. 

> So you are polling for gc runs, not pushing them actually. So your GC events
> are not in line with other records time-wise. Is that a problem? Another thing
> is that you are polling for GC records in random places to my taste: on
> willSendResourceRequest, didFinishLoadingResource, addRecordToTimeline,
> pushCurrentRecord. I realize that it might be related to the helper method
> structure in the timeline agent, but I'd like to see it fixed since it really
> start looking random to me.

As far as GC run is happening more or less randomly I'm trying to push gc events into to timeline each time when TimelineAgent is called via will or did methods.
It is enough to do that at pushCurrentRecord and addRecordToTimeline but some events like SendRequest are propagating event record to the frontend directly.

> FYI: some time ago we agreed that we should create jsc and v8 folders under
> WebCore/inspector where we would put things like ScriptGCEventHelper. Unlike
> bindings, in our case, they would share same interface header located under
> WebCore/inspector. You can be the first guy to do that. Or we will move these
> guys at once, so not a strict requirement to do it now.

I think it is not so many chances to use JSC and V8 at the some time and there is no special reason to have an abstract class and implementation with virtual functions.

> (From update of attachment 52498 [details])
> > +        static void pushCollectedGCEvents(InspectorTimelineAgent*) {}
> > +        static void getHeapSize(size_t&, size_t&) {}
> 
> - The fact that same tests are passing for JSC and V8 with no instrumentation
> for JSC is confusing. What would WebKit user see in the UI?
> - If we anyways create an instance of this ScriptGCEventHelper object, then
> these methods should probably be instance methods. In fact, I can see
> pushCollectedGCEvents being invoked on the instance already.
> - Bi-directional dependency between InspectorTimelineAgent and
> ScriptGCEventHelper bothers me. In theory, it should exist: you query for heap
> size and push gc events (i.e. pass control both ways). But I can see that your
> push is not really a push - it is accumulating events and timeline is actually
> queryign for them. So there really is a TimelineAgent -> ScriptGCEventHelper
> dependency only.
> 
> > +        v8::V8::AddGCPrologueCallback(gcPrologueCallback);
> > +        v8::V8::AddGCEpilogueCallback(gcEpilogueCallback);
> 
> How expensive is being a callback?
> 
> > +
> > +void ScriptGCEventHelper::pushCollectedGCEvents(InspectorTimelineAgent* agent)
> > +{
> > +    if (s_gcRunEvents.size()) {
> > +        for (GCRunEvents::iterator i = s_gcRunEvents.begin(); i != s_gcRunEvents.end(); ++i)
> > +            agent->didGCRun(i->startTime, i->endTime, i->collectedBytes);
> > +        s_gcRunEvents.clear();
> > +    }
> 
> So you are polling for gc runs, not pushing them actually. So your GC events
> are not in line with other records time-wise. Is that a problem? Another thing
> is that you are polling for GC records in random places to my taste: on
> willSendResourceRequest, didFinishLoadingResource, addRecordToTimeline,
> pushCurrentRecord. I realize that it might be related to the helper method
> structure in the timeline agent, but I'd like to see it fixed since it really
> start looking random to me.
> > +
> > +namespace WebCore {
> > +    class InspectorTimelineAgent;
> > +
> 
> We should not indent class declarations according to new style.
> 
> FYI: some time ago we agreed that we should create jsc and v8 folders under
> WebCore/inspector where we would put things like ScriptGCEventHelper. Unlike
> bindings, in our case, they would share same interface header located under
> WebCore/inspector. You can be the first guy to do that. Or we will move these
> guys at once, so not a strict requirement to do it now.

[Pavel Feldman]

(In reply to comment #10)

> The users will see standard popups without Heap Size info. Also GC Run event
> will not appear until somebody write an implementation of these methods for
> JSC. The usedHeapSize/totalHeapSize properties at frontend side are defined but
> zero in JSC case.
>

Ok, sounds reasonable.
 
> It is not possible to call TimelineAgent from GC directly but I can push GCRun
> events to the agent 
> each time when agent ask GCEventHelper about HeapSize info.
> In case of pull design scheme, the agent will have to know about internal
> structure of GCEventHelper.
> 

It does not need to know about internal structure of GCEvenHelper in case you expose a GCRecord struct and return a vector of these in getGCRunRecords.

> As far as GC run is happening more or less randomly I'm trying to push gc
> events into to timeline each time when TimelineAgent is called via will or did
> methods.
> It is enough to do that at pushCurrentRecord and addRecordToTimeline but some
> events like SendRequest are propagating event record to the frontend directly.
> 

That's what I a talking about - there is no single place in the code that would allow  adding an instrumentation flavor (such as memory state) to each of the records. There should be a single generic method every record is going through, so that you could put your heap snapshotting there. Single place.

> I think it is not so many chances to use JSC and V8 at the some time and there
> is no special reason to have an abstract class and implementation with virtual
> functions.
> 

That's not about it. That's about knowing when you break v8 while editing jsc and such.

[Ilya Tikhonovsky]

Created attachment 52555 [details]
[patch] Third iteration.

1) GCRun events data container was moved from ScriptGCEventHelper to InspectorTimelineAgent;
2) all active Timeline agents will receive GCRun events data when GCRun event happen;
3) as far as we can't use ScriptObject when GC Run event happen TimelineAgent will use Vector to store GC Run event data
4) Bug with Epilogue/Prologue deregistration was fixed.

[Pavel Feldman]

Comment on attachment 52555 [details]
[patch] Third iteration.

Looks better, but bi-directional dependency is still there. Could you introduce a ScriptGCHelperListener (as ScriptDebugServerListener in WebCore/inspector) to resolve that?

Rest of the nits below. 


> +namespace WebCore {
> +class ScriptGCEventHelper
> +{

Ad blank line here.

> +public:
> +    ScriptGCEventHelper(InspectorTimelineAgent*){}
> +    static void getHeapSize(size_t&, size_t&) {}
> +};

Ad blank line here.

> +} // namespace WebCore

> +namespace WebCore {

Ad blank line here.

> +    static int s_helpersCounter;

I guess this one is no longer needed.

> -    : m_frontend(frontend)
> +    : m_frontend(frontend), m_gcEventHelper(this)

Move ", m_gcEventHelper" to the next line.

[Ilya Tikhonovsky]

Created attachment 52617 [details]
[patch] Fourth iteration.

obsolete counter was removed.
style was fixed.

[Ilya Tikhonovsky]

Created attachment 52621 [details]
[patch] Fifth iteration.

listener implementation.

[Pavel Feldman]

Comment on attachment 52621 [details]
[patch] Fifth iteration.

r- for iterating over original and for poor 'helper' name.

ScriptGCEventHelper is no longer a good name since you can't add listeners to the helper.

> +public:
> +    static void addEventListener(ScriptGCEventListener*){}
> +    static void removeEventListener(ScriptGCEventListener*){}
> +    static void getHeapSize(size_t&, size_t&){}

should be ") { }"

> +    double endTime = WTF::currentTimeMS();
> +    size_t collectedBytes = s_usedHeapSize - getUsedHeapSize();
> +    for (GCEventListeners::iterator i = s_eventListeners.begin(); i != s_eventListeners.end(); ++i)
> +        (*i)->didGCRun(s_startTime, endTime, collectedBytes);

You should iterate over copy in case client wants to unregister listener after the first event or something similar.

> +    typedef Vector< ScriptGCEventListener* > GCEventListeners;

Vector<ScriptGCEventListener*>

> +    virtual void didGCRun(double startTime, double endTime, size_t collectedBytes) = 0;

didGC?

[Ilya Tikhonovsky]

Created attachment 52629 [details]
[patch] Sixth iteration. :)

ScriptGCEventHelper was renamed to ScriptGCEvent;
GCRun was renamed to GCEvent;
Cometic coding style changes;
didGCRun was renamed to didGC,

[Pavel Feldman]

Comment on attachment 52629 [details]
[patch] Sixth iteration. :)

Nit: I'd use public inheritance here.

[Ilya Tikhonovsky]

Committing to http://svn.webkit.org/repository/webkit/trunk ...
	M	LayoutTests/ChangeLog
	M	LayoutTests/inspector/timeline-enum-stability-expected.txt
	M	LayoutTests/inspector/timeline-event-dispatch-expected.txt
	M	LayoutTests/inspector/timeline-layout-expected.txt
	M	LayoutTests/inspector/timeline-mark-timeline-expected.txt
	M	LayoutTests/inspector/timeline-network-resource-expected.txt
	M	LayoutTests/inspector/timeline-paint-expected.txt
	M	LayoutTests/inspector/timeline-parse-html-expected.txt
	M	LayoutTests/inspector/timeline-recalculate-styles-expected.txt
	M	LayoutTests/inspector/timeline-script-tag-1-expected.txt
	M	LayoutTests/inspector/timeline-script-tag-2-expected.txt
	M	LayoutTests/inspector/timeline-test.js
	M	LayoutTests/platform/chromium-win/inspector/timeline-event-dispatch-expected.txt
	M	LayoutTests/platform/chromium-win/inspector/timeline-mark-timeline-expected.txt
	M	LayoutTests/platform/chromium-win/inspector/timeline-network-resource-expected.txt
	M	LayoutTests/platform/chromium-win/inspector/timeline-paint-expected.txt
	M	LayoutTests/platform/chromium-win/inspector/timeline-parse-html-expected.txt
	M	WebCore/ChangeLog
	M	WebCore/English.lproj/localizedStrings.js
	M	WebCore/WebCore.gypi
	M	WebCore/WebCore.pro
	M	WebCore/inspector/InspectorTimelineAgent.cpp
	M	WebCore/inspector/InspectorTimelineAgent.h
	M	WebCore/inspector/TimelineRecordFactory.cpp
	M	WebCore/inspector/TimelineRecordFactory.h
	M	WebCore/inspector/front-end/Popover.js
	M	WebCore/inspector/front-end/TimelineAgent.js
	M	WebCore/inspector/front-end/TimelinePanel.js
Committed r57150

[WebKit Review Bot]

http://trac.webkit.org/changeset/57150 might have broken Chromium Linux Release

I have a bit of an issue with the way these GCEvents are represented in the event tree structure.

All nodes in the tree up until now represented a start and end time where the UI thread was blocked. Unless I am missing something, in situations where the GCEvent nests in the event tree (where it is not a top level event), the GCEvent's start and end times can sometimes overlap its peers in the event tree!

I have confirmed by looking at the data that you can have GCEvents that claim to happen between X to Y, and when in fact some other peer node claims to occupy times between X to Y. I would have to assume that in these situations, the GCEvent simply needs to be a child of this overlapping thing... or else these GCEvents should not be nodes at all.

This violates a fundamental property of the event tree datastructure. That is,

time in self for a node = my duration - duration of all my children.

If the timings that you are measuring all happen on the UI thread, then in order to maintain the sanity of the tree structure (non-overlapping peers), they need to be stuck to the appropriate parent node, or simply recorded as some kind of aggregate information on a node and not as a node itself.

It does not happen very often, but I managed to reproduce. Here is a snippet of the timeline record stream that demonstrates things coming out of order. Here we get a data received event, followed by two small GCEvents, and then an EvalScript event. The GC's here should be children of this EvalScript event, but they are not. They are top level and are actually emitted before the EvalScript event even though their timestamps indicate they come after:

{"data":{"identifier":22},"children":[],"type":16,"usedHeapSize":2962736,"totalHeapSize":5148672,"duration":1,"time":36294.000244140625,"sequence":1408}

{"data":{"usedHeapSizeDelta":1334504},"type":17,"usedHeapSize":8056076,"totalHeapSize":10981376,"duration":15,"time":36405.000244140625,"sequence":1409}

{"data":{"usedHeapSizeDelta":1058044},"type":17,"usedHeapSize":8064820,"totalHeapSize":10981376,"duration":2,"time":36423.000244140625,"sequence":1410}

{"data":{"url":"https://wave.google.com/a/google.com/static/F4CDD1840C43DA658FB4E6CC8625D245.cache.js","lineNumber":1},"children":[{"data":{"timerId":3,"timeout":50,"singleShot":false},"type":5,"usedHeapSize":6437768,"totalHeapSize":8245248,"time":36403.000244140625}],"type":10,"usedHeapSize":8070336,"totalHeapSize":10981376,"duration":131.999755859375,"time":36302.000244140625,"sequence":1411}

Out of order top level events are not so bad. But here we have some children of an HTML parse node that displays the same out of orderness, thus violating the self time property. We see a GCEvent come before an EvalScript event inside a node, when this GCEvent should really be a child of the EvalScript event, not its peer.:

"children":[
 {"data":{},"children":[],"type":2,"usedHeapSize":11760936,"totalHeapSize":14364672,"duration":0,"time":36647.000244140625},

 {"data":{"usedHeapSizeDelta":3969088},"type":17,"usedHeapSize":7986124,"totalHeapSize":17584128,"duration":21,"time":36649.000244140625},{"data":{"url":"https://wave.google.com/a/google.com/?pli=1","lineNumber":55},"children":[],"type":10,"usedHeapSize":7986264,"totalHeapSize":17584128,"duration":23.999755859375,"time":36647.000244140625}
]

I know how this happens. If ScriptGCEvent::gcEpilogueCallback() gets called AFTER the correct node's parent has already closed and popped from the record stack, then the GCEvents will incorrectly be attributed to the parent of the node that they should have been attributed to.

I am not sure what guarantees you have about V8 calling you back in time. It seems like sometimes it doesnt.

Sorry. I made a mistake in my diagnosis.

The problem is simpler.

InspectorTimelineAgent::didCompleteRecord() pops the record stack and then calls addRecordToTimeline()

addRecordToTimeline() pushes the GCEvents. This then attributes the GCEvents to whatever is currently last on the record stack. Too bad the real parent has already been popped :).

This means that the only time GCEvents are correctly parented are when they happen to get pushed by some other peer node closing BEFORE their parent tries to pop. This is the common case so the data looks mostly correct.

[Pavel Feldman]

Your findings are correct. Shortly speaking, GC events are never reported synchronously. The reason is that we can't run JavaScript code from within GC event, while front-end push is implemented using javascript code. All the calls into ScriptObject are JS calls in fact.

The only good way of handling this (and we've been considering it for a long time + it was the original implementation in Chromium downstream) is to use native structures in place of ScriptValue/Object/Array that would natively serialize into JSON. They are called Value in Chromium (see base/values.h). They can be serialized to JSON using not that much code: http://src.chromium.org/viewvc/chrome/trunk/src/base/json/json_writer.cc.  Unfortunately, json_reader.cc is much larger and more complex, but I think we could work out solution that does not require it - stuff will still be parsed in the js environment. I would do it all right away if I had resources.

(In reply to comment #24)
> Your findings are correct. Shortly speaking, GC events are never reported
> synchronously. The reason is that we can't run JavaScript code from within GC
> event, while front-end push is implemented using javascript code. All the calls
> into ScriptObject are JS calls in fact.
> 
> The only good way of handling this (and we've been considering it for a long
> time + it was the original implementation in Chromium downstream) is to use
> native structures in place of ScriptValue/Object/Array that would natively
> serialize into JSON. They are called Value in Chromium (see base/values.h).
> They can be serialized to JSON using not that much code:
> http://src.chromium.org/viewvc/chrome/trunk/src/base/json/json_writer.cc. 
> Unfortunately, json_reader.cc is much larger and more complex, but I think we
> could work out solution that does not require it - stuff will still be parsed
> in the js environment. I would do it all right away if I had resources.

I understand the not being able to send a record synchronously from the GC callback. But I am not certain that we need to in order to fix the wrong parent bug. I have a patch that I believe resolves the issue:

https://bugs.webkit.org/show_bug.cgi?id=37340