1490963 - ID of start / stop / redirect Network Tracing Markers do not match

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P1)

Description

[Ola Gasidlo [:ogasidlo] [:ola] OOO - please ping :ladybenko:]

We have a bug, where the load ids of tracing markers do not match (start && end marker).


Profile 1
--------
https://deploy-preview-1232--perf-html.netlify.com/public/667c87a4905824b0ee87dac2704bff7911fc27e6/network-chart/?globalTrackOrder=1-2-3-0-4&hiddenGlobalTracks=1-2-3&hiddenLocalTracksByPid=7373-1&localTrackOrderByPid=7373-0-1~14121-0~&thread=0&v=3

STR:
Main Thread > Network > search for `has` which will give you a start and end marker. > check tooltop && compare the load

Expected Result:
Content 4 of 4 as well as Main Thread show `Load: 130` as identifier of start and stop marker

Actual Result:
Start marker in Main Thread has `Load: 253`, others have `Load: 130`.


Profile 2
--------
https://deploy-preview-1232--perf-html.netlify.com/public/7889e7db9f3c8b94f654053569fb6e75da281b08/network-chart/?globalTrackOrder=0-1-2-3-4-5&hiddenGlobalTracks=2-4-1-3&hiddenLocalTracksByPid=29824-1&localTrackOrderByPid=29824-1-0~29831-0~&thread=6&v=3

same as above, search term `moment.`

Expected Result:
Content 5 of 5 and Main Thread show same identifier of start / stop / redirect marker

Actual Result:
--> Content 5 of 5: Start marker has `Load: 521`, Redirect & stop have `Load: 3345`
--> Main Thread: Stop and start `Load: 3345` AND 2 additional start markers with  `Load: 3343`  and `Load: 3329`


Reference @ github: https://github.com/devtools-html/perf.html/issues/1267


Code reference:
https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/netwerk/protocol/http/HttpChannelChild.cpp#1223

https://searchfox.org/mozilla-central/search?q=symbol:_ZN7mozilla3net15HttpBaseChannel12SetChannelIdEm%2C_ZN14nsIHttpChannel12SetChannelIdEm&redirect=false

Comment 1

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: net-markers.jpg

I am attaching a screenshot showing/comparing the tooltips from the Profile #1 test case:

Here are the IDs:
main thread: start: 253, stop: 130 
content (4 of 4): start: 130, stop: 130 

@Honza: the perf tool is generating the markers from HttpChannelChild.cpp using channelId as the marker Id.

See e.g. here:
https://searchfox.org/mozilla-central/rev/a23c3959b62cd3f616435e02810988ef5bac9031/netwerk/protocol/http/HttpChannelChild.cpp#2669

It's happening in:
- AsynOpen
- Redirect1Begin
- onStopRequest

Why start and stop channel ID's would be different?
In case of redirect new channels are created?

Honza

Comment 2

[Kershaw Chang [:kershaw]]

(In reply to Ola Gasidlo from comment #0)
> We have a bug, where the load ids of tracing markers do not match (start &&
> end marker).
> 
> 
> Profile 1
> --------
> https://deploy-preview-1232--perf-html.netlify.com/public/
> 667c87a4905824b0ee87dac2704bff7911fc27e6/network-chart/?globalTrackOrder=1-2-
> 3-0-4&hiddenGlobalTracks=1-2-3&hiddenLocalTracksByPid=7373-
> 1&localTrackOrderByPid=7373-0-1~14121-0~&thread=0&v=3
> 
> STR:
> Main Thread > Network > search for `has` which will give you a start and end
> marker. > check tooltop && compare the load
> 
> Expected Result:
> Content 4 of 4 as well as Main Thread show `Load: 130` as identifier of
> start and stop marker
> 
> Actual Result:
> Start marker in Main Thread has `Load: 253`, others have `Load: 130`.
> 
> 
> Profile 2
> --------
> https://deploy-preview-1232--perf-html.netlify.com/public/
> 7889e7db9f3c8b94f654053569fb6e75da281b08/network-chart/?globalTrackOrder=0-1-
> 2-3-4-5&hiddenGlobalTracks=2-4-1-3&hiddenLocalTracksByPid=29824-
> 1&localTrackOrderByPid=29824-1-0~29831-0~&thread=6&v=3
> 
> same as above, search term `moment.`
> 

I only take a look at profile 2.
In this case, the start marker 'Load: 521' is to load "http://cdnjs.cloudflare.com/ajax/libs/moment.js/1.7.2/moment.min.js". This load will be redirected to "https://cdnjs.cloudflare.com/ajax/libs/moment.js/1.7.2/moment.min.js".

> Expected Result:
> Content 5 of 5 and Main Thread show same identifier of start / stop /
> redirect marker
> 

The name "Content 5 of 5" and "Main Thread" are super confusing. I think "Content 5 of 5" means markers set in HttpChannelChild.cpp, which is in content process. And "Main Thread" means markers set in nsHttpChannel.cpp in chrome process.

When redirection is happening, I think you cannot expect the channel id to be the same. After all, "http://cdnjs.cloudflare.com/ajax/libs/moment.js/1.7.2/moment.min.js" and "https://cdnjs.cloudflare.com/ajax/libs/moment.js/1.7.2/moment.min.js" are actually two different loads.

> Actual Result:
> --> Content 5 of 5: Start marker has `Load: 521`, Redirect & stop have
> `Load: 3345`
> --> Main Thread: Stop and start `Load: 3345` AND 2 additional start markers
> with  `Load: 3343`  and `Load: 3329`
> 

I also found why we have two different ids in Main Thread. 
We should move the code in [1] from nsHttpChannel::Init to nsHttpChannel::AsyncOpen. The start marker is set too early. 


[1] https://searchfox.org/mozilla-central/rev/a23c3959b62cd3f616435e02810988ef5bac9031/netwerk/protocol/http/nsHttpChannel.cpp#403-412

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Make main-process network START markers match STOP markers

I only notice the mismatch on the Main Process -- and in fact, HttpChannelChild.cpp has the LOAD_START added in AsyncOpen already.  Looks better with this patch in the Main Process

Comment 4

[Kershaw Chang [:kershaw]]

Comment on attachment 9008859 [details] [diff] [review]
Make main-process network START markers match STOP markers

I'd like to ask Honza to review this.

Thanks.

Comment 5

[Honza Bambas (:mayhemer)]

Comment on attachment 9008859 [details] [diff] [review]
Make main-process network START markers match STOP markers

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

correct.  cause: init on the parent process will generate a new id using a counter that is parent process specific.  but later asyncOpen called from httpchannelparent will reassign the id to be the one that the related httpchannelchild instance got on the child process.  hence, the id will change between Init() and AsyncOpen().

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c6289939c72c
Make main-process network START markers match STOP markers r=mayhemer

Comment 7

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/c6289939c72c