1541360 - It seems like we miss network markers on the parent process

Status: NEW

(Core :: Gecko Profiler, defect, P2)

Description

[Julien Wajsberg [:julienw]]

Here is a profile of loading CNN I just took with latest nightly: https://perfht.ml/2TQ9DB9.

We can clearly see that the requests are much different in the parent process vs the content process. Upon investigating closer, I see that this is because we miss either the start or end marker of normally pairs of network markers.

Here you can see the same profile in my WIP patch, where unmatched end/start markers respectively expand the merged marker to the start or end of the profile: https://deploy-preview-1917--perf-html.netlify.com/public/52d5d452191340ab79ac92b519bcac4479fc3ab9/network-chart/?globalTrackOrder=0-1-2-3&thread=0&v=3

We see clearly that there's a problem :-)

Edit: that profile was actually from a old version of Firefox where there were problems that got fixed since then. I don't see problems on CNN with current versions of Firefox, see: https://deploy-preview-1917--perf-html.netlify.com/public/3fb3aa86029eb7cb83cc9da927c94ff50b64b02f/network-chart/?globalTrackOrder=0-1-2-3-4-5&hiddenGlobalTracks=1-2-3-4&localTrackOrderByPid=5569-1-2-0~28406-0~28080-0~28189-0~28136-0~28181-0-1~&profileName=&thread=0&v=3
But I think there are problems for other websites, see other comments.

Comment 1

[Julien Wajsberg [:julienw]]

We can especially look at the file menu_money.png and compare their markers between profiles.

I realize that in perf.html we rely on the "name" and not the "ID" to match markers. And we don't expose the "ID" in the tooltip either which makes it more difficult to debug. I'll investigate more about that.

Comment 2

[Julien Wajsberg [:julienw]]

Other cases exhibiting the same problem:

• nytimes.com: https://deploy-preview-1917--perf-html.netlify.com/public/c157b2773f2da0fee910bd8b51a9a69c483348ad/network-chart/?globalTrackOrder=0-1-2-3-4-5-6-7-8-9&hiddenGlobalTracks=2-3-4-5-6-7-8&thread=0&v=3
• lemonde.fr: https://deploy-preview-1917--perf-html.netlify.com/public/49b82737e16b5adedafe6bd87cdd4553d3d8c14d/network-chart/?globalTrackOrder=0-1-2-3-4-5-6-7-8-9-10&hiddenGlobalTracks=1-2-3-4-5-6-7-8-9&thread=11&v=3

This one is fine:

• linuxfr.org https://deploy-preview-1917--perf-html.netlify.com/public/4b44dfe73ab00686d70fbbf2a1dd5f7eb06b4514/network-chart/?globalTrackOrder=0-1-2-3-4-5-6-7-8-9-10&hiddenGlobalTracks=1-2-4-5-6-7-8-10&thread=10&v=3

My current theory is that it's related to the use of network-first service workers. I don't see the problem with the offline-first service worker in the profiler.

Comment 3

[Julien Wajsberg [:julienw]]

I see the problem also on franceinter.fr: https://deploy-preview-1917--perf-html.netlify.com/public/82c7f2e3bc71f8d23cfd7d625073517bdb6133c7/network-chart/?globalTrackOrder=0-1-2-3-4-5-6-7-8-9-10&hiddenGlobalTracks=1-2-3-4-5-6-7-8-9&thread=11&v=3

This website doesn't seem to use a service worker, so my theory is likely wrong.

Comment 4

[Julien Wajsberg [:julienw]]

I realize that in perf.html we rely on the "name" and not the "ID" to match markers. And we don't expose the "ID" in the tooltip either which makes it more difficult to debug. I'll investigate more about that.

I didn't report on this: I checked that when the ID changes the name changes as well, so we should be OK on this side. It would still be probably cleaner to use the ID to match markers, but this isn't the source of the issue.

Comment 5

[Julien Wajsberg [:julienw]]

france.tv: https://profiler.firefox.com/public/27881954670815a9c855b7675d1741833f02f459/network-chart/?globalTrackOrder=0-1&localTrackOrderByPid=3164-1-2-0~20424-0-1~&thread=2&v=3

Looking at network markers for facebook or google analytics (and others) we definitely see a discrepancy between the parent process (where some of these markers aren't finished) and the child process (that looks ok).

Hey Randell, is it something you could try to look at as well? Thanks!

Comment 6

[Julien Wajsberg [:julienw]]

Setting to P2 for our very own definition that "we're lying to the user".

Comment 7

[Julien Wajsberg [:julienw]]

NI me to check what's missing here.

Comment 8

[Julien Wajsberg [:julienw]]

I tried again various use cases here.

I found problems in:

1. franceinter.fr, especially when force-reloading it.

-> problems in the parent process, for favicon.ico and touch-icon-192x192.png => https://perfht.ml/31wF2yg
There are 2 requests for each, one of them only has a "start" marker. So clearly something is incorrect here.
Interestingly the content process also has 2 requests for each, but they are complete... yet something seems incorrect too, because the second request starts right after the first one ends. => https://perfht.ml/2u8YBAv

In the network panel from the Browser Toolbox, I can see only 1 request for each URL.

-> also problems in the parent process only about subdocument (frames) called container.html where we miss the end marker => https://perfht.ml/2OrheGO
Note you need tracking protection disabled to see those.
According to the Browser toolbox' network panel, these requests are cached in this case. Also they look OK in the content process.
I see very similar problems on the nytimes site => https://perfht.ml/3b9CdYf

2. On france.tv, I see this on a normal warm load of the page (ie: it was already loaded, I go to the location bar, and press enter) => https://perfht.ml/2GW0ByJ
   One of the request is duplicated in the parent process, one of them doesn't have the end marker.
   In the content process it looks good.

Hey Honza, does that ring any bell?

Comment 9

[Honza Bambas (:mayhemer)]

According to the Browser toolbox' network panel, these requests are cached in this case.

Can you explain what exactly you mean with this? the netpanel never shows cacheability, it only shows if we have loaded the resource from the cache or not. Did you mean the latter?

I looked only at the container.html problem. Tried to repro locally, hard to say what happens:

• turned off tracking protection altogether
• cleared HTTP cache
• loaded franceinter.fr (from a tile)
• let it load (takes so looong!)
• ctrl-F5
• let load again (slooow!)
• exit

looking at the produced log, there are two requests per page load for the https://tpc.googlesyndication.com/safeframe/1-0-37/html/container.html resource, they are always cancelled on the child process, mostly at random time. Not sure if that has anything to do with the missing markers.

I think we are simply missing a common "channel has ended" point you can observe or take a marker at. Wasn't this discussed in Berlin?

Next time you are providing profiles like this to me to look at, please add nsHttp:5 MOZ_LOG in it or along it (at least).

Comment 10

[Julien Wajsberg [:julienw]]

Can you explain what exactly you mean with this? the netpanel never shows cacheability, it only shows if we have loaded the resource from the cache or not. Did you mean the latter?

Yes, exactly. Sorry for the confusion!

I think we are simply missing a common "channel has ended" point you can observe or take a marker at. Wasn't this discussed in Berlin?

I don't think we discussed that.
Short-term I think we miss an end point for requests that were aborted.
Longer term having this point "channel ended" (for all sorts of ends) could be useful, when we'll want to add markers for each phase.

Next time you are providing profiles like this to me to look at, please add nsHttp:5 MOZ_LOG in it or along it (at least).

Sure. I knew it before too, just forgot, sorry about that.