658822 - Fix implementation of DNS timing in nsITimedChannel

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Christian :Biesinger (don't email me, ping me on IRC)]

See  bug 576006 comment 18 et al... the DNS prefetching in nsHttpChannel means that we don't currently get real DNS timings.

Comment 1

[Christian :Biesinger (don't email me, ping me on IRC)]

Attachment: patch

Comment 2

[Jason Duell]

cc-ing Patrick, since he actually knows this code better than I and may also want to do a lookover.

Comment 3

[Jason Duell]

Comment on attachment 534360 [details] [diff] [review]
patch

+r with nits at least considered :)

>diff --git a/netwerk/base/src/nsDNSPrefetch.cpp b/netwerk/base/src/nsDNSPrefetch.cpp
> 
>+    if (mStoreTiming)
>+        mPrefetchStart = mozilla::TimeStamp::Now();
>+    // If AsyncResolve fails, for example because prefetching is disabled,
>+    // then our timing will be useless. However, in such a case,
>+    // mPrefetchEnd will be a null timestamp and callers should check
>+    // TimeValid() before using the timing.

Dupe the "callers should check TimeValid() before using the timings" and put in comment in nsDNSPrefetch.h where TimeValid() is declared.

> NS_IMETHODIMP
> nsDNSPrefetch::OnLookupComplete(nsICancelable *request,
>                                 nsIDNSRecord  *rec,
>                                 nsresult       status)
> {
>+    if (mStoreTiming)
>+        mPrefetchEnd = mozilla::TimeStamp::Now();
>     return NS_OK;

Dumb question: how long are prefetched DNS lookups kept?  Is there a chance that they get thrown out, and we're actually not using the timing we're gathering here?

>diff --git a/netwerk/base/src/nsDNSPrefetch.h b/netwerk/base/src/nsDNSPrefetch.h
> 
> class nsDNSPrefetch : public nsIDNSListener
> {
> public:
>+    nsDNSPrefetch(nsIURI *aURI, PRBool storeTiming);
>+    bool TimeValid() const {
>+        return !mPrefetchStart.IsNull() && !mPrefetchEnd.IsNull();
>+    }
>+    const mozilla::TimeStamp& PrefetchStart() const { return mPrefetchStart; }
>+    const mozilla::TimeStamp& PrefetchEnd() const { return mPrefetchEnd; }

Confusing function names.  Very likely to be mistaken for "start the prefetch".  Maybe rename to "GetStartTimeStamp()" and "GetEndTimeStamp"?

I also think maybe "TimingsAreValid" (or "TimingsValid") is a better name for TimeValid.
 

>diff --git a/netwerk/protocol/http/nsHttpChannel.cpp b/netwerk/protocol/http/nsHttpChannel.cpp
> 
> NS_IMETHODIMP
> nsHttpChannel::GetDomainLookupStart(mozilla::TimeStamp* _retval) {
>-    if (mTransaction)
>+    if (mDNSPrefetch && mDNSPrefetch->TimeValid())
>+        *_retval = mDNSPrefetch->PrefetchStart();
>+    else if (mTransaction)
>         *_retval = mTransaction->Timings().domainLookupStart;
>     else
>         *_retval = mTransactionTimings.domainLookupStart;
>     return NS_OK;

Memory savings idea:  maybe merge the mDNSPrefetch values into mTransactionTimings during nsHttpChannel::OnStopRequest, and then we can null out mDNSPrefetch and save a little memory?  Seems easy enough, and it's nice to keep channels smaller given how long nsDocument likes to keep them around.  The logic in these accessor functions would stay the same.

Comment 4

[Christian :Biesinger (don't email me, ping me on IRC)]

(In reply to comment #3)
> Dumb question: how long are prefetched DNS lookups kept?  Is there a chance
> that they get thrown out, and we're actually not using the timing we're
> gathering here?

For network.dnsCacheExpiration seconds; by default, 3 minutes. It is true that this may not represent the "true" DNS timing in some edge cases (especially when the connections-per-host queue fills up).

However:
1. I don't see a good way to avoid that problem
2. Even if this was not the "real" DNS lookup that we used, it still represents a valid timing for a lookup for this website. So it doesn't seem completely arbitrary to use it.


I will fix the other comments.

Comment 5

[Jason Duell]

>  Even if this was not the "real" DNS lookup that we used, it still represents a valid timing for a lookup for this website. 

Well, it's "valid" in some sense, but not in the sense that it actually represents the chunk of time that was spent on DNS in the load.  I.e., if the entry times out, and for some reason the DNS on the non-prefetch patch takes a really long time, that won't show up as the problem in the timings.

But I agree this is probably an edge case, and hard to fix, so I'm ok with it.

Comment 6

[Christian :Biesinger (don't email me, ping me on IRC)]

I will also rename the timestamp members to mStartTimestamp/mEndTimestamp

Comment 7

[Patrick McManus [:mcmanus]]

(In reply to comment #4)

> 2. Even if this was not the "real" DNS lookup that we used, it still
> represents a valid timing for a lookup for this website. So it doesn't seem
> completely arbitrary to use it.

That makes sense to me.. probably need more comments to that effect.

isn't it possible that you are using the start timestamp from transaction->timings() (because the prefetch is invalid) and the end timestamp from the prefetch (because the prefetch has become valid in the interim)? Unless those are always retreived back to back on the socket thread?

Comment 8

[Christian :Biesinger (don't email me, ping me on IRC)]

(In reply to comment #7)
> That makes sense to me.. probably need more comments to that effect.

will add.

> isn't it possible that you are using the start timestamp from
> transaction->timings() (because the prefetch is invalid) and the end
> timestamp from the prefetch (because the prefetch has become valid in the
> interim)? Unless those are always retreived back to back on the socket
> thread?

Socket thread doesn't help, DNS callbacks don't use the socket thread.

You are correct though, there is this possibility. Isn't that only a problem before OnStartRequest, though? Afterwards, we should have valid timings.

Comment 9

[Christian :Biesinger (don't email me, ping me on IRC)]

Attachment: patch for checkin

all comments addressed

Comment 10

[Christian :Biesinger (don't email me, ping me on IRC)]

(In reply to comment #8)
> You are correct though, there is this possibility. Isn't that only a problem
> before OnStartRequest, though? Afterwards, we should have valid timings.

And to clarify my thought here - I expect callers will generally access this data from OnStopRequest or OnChannelRedirect.

Comment 11

[Patrick McManus [:mcmanus]]

(In reply to comment #10)
> (In reply to comment #8)
> And to clarify my thought here - I expect callers will generally access this
> data from OnStopRequest or OnChannelRedirect.

yep. probably. I think the differences are minor enough in any event to be pretty unimportant - especially at first pass.

This of course, by design, captures DNS time as part of the transaction lifetime - it doesn't capture the actual time it takes to resolve the query, right?

It would be interesting to crosstab those two things in order to understand the effectiveness of the cache and the prefetching and understand how many 'partial' cache hits we see.

Comment 12

[Christian :Biesinger (don't email me, ping me on IRC)]

(In reply to comment #11)
> This of course, by design, captures DNS time as part of the transaction
> lifetime - it doesn't capture the actual time it takes to resolve the query,
> right?

I'm not sure I understand the difference - I am capturing actual time to resolve the query, unless it's cached, in which case I'm capturing cache lookup time. no?

Comment 13

[Patrick McManus [:mcmanus]]

(In reply to comment #12)

> I'm not sure I understand the difference - I am capturing actual time to
> resolve the query, unless it's cached, in which case I'm capturing cache
> lookup time. no?

you might very well be piggybacking on another request for the same lookup which had already started, but not finished, when you made your request.. that's what I meant by partial cache hit.

Comment 14

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

http://hg.mozilla.org/mozilla-central/rev/a98b112f0ed2

Comment 15

[Christian :Biesinger (don't email me, ping me on IRC)]

Oh, good point. Yeah, I agree it'd be interesting to figure out how much that affects things.