Bug 38831 – Web Inspector: WebSocket in Timeline tab

• Component: Web Inspector (Deprecated)
• Status: RESOLVED INVALID

[Yuta Kitamura]

Add WebSocket-related events in the Timeline tab.

This is a child bug of bug 34565.

[Yuta Kitamura]

Created attachment 55522 [details]
Screenshot of prototype implementation

At this moment, I have prototype implementation (screenshot attached).

The code is not ready for review yet (needs many clean-ups). What I did was basically adding functions for WebSocket events to InspectorTimelineAgent and making a few changes to the front-end scripts.

My current concerns are:
- Which event category is suitable for these events? "Loading" sounds possible but WebSocket communication is a bit different from loading regular resources.
- Do I need to modify event hierarchy (like regular resource loads are doing)?

Any suggestions are welcome.

[Joseph Pecoraro]

Neat. Do you have a sample WebSocket application somewhere you're testing with (I see localhost)?

[Yuta Kitamura]

(In reply to comment #2)
> Neat. Do you have a sample WebSocket application somewhere you're testing with (I see localhost)?

I ran WebSocket layout tests.

To try it, run the server first:
$ WebKitTools/Scripts/run-webkit-websocketserver

Then open http://localhost:8880/websocket/tests/ and pick any test you like (I used simple.html).

[Yuta Kitamura]

(In reply to comment #1)
> My current concerns are:
> - Which event category is suitable for these events? "Loading" sounds possible but WebSocket communication is a bit different from loading regular resources.
> - Do I need to modify event hierarchy (like regular resource loads are doing)?

One more concern:
- How to write tests?

[Fumitoshi Ukai]

Looks good!

Have several comments:
- can we have one row for "Create WebSocket", "Send WebSocketHandshake" and "Receive WebSocketHandshake"?
  I think "Create WebSocket" to "Send WebSocketHandshake" is almost atomic in script execution context.  Isn't it?
  And, we could put opening websocket in one row, as resource loading, such as a row of "Send Request (js-test-style.css)".

- I think we should use Event, rather than Function Call.
  For instance, Event(open), Event(message), Event(close), istead of Function Call (simple.js:19), ..

- Do we need "Receive WebSocket Message"?

- I believe we'll have "Send WebSocket Message".

- IMO, We might want to categorize handshaking in "Loading", and other activities (events, send, close) in "Scripting".

[Yuta Kitamura]

(In reply to comment #5)
> Looks good!
> 
> Have several comments:
> - can we have one row for "Create WebSocket", "Send WebSocketHandshake" and "Receive WebSocketHandshake"?
>   I think "Create WebSocket" to "Send WebSocketHandshake" is almost atomic in script execution context.  Isn't it?

I don't think so, because after "Create WebSocket" the browser needs to wait establishment of TCP connection. There is a gap between "Create WebSocket" and "Send WebSocket Handshake" (about 20ms or so) probably because of this reason, which will help developers to analyze latency.

I also think having both entries helps distinguishing TCP connection failure and WebSocket handshake failure.

>   And, we could put opening websocket in one row, as resource loading, such as a row of "Send Request (js-test-style.css)".

Yes, this issue is on my radar (second concern in comment #1).

> 
> - I think we should use Event, rather than Function Call.
>   For instance, Event(open), Event(message), Event(close), istead of Function Call (simple.js:19), ..

Web Inspector is already able to put "Function Call" lines. This is not what I added, and probably not easy to change. Sorry for my misleading screenshot.

> 
> - Do we need "Receive WebSocket Message"?

I think so, why not?

Understanding when messages are sent or received should help developers to debug their application.

In my current implementation, no information about message frames (message length or (possibly) message itself) is captured. It's fairly easy to add that info to pop-ups.

> 
> - I believe we'll have "Send WebSocket Message".

I already have implemented this message, but when I took the screenshot I happened to choose the (inappropriate) test which did not send any WebSocket messages. The event just didn't occur.

> 
> - IMO, We might want to categorize handshaking in "Loading", and other activities (events, send, close) in "Scripting".

Sounds reasonable to me.

[Yuta Kitamura]

Created attachment 55527 [details]
Screenshot of prototype implementation (updated)

Update the screenshot to clarify what I did. It also contains "Send WebSocket Message" events.

[Fumitoshi Ukai]

> > Have several comments:
> > - can we have one row for "Create WebSocket", "Send WebSocketHandshake" and "Receive WebSocketHandshake"?
> >   I think "Create WebSocket" to "Send WebSocketHandshake" is almost atomic in script execution context.  Isn't it?
> 
> I don't think so, because after "Create WebSocket" the browser needs to wait establishment of TCP connection. There is a gap between "Create WebSocket" and "Send WebSocket Handshake" (about 20ms or so) probably because of this reason, which will help developers to analyze latency.

Hmm, I see.  But I think we can collapse "opening websocket" in one row (from "new WebSocket()" to "open" event).  The row could be expanded into more detail rows.
I think "Send Request" for resource already do this.


> > - I think we should use Event, rather than Function Call.
> >   For instance, Event(open), Event(message), Event(close), istead of Function Call (simple.js:19), ..
> 
> Web Inspector is already able to put "Function Call" lines. This is not what I added, and probably not easy to change. Sorry for my misleading screenshot.

My point is "Function Call" should be a child of "Event". 
I think other events, such as keydown, do this.

> > - Do we need "Receive WebSocket Message"?
> 
> I think so, why not?
> 
> Understanding when messages are sent or received should help developers to debug their application.
> 
> In my current implementation, no information about message frames (message length or (possibly) message itself) is captured. It's fairly easy to add that info to pop-ups.

I'm wondering what is trying to capture "Receive WebSocket Message".  Is this different from Event(message) or Event(error) ?

> > - I believe we'll have "Send WebSocket Message".
> 
> I already have implemented this message, but when I took the screenshot I happened to choose the (inappropriate) test which did not send any WebSocket messages. The event just didn't occur.

Can we get info (for example, websocket url?) for these rows (send, close, and events)?

[Pavel Feldman]

Here are the guidelines you should follow when adding instrumentation into the timeline:

- Synchronous events (the ones that have start and end, consuming cpu in between) should make pairs of calls willDoSomething and didDoSomething and result in a solid bar on timeline.
- Asynchronous events, the ones sending network requests and such should make atomic calls to didSomething

Now the interesting part. We now consider timeline a causation analysis tool, so all of the events related to a single socket should fall under a single root record (Create Web Socket in your case). Based on the methods above and socket ids, you should manually bind the events on the front-end side (as it is done with regular resources and timers). Adding loislo who should be able to give you the hints on how to achieve that.

[Yuta Kitamura]

(In reply to comment #8)
> Hmm, I see.  But I think we can collapse "opening websocket" in one row (from "new WebSocket()" to "open" event).  The row could be expanded into more detail rows.
> I think "Send Request" for resource already do this.
> 

I'd like to put all events of the same WebSocket under the "Create WebSocket" event, as Pavel suggests. This is symmetric to regular resource loading, too.

> 
> My point is "Function Call" should be a child of "Event". 
> I think other events, such as keydown, do this.
>

I don't have any idea about how event hierarchy is constructed for DOM events. I'll investigate.
 
> I'm wondering what is trying to capture "Receive WebSocket Message".  Is this different from Event(message) or Event(error) ?

OK, I think I understand the problem correctly this time.

Current WebSocket events are captured in member functions of WebSocketChannel:
- Create WebSocket -> WebSocketChannel constructor
- Send WebSocket Handshake Request -> didOpen()
- Receive WebSocket Handshake Response -> didReceiveData()
- Send WebSocket Message -> send()
- Receive WebSocket Message -> receive()
- Close WebSocket -> close() (closed by client) and didClose() (closed by server)

In other words, my implementation does not capture any events from WebSocket DOM objects.

These events can be (roughly) mapped to WebSocket events (onopen, onmessage, onerror, onclose):
- Receive WebSocket Handshake Response -> onopen event
- Receive WebSocket Message -> onmessage event (and possibly onerror; my current implementation does not report errors)
- Close WebSocket -> onclose event
- Send WebSocket Message -> send() method call

I think this is a problem of the style of how to present the events to users (channel-based events vs DOM events). Channel-based style looks like regular resource loading (Send Request/Receive Response/Receive Data), while DOM events are close to what developers observe.

I'm wondering which is better. Showing both might also be possible, but it could be too redundant.

> 
> > > - I believe we'll have "Send WebSocket Message".
> > 
> > I already have implemented this message, but when I took the screenshot I happened to choose the (inappropriate) test which did not send any WebSocket messages. The event just didn't occur.
> 
> Can we get info (for example, websocket url?) for these rows (send, close, and events)?

Yes. In theory, we can put any data in pop-ups.

[Yuta Kitamura]

Thank you for your comment!

(In reply to comment #9)
> Here are the guidelines you should follow when adding instrumentation into the timeline:
> 
> - Synchronous events (the ones that have start and end, consuming cpu in between) should make pairs of calls willDoSomething and didDoSomething and result in a solid bar on timeline.
> - Asynchronous events, the ones sending network requests and such should make atomic calls to didSomething

In my current implementation, "Send WebSocket Handshake Request" and "Send WebSocket Message" use a pair of willDoSomething and didDoSomething. I guess this might be meaningless, however, because it just measures (extremely) the overhead of the "send" system call and other network utility methods. They are always about 2ms in my environment.

Other events only have didDoSomething.

> 
> Now the interesting part. We now consider timeline a causation analysis tool, so all of the events related to a single socket should fall under a single root record (Create Web Socket in your case). Based on the methods above and socket ids, you should manually bind the events on the front-end side (as it is done with regular resources and timers). Adding loislo who should be able to give you the hints on how to achieve that.

OK, sounds nice. I'll try to do it.

To my understanding, TimelinePanel._findParentRecord (in front-end/TimelinePanel.js) adjusts the event hierarchy. Am I right?

[Ilya Tikhonovsky]

(In reply to comment #11)
> Thank you for your comment!
> 
> (In reply to comment #9)
> > Here are the guidelines you should follow when adding instrumentation into the timeline:
> > 
> > - Synchronous events (the ones that have start and end, consuming cpu in between) should make pairs of calls willDoSomething and didDoSomething and result in a solid bar on timeline.
> > - Asynchronous events, the ones sending network requests and such should make atomic calls to didSomething
> 
> In my current implementation, "Send WebSocket Handshake Request" and "Send WebSocket Message" use a pair of willDoSomething and didDoSomething. I guess this might be meaningless, however, because it just measures (extremely) the overhead of the "send" system call and other network utility methods. They are always about 2ms in my environment.

The general idea to have will* and did* are the nesting events.

As I understand there is a chance that some JS callback method will be called when some data is received.
According to the idea it would be better to call willReceiveData before data processing and didReceiveData after. In that case you will get nested Function Call event automatically.

> 
> Other events only have didDoSomething.
> 
> > 
> > Now the interesting part. We now consider timeline a causation analysis tool, so all of the events related to a single socket should fall under a single root record (Create Web Socket in your case). Based on the methods above and socket ids, you should manually bind the events on the front-end side (as it is done with regular resources and timers). Adding loislo who should be able to give you the hints on how to achieve that.
> 
> OK, sounds nice. I'll try to do it.
> 
> To my understanding, TimelinePanel._findParentRecord (in front-end/TimelinePanel.js) adjusts the event hierarchy. Am I right?

Yes. 

Another small tip. I'm trying to put some useful info directly to the record details.
In some cases it is the url of resource, in the others it is the caller url or another helpful data.
You can extend _getRecordDetails record for that.

[Yuta Kitamura]

(In reply to comment #12)
> The general idea to have will* and did* are the nesting events.
> 
> As I understand there is a chance that some JS callback method will be called when some data is received.
> According to the idea it would be better to call willReceiveData before data processing and didReceiveData after. In that case you will get nested Function Call event automatically.

OK, I think I've got it. I'd like to try it.

> 
> Another small tip. I'm trying to put some useful info directly to the record details.
> In some cases it is the url of resource, in the others it is the caller url or another helpful data.
> You can extend _getRecordDetails record for that.

I'll look into it later. Thank you!

[Yuta Kitamura]

Created attachment 55962 [details]
Screenshot of prototype v2

I've updated my prototype and addressed many issues raised above. Here's an updated screenshot.

Some visible changes:
- Loading events and script events are distinguished.
  - Loading events are: "Open WebSocket", "Send WebSocket Handshake", "Receive WebSocket Handshake", and "Destroy WebSocket".
  - Script events are: "Open WebSocket" (onopen), "Send WebSocket Message" (send), "Receive WebSocket Message" (onmessage), "Receive WebSocket Error" (onerror), and "Close WebSocket" (onclose).

- Loading events has been organized so that they have the right hierarchy (like normal loading events).

- WebSocket events (onopen, etc.) are now timed correctly.

[Ilya Tikhonovsky]

As I can see there is some inconsistency between Create Web Socket event and it's caller.
Looks like Create Web Socket was enforced by send.js but corresponding Evaluate Script event is the next recorded event.
Probably you have used m_frontend->addRecordToTimeline instead of member function InspectorTimelineAgent::addRecordToTimeline
The first one is sending the data directly to the front-end. The second is tracking the stack of events.

Another thing is a causal relationship between Create WebSocket and Open WebSocket.
I think it would be better to append Open event as a child of Create event.

[Yuta Kitamura]

(In reply to comment #15)
> As I can see there is some inconsistency between Create Web Socket event and it's caller.
> Looks like Create Web Socket was enforced by send.js but corresponding Evaluate Script event is the next recorded event.
> Probably you have used m_frontend->addRecordToTimeline instead of member function InspectorTimelineAgent::addRecordToTimeline
> The first one is sending the data directly to the front-end. The second is tracking the stack of events.

Yes, I did that for "Create WebSocket" events but it was intentional; when I used InspectorTimelineAgent::addRecordToTimeline, a parent event of "Create WebSocket" (i.e. "Evaluate Script") got a awkwardly long timeline bar because loading events had long lifetime.

I tried to make WebSocket's loading events consistent with normal loading events: a "root" event of loading (i.e. "Send Request") becomes a first-level timeline event (a direct child of the root record), and other events are children of the root event. To my understanding, this is basically the same way how normal loading events are recorded. In fact, InspectorTimelineAgent::willSendResourceRequest calls m_frontend->addRecordToTimeline instead of InspectorTimelineAgent::addRecordToTimeline member function.

> 
> Another thing is a causal relationship between Create WebSocket and Open WebSocket.
> I think it would be better to append Open event as a child of Create event.

I understand the event names are confusing. Let me try to clarify:

- Script events (yellow bars) are JavaScript WebSocket events that invokes a callback of the JS object (if any). WebSocket.send() is also recorded and categorized into script events.
-- JS events are: onopen, onmessage, onerror, and onclose. These correspond to timeline event names.
- Script events have "normal" event relationships (stacked hierarchy).

- Loading events (blue bars) are related to backend connection. These are described above.
- Loading events do NOT obey the normal event relationships.

I hope my explanation helps. Suggestions of better event names are welcome.

[Yuta Kitamura]

Created attachment 56042 [details]
Patch FYI (not ready for formal review)

[Yuta Kitamura]

(In reply to comment #17)
> Created an attachment (id=56042) [details]
> Patch FYI (not ready for formal review)

I attached my current work. It's not ready for formal review process, but feel free to try, review and make comments.

I basically did:
- Define new record types,
- Add many member functions to InspectorTimelineAgent, each of which creates a timeline record,
- Add number of hooks to WebSocketChannel, and
- Fix TimelinePanel so that new records are shown nicely.

[Ilya Tikhonovsky]

(In reply to comment #16)

> Yes, I did that for "Create WebSocket" events but it was intentional; when I used InspectorTimelineAgent::addRecordToTimeline, a parent event of "Create WebSocket" (i.e. "Evaluate Script") got a awkwardly long timeline bar because loading events had long lifetime.

This is normal situation for Timeline. We want to show to the developer what happen if he click on item or just have included some javascript file into the page. 

He should be able to see that this script forced the browser to do some cpu or time expensive operations. 

Some time ago we decided that we want to group the entire chain of events under the initiator of the chain. http://webkit.org/blog/1091/more-web-inspector-updates/
The reason of that are the complex cases like Wave where thousands of events can be generated for a second.  Timeline with the plain list of events will be unusable in such cases.

> I tried to make WebSocket's loading events consistent with normal loading events: a "root" event of loading (i.e. "Send Request") becomes a first-level timeline event (a direct child of the root record), and other events are children of the root event. To my understanding, this is basically the same way how normal loading events are recorded. In fact, InspectorTimelineAgent::willSendResourceRequest calls m_frontend->addRecordToTimeline instead of InspectorTimelineAgent::addRecordToTimeline member function.

SendRequests are enforced by browser native code and usually we have no information about the initiator. But this week I've landed a patch for attaching some SendRequest records to the initiator. 

> 
> > 
> > Another thing is a causal relationship between Create WebSocket and Open WebSocket.
> > I think it would be better to append Open event as a child of Create event.
> 
> I understand the event names are confusing. Let me try to clarify:
> 
> - Script events (yellow bars) are JavaScript WebSocket events that invokes a callback of the JS object (if any). WebSocket.send() is also recorded and categorized into script events.
> -- JS events are: onopen, onmessage, onerror, and onclose. These correspond to timeline event names.
> - Script events have "normal" event relationships (stacked hierarchy).
> 
> - Loading events (blue bars) are related to backend connection. These are described above.
> - Loading events do NOT obey the normal event relationships.
> 
> I hope my explanation helps. Suggestions of better event names are welcome.

There is the same situation with the timers. One piece of code can setup a timer, another will be called when the timer fire. These two events will be recorded independently but TimerFire events will be inserted as children of TimerInstall at front-end side.

[Yuta Kitamura]

(In reply to comment #19)
> 
> SendRequests are enforced by browser native code and usually we have no information about the initiator. But this week I've landed a patch for attaching some SendRequest records to the initiator. 

OK, could you tell me the revision of your patch and how to reproduce that situation?

I will update the patch based on your comment next week.

[Ilya Tikhonovsky]

(In reply to comment #20)
> (In reply to comment #19)
> > 
> > SendRequests are enforced by browser native code and usually we have no information about the initiator. But this week I've landed a patch for attaching some SendRequest records to the initiator. 
> 
> OK, could you tell me the revision of your patch and how to reproduce that situation?
> 
> I will update the patch based on your comment next week.

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

[Yuta Kitamura]

Created attachment 56318 [details]
Screenshot of prototype v3

I think I addressed the issues raised by Ilya except for the relationship between "Create WebSocket" and "Open WebSocket" (comment #15).

"Open WebSocket" (onopen event handler callback), "Receive WebSocket Message" (onmessage), "Receive WebSocket Error" (onerror) and "Close WebSocket" (onclose) are event handlers which do not occur in any other event records. This means that these event records may be placed under the "Create WebSocket" record.

Only one exception is "Send WebSocket Message" event, which corresponds to a method call of send(). This cannot be put under the "Create WebSocket" record.

My current approach is to put loading (blue) records under the tree, and script (yellow) records outside the blue tree. Another possible approach is to put every record except "Send WebSocket Message" under the "Create WebSocket" record. I'm still wondering which is better.

[Fumitoshi Ukai]

(In reply to comment #22)
> Created an attachment (id=56318) [details]
> Screenshot of prototype v3

Looks good.

> I think I addressed the issues raised by Ilya except for the relationship between "Create WebSocket" and "Open WebSocket" (comment #15).
> 
> "Open WebSocket" (onopen event handler callback), "Receive WebSocket Message" (onmessage), "Receive WebSocket Error" (onerror) and "Close WebSocket" (onclose) are event handlers which do not occur in any other event records. This means that these event records may be placed under the "Create WebSocket" record.
> 
> Only one exception is "Send WebSocket Message" event, which corresponds to a method call of send(). This cannot be put under the "Create WebSocket" record.

What will correspond to a method call of close() ?

> My current approach is to put loading (blue) records under the tree, and script (yellow) records outside the blue tree. Another possible approach is to put every record except "Send WebSocket Message" under the "Create WebSocket" record. I'm still wondering which is better.

[Yuta Kitamura]

(In reply to comment #23)
> What will correspond to a method call of close() ?

Currently there's no event record corresponding to close(). Do you want it?

If we decide to add that event record, we need to change the names of event records. My current plan is:

    "Open WebSocket"            -> "WebSocket Event (open)"
    "Receive WebSocket Message" -> "WebSocket Event (message)"
    "Receive WebSocket Error"   -> "WebSocket Event (error)"
    "Close WebSocket"           -> "WebSocket Event (close)"
    "Send WebSocket Message"    -> (leave as is)
    (new event for close())     -> "Close WebSocket"

[Yuta Kitamura]

Sorry for not posting recent updates.

Currently I have a working patch, but it depends on other uncommitted patches (bug 38728, bug 39864). I'm waiting for these patches to be reviewed, and I cannot upload a patch for this issue until these patches are committed.

[Yuta Kitamura]

Created attachment 72911 [details]
Patch v1

[Fumitoshi Ukai]

Comment on attachment 72911 [details]
Patch v1

View in context: https://bugs.webkit.org/attachment.cgi?id=72911&action=review

> WebCore/websockets/WebSocketChannel.cpp:405
> +    if (m_identifier)

might need to check m_context is not NULL here?

> WebCore/websockets/WebSocketChannel.cpp:414
> +    if (m_identifier)

ditto

> WebCore/websockets/WebSocketChannel.cpp:423
> +    if (m_identifier)

ditto

[Yuta Kitamura]

Created attachment 73876 [details]
Patch v2: Fix comment #27

[Fumitoshi Ukai]

(In reply to comment #28)
> Created an attachment (id=73876) [details]
> Patch v2: Fix comment #27

LGTM

[Yuta Kitamura]

Created attachment 84535 [details]
Patch v2.1: Merge to trunk

[Yuta Kitamura]

The patch v2 was left unreviewed for a long time and cannot be applied to trunk (mainly because a lot of refactoring effort was made for inspector), so I updated the patch to match with trunk. I hope I can move forward...

[Eric Seidel (no email)]

Who can review this?  This has been up for over a month and a half.

[Adam Barth]

Comment on attachment 84535 [details]
Patch v2.1: Merge to trunk

Please renominate this patch for review if it's still relevant.

[pdeng6]

Why this patch is left for such a long time? 
I think it is a meaningful support for Web Socket. :)

[Eric Seidel (no email)]

There are over 500 patches up for review. :)  We just simply don't get to them all.  It's important to find an interested reviewer and work with them to reduce the chance of your patch being forgotten.

[pdeng6]

This work stopped for a long time, as talked with Toyoshima san, I will take this and move on. :)
I've opened #105227 to track WebSocket networking events support in Timeline, and #105228 to track the onopen, onerror, onmessage, onclose event handle support.
Thanks Kitamura san for previous work.

[Pavel Feldman]

I haven't seen anyone asking for it and given the amount of code it adds, I doubt we should land it.

[Pavel Feldman]

@caseq: the amount of instrumentation code we would need to add for such a task is bizarre. What can we do with timeline to ease this?

[Andrey Kosyakov]

(In reply to comment #38)
> @caseq: the amount of instrumentation code we would need to add for such a task is bizarre. What can we do with timeline to ease this?

Looks like trace event based insturmentation that we're current;y working on should address this.

[pdeng6]

(In reply to comment #39)
> (In reply to comment #38)
> > @caseq: the amount of instrumentation code we would need to add for such a task is bizarre. What can we do with timeline to ease this?
> 
> Looks like trace event based insturmentation that we're current;y working on should address this.

@caseq, do you mean the instrumentation code for Timeline will be Trace event based in future? I guess 
https://bugs.webkit.org/show_bug.cgi?id=105796 and https://bugs.webkit.org/show_bug.cgi?id=105851
may be related work, then how about platform other than chromium? :)

thanks
Pan

[Brian Burg]

Closing as invalid, as this bug pertains to the old inspector UI and/or its tests.
Please file a new bug (https://www.webkit.org/new-inspector-bug) if the bug/feature/issue is still relevant to WebKit trunk.