Closed Bug 1514359 Opened 5 years ago Closed 5 years ago

Some network end markers are only present in the content process but not in the parent process

Categories

(Core :: Gecko Profiler, defect, P3)

defect

Tracking

()

RESOLVED FIXED
mozilla66
Tracking Status
firefox66 --- fixed

People

(Reporter: mstange, Assigned: jesup)

References

Details

Attachments

(1 file)

Here's a profile captured in automation: https://perfht.ml/2Li3cnZ
I filtered it to only show markers of load 380. For this load, the content process has both a start marker and an end marker. However, the parent process only has a start marker, and *no end marker*. Is this expected?

Here's the marker JSON for the three markers, obtained using the context menu item "Copy marker JSON":

Start marker in the parent process:
> {
>   "start": 64606.736205,
>   "dur": 0.07666099999914877,
>   "name": "Load 380: https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>   "data": {
>     "status": "STATUS_START",
>     "cache": "Unresolved",
>     "pri": 10,
>     "URI": "https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>     "startTime": 64606.736205,
>     "endTime": 64606.812866,
>     "type": "Network",
>     "id": 7413113553276
>   },
>   "title": null
> }

Start marker in the content process:
> {
>   "start": 64606.31028120312,
>   "dur": 0.07805500000540633,
>   "name": "Load 380: https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>   "data": {
>     "status": "STATUS_START",
>     "pri": 10,
>     "URI": "https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>     "startTime": 64606.31028120312,
>     "endTime": 64606.38833620313,
>     "type": "Network",
>     "id": 7413113553276
>   },
>   "title": null
> }

End marker in the content process:
> {
>   "start": 64606.38833620313,
>   "dur": 233.91484299999865,
>   "name": "Load 380: https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>   "data": {
>     "status": "STATUS_STOP",
>     "pri": 10,
>     "URI": "https://images-na.ssl-images-amazon.com/images/G/01/temp/SSD/generic/SSD_Flyout._CB473537180_.png",
>     "startTime": 64606.38833620313,
>     "endTime": 64840.303179203125,
>     "type": "Network",
>     "id": 7413113553276
>   },
>   "title": null
> }
Actually, is it possible that we're missing end markers in the parent process for all requests that were served from the cache?

If I select the parent process and execute the following on the console, all results have either "Missed" or "MissedViaReval" in their cache property:

filteredThread.markers.data.filter(d => d && d.type === 'Network' && d.status !== 'STATUS_START')
new Set(filteredThread.markers.data.filter(d => d && d.type === 'Network' && d.status !== 'STATUS_START').map(d => d.cache))
Blocks: 1453387
(In reply to Markus Stange [:mstange] from comment #1)
> Actually, is it possible that we're missing end markers in the parent
> process for all requests that were served from the cache?

Where is the stop marker captured?

> 
> If I select the parent process and execute the following on the console, all
> results have either "Missed" or "MissedViaReval" in their cache property:
> 
> filteredThread.markers.data.filter(d => d && d.type === 'Network' &&
> d.status !== 'STATUS_START')
(In reply to Honza Bambas (:mayhemer) from comment #3)
> (In reply to Markus Stange [:mstange] from comment #1)
> > Actually, is it possible that we're missing end markers in the parent
> > process for all requests that were served from the cache?
> 
> Where is the stop marker captured?

In nsHttpChannel::OnStopRequest and in HttpChannelChild::OnStopRequest:

https://searchfox.org/mozilla-central/rev/47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/nsHttpChannel.cpp#7325
https://searchfox.org/mozilla-central/rev/47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/HttpChannelChild.cpp#1081
(In reply to Markus Stange [:mstange] from comment #4)
> (In reply to Honza Bambas (:mayhemer) from comment #3)
> > (In reply to Markus Stange [:mstange] from comment #1)
> > > Actually, is it possible that we're missing end markers in the parent
> > > process for all requests that were served from the cache?
> > 
> > Where is the stop marker captured?
> 
> In nsHttpChannel::OnStopRequest and in HttpChannelChild::OnStopRequest:
> 
> https://searchfox.org/mozilla-central/rev/
> 47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/nsHttpChannel.
> cpp#7325

It should be here:
[1] https://searchfox.org/mozilla-central/rev/47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/nsHttpChannel.cpp#7524

> https://searchfox.org/mozilla-central/rev/
> 47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/
> HttpChannelChild.cpp#1081

This one will trigger for all types of response processing.

I'm not sure how you are handling redirects, tho.  For a channel that receives (or sees a cached) 30X redirect response we don't get to [1].  The listener is carried over to the target channel, the source channel is cancelled.  This happens only if the redirect is not vetoed by the redirect-veto listeners and nothing else fails (like opening the target channel and number of other checks).
Note that [1] in the previous comment is the place we notify the target consumer (listener) of the channel on the parent process.  For content loads it's always HttpChannelParent that proxies the call to the child channel.

So, where exactly to put this marker depends on what is the exact definition of what you are trying to measure.
Randell, can you move the marker to the location that Honza suggested and answer the other questions?
Flags: needinfo?(rjesup)
> > > Where is the stop marker captured?
> > 
> > In nsHttpChannel::OnStopRequest and in HttpChannelChild::OnStopRequest:

> 
> It should be here:
> [1]
> https://searchfox.org/mozilla-central/rev/
> 47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/nsHttpChannel.
> cpp#7524

Ok, that seems to make sense.

> > https://searchfox.org/mozilla-central/rev/
> > 47edbd91c43db6229cf32d1fc4bae9b325b9e2d0/netwerk/protocol/http/
> > HttpChannelChild.cpp#1081
> 
> This one will trigger for all types of response processing.
> 
> I'm not sure how you are handling redirects, tho.  For a channel that
> receives (or sees a cached) 30X redirect response we don't get to [1].  The
> listener is carried over to the target channel, the source channel is
> cancelled.  This happens only if the redirect is not vetoed by the
> redirect-veto listeners and nothing else fails (like opening the target
> channel and number of other checks).

We want those to be just seen as a redirect marker with the same id, and then a stop (or another redirect), so the sequence is:
LOAD_START -> [ LOAD_REDIRECT ]* -> LOAD_STOP
All with the same ChannelID.

See line 5546 in nsHttpChannel.cpp (NetworkLoadType::LOAD_REDIRECT marker in ContinueProcessRedirectionAfterFallback()).
Should this handle everything if I move LOAD_STOP to [1]?

You can see exactly what we're doing in nsHttpChannel.cpp and HttpChannelChild.cpp looking for profiler_add_network_marker()
Flags: needinfo?(rjesup) → needinfo?(honzab.moz)
(In reply to Randell Jesup [:jesup] from comment #8)
> We want those to be just seen as a redirect marker with the same id, and
> then a stop (or another redirect), so the sequence is:
> LOAD_START -> [ LOAD_REDIRECT ]* -> LOAD_STOP
> All with the same ChannelID.
> 
> See line 5546 in nsHttpChannel.cpp (NetworkLoadType::LOAD_REDIRECT marker in
> ContinueProcessRedirectionAfterFallback()).
> Should this handle everything if I move LOAD_STOP to [1]?

Yes.

Then, I think redirect at [2] deserves a marker as well.  There are extensions that intercept channels and redirects w/o your knowledge, IIUC.

Then I'm not sure how you are handling the ChannelId property, but it seems that the code at [3] should move somewhere to the method at [4] and become more universal, also for proxy fail-over and various cases we do redirect internally to the same URI.

[2] https://searchfox.org/mozilla-central/rev/13788edbabb04d004e4a1ceff41d4de68a8320a2/netwerk/protocol/http/nsHttpChannel.cpp#2806
[3] https://searchfox.org/mozilla-central/rev/13788edbabb04d004e4a1ceff41d4de68a8320a2/netwerk/protocol/http/HttpChannelChild.cpp#1686-1692
[4] https://searchfox.org/mozilla-central/rev/13788edbabb04d004e4a1ceff41d4de68a8320a2/netwerk/protocol/http/HttpBaseChannel.cpp#3375
Flags: needinfo?(honzab.moz)
Priority: -- → P3
Assignee: nobody → rjesup
Status: NEW → ASSIGNED
Comment on attachment 9036610 [details] [diff] [review]
create network marker for end-of-load in correct spot

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

yep, this is the right place.

https://bugzilla.mozilla.org/show_bug.cgi?id=1514359#c9 in a different bug/patch?
Attachment #9036610 - Flags: review?(honzab.moz) → review+
Pushed by rjesup@wgate.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ded17dffa465
create network marker for end-of-load in correct spot r=mayhemer
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
You need to log in before you can comment on or make changes to this bug.