1325325 - Check HTTP_NET_VS_CACHE_*_REVALIDATED probes for correctness

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect)

Description

[Michal Novotny [:michal]]

We are probably doing something wrong when measuring time of revalidated requests because according to telemetry there is not a single report of cache being faster than network.

Comment 1

[Junior [inactive]]

I'm still digging this.
Most of the time are 304, but cache should still be faster most of the time.

Comment 2

[Junior [inactive]]

For a 304 revalidate case, nsHttpChannel will receive a onStart/StopReqeust for a 304,
 where we should not record the timestamp since it's not a success response.
Therefore, after the 304, we issue a ReadFromCache for the same AsyncOpen, 
and another pair of onStart/StopReqeust from cache comes.

Comment 3

[Junior [inactive]]

Attachment: avoid_record_304

Comment 4

[Michal Novotny [:michal]]

Comment on attachment 8826138 [details] [diff] [review]
avoid_record_304

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

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +6730,2 @@
>          if (request == mTransactionPump && mCacheEntry &&
> +            !mCachedContentIsValid &&

Shouldn't we use mDidReval instead?

This prevents rewriting stored times in the cache entry, but we still get wrong mOnStartRequestTimestamp. Now we use the time when we started to read the data from the cache, but we should use the earlier when we got the response from the server. I.e. we should prevent rewriting mOnStartRequestTimestamp in second nsHttpChannel::OnStartRequest call.

Comment 5

[Junior [inactive]]

(In reply to Michal Novotny (:michal) from comment #4)
> Comment on attachment 8826138 [details] [diff] [review]
> avoid_record_304
> 
> Review of attachment 8826138 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: netwerk/protocol/http/nsHttpChannel.cpp
> @@ +6730,2 @@
> >          if (request == mTransactionPump && mCacheEntry &&
> > +            !mCachedContentIsValid &&
> 
> Shouldn't we use mDidReval instead?
> 
I'm worried about the custom conditional request, since it does *not* set mDidReval = true.
But we can deal with it in Bug 1331324 and use mDidReval first.

> This prevents rewriting stored times in the cache entry, but we still get
> wrong mOnStartRequestTimestamp. Now we use the time when we started to read
> the data from the cache, but we should use the earlier when we got the
> response from the server. I.e. we should prevent rewriting
> mOnStartRequestTimestamp in second nsHttpChannel::OnStartRequest call.

I'm wondering why we should prevent rewriting mOnStartRequestTimestamp.

We want to measure the time between AsynOpen and mListener->OnStartRequest,
and we propagate the OnStartRequest to mListener in |nsHttpChannel::CallOnStartRequest|
which is triggered by mCachePump, the second nsHttpChannel.

Comment 6

[Michal Novotny [:michal]]

(In reply to Junior[:junior] from comment #5)
> I'm worried about the custom conditional request, since it does *not* set
> mDidReval = true.
> But we can deal with it in Bug 1331324 and use mDidReval first.

If we revalidated the entry and the revalidation failed, then mDidReval is true, but mCachedContentIsValid = false. And we shouldn't save this network time because it contains also time spent loading the cache entry. In fact, we should never save network time when we hit the disk due to get the cache entry and this solves just one case. But AFAICS it's not easy to handle other cases and they should be rare.

> > This prevents rewriting stored times in the cache entry, but we still get
> > wrong mOnStartRequestTimestamp. Now we use the time when we started to read
> > the data from the cache, but we should use the earlier when we got the
> > response from the server. I.e. we should prevent rewriting
> > mOnStartRequestTimestamp in second nsHttpChannel::OnStartRequest call.
> 
> I'm wondering why we should prevent rewriting mOnStartRequestTimestamp.
> 
> We want to measure the time between AsynOpen and mListener->OnStartRequest,
> and we propagate the OnStartRequest to mListener in
> |nsHttpChannel::CallOnStartRequest|
> which is triggered by mCachePump, the second nsHttpChannel.

You're right. We should report the delay between AsyncOpen and a point when we have first data for the listener. Sorry for the confusion.

Comment 7

[Junior [inactive]]

(In reply to Michal Novotny (:michal) from comment #6)
> (In reply to Junior[:junior] from comment #5)
> > I'm worried about the custom conditional request, since it does *not* set
> > mDidReval = true.
> > But we can deal with it in Bug 1331324 and use mDidReval first.
> 
> If we revalidated the entry and the revalidation failed, then mDidReval is
> true, but mCachedContentIsValid = false. And we shouldn't save this network
> time because it contains also time spent loading the cache entry. In fact,
> we should never save network time when we hit the disk due to get the cache
> entry and this solves just one case. But AFAICS it's not easy to handle
> other cases and they should be rare.
> 
I agree that we should not measure the network time if we need to load to cache entry
because that's not the case when we race cache with network.

When we race cache with network, we won't send a conditional request.

Comment 8

[Junior [inactive]]

Attachment: avoid_record_conditional_requests

Comment 9

[Michal Novotny [:michal]]

Comment on attachment 8827379 [details] [diff] [review]
avoid_record_conditional_requests

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

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +6725,5 @@
>          // If we are using the transaction to serve content, we also save the
>          // time since async open in the cache entry so we can compare telemetry
>          // between cache and net response.
> +        // We ignore the conditional requests since we won't send a conditional
> +        // request in racing cache with network.

I think we need a bit better comment. Something like:

Do not store the time in case of conditional request because even if we fetch the data from the server the time includes loading of the old cache entry which would skew the network load time.

Comment 10

[Junior [inactive]]

Attachment: avoid_record_conditional_requests-v2

Rebase and modify comments based on reviewer's hint. Carry r+

Comment 11

[Junior [inactive]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=bcdf15c40c4a

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aba1bf821277
Do not record the timestamp for conditional requests. r=michal

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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