1543040 - [network markers] Redirections don't always have the timing data

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P3)

Description

[Julien Wajsberg [:julienw]]

I see this in some profiles, and I believe this comes from [1]. Could we just add &mTransactionTimings instead of nullptr or is wrong?

This seems to be correct in [2]. It's not clear to me what the difference is between these 2 locations.

[1] https://searchfox.org/mozilla-central/rev/8d78f219702286c873860f39f9ed78bad1a6d062/netwerk/protocol/http/nsHttpChannel.cpp#5912-5915
[2] https://searchfox.org/mozilla-central/rev/8d78f219702286c873860f39f9ed78bad1a6d062/netwerk/protocol/http/HttpChannelChild.cpp#1690-1693

Comment 1

[Honza Bambas (:mayhemer)]

I don't see a reason why not to pass trans timing at [1] as well. If the redirect is coming from net (is not cached) we have it here.

Comment 2

[Julien Wajsberg [:julienw]]

So, I had a quick look, and it looks like we don't have good timings anyway, neither on the parent process nor the child process. It looks like mTransactionTimings isn't filled when there is a redirection.

Doing something like this seems to work:

diff --git a/netwerk/protocol/http/nsHttpChannel.cpp b/netwerk/protocol/http/nsHttpChannel.cpp
index 127138d679b81..a46fc74476c9b 100644
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -5923,20 +5923,21 @@ nsresult nsHttpChannel::ContinueProcessRedirectionAfterFallback(nsresult rv) {
     rv = PromptTempRedirect();
     if (NS_FAILED(rv)) return rv;
   }
 
 #ifdef MOZ_GECKO_PROFILER
   if (profiler_is_active()) {
     int32_t priority = PRIORITY_NORMAL;
     GetPriority(&priority);
+    auto timings = mTransaction->Timings();
     profiler_add_network_marker(
         mURI, priority, mChannelId, NetworkLoadType::LOAD_REDIRECT,
         mLastStatusReported, TimeStamp::Now(), mLogicalOffset,
-        mCacheDisposition, nullptr, mRedirectURI);
+        mCacheDisposition, &timings, mRedirectURI);
   }
 #endif
 
   nsCOMPtr<nsIIOService> ioService;
   rv = gHttpHandler->GetIOService(getter_AddRefs(ioService));
   if (NS_FAILED(rv)) return rv;
 
   uint32_t redirectFlags;

Is that a good approach? Are we sure that mTransaction is never null at this location?

Comment 3

[Honza Bambas (:mayhemer)]

no, you have to add a non-null check. the patch seems correct to me. we fill (from obvious reasons) timing at [1], onstoprequest, which is never reached before the point you are patching.

[1] https://searchfox.org/mozilla-central/rev/116bd975c30746ddefc3d20e6947d1871469354f/netwerk/protocol/http/nsHttpChannel.cpp#7889

Comment 4

[Julien Wajsberg [:julienw]]

Attachment: Bug 1543040 - Report timings for redirects in the child as well

Comment 5

[Julien Wajsberg [:julienw]]

Attachment: Bug 1543040 - Report transaction timings in the redirect marker

Comment 6

[Julien Wajsberg [:julienw]]

Attachment: Bug 1543040 - Report transaction timings in the redirect marker

Comment 7

[Julien Wajsberg [:julienw]]

I think I start to grasp how these things work with each other :)

Comment 8

[Julien Wajsberg [:julienw]]

Here is a profile captured with this patch => https://perfht.ml/2Vw8gIK

Especially look at the timings for https://developer.mozilla.org, on both the parent and the child processes. Note that the child process has 2 requests showing up because of bug 1546641.

Comment 9

[Julien Wajsberg [:julienw]]

Here is a try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=48f6e59e318c5c309c41fe5ef970699c20627c16

Comment 10

[Julien Wajsberg [:julienw]]

Hey Honza, the above try is too orange in my taste, but I can't make sense of the failures, as they don't seem related to the change. But they're pretty consistent cross-platform. Is there anything I'm doing wrong?

Comment 11

[Honza Bambas (:mayhemer)]

This is the base cset run:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=b74e5737da64a7af28ab4f81f996950917aa71c5&selectedJob=247510224
which is green.. I really don't see any problem with the patch. Please isolate which of the two patches it is at least, then try to minimize your changes to narrow this down in the patch that is causing this. It's very weird that change would cause such an unclear perma failure. Maybe also try to rebase to a newer m-c cset before push, just in case.

Comment 12

[Julien Wajsberg [:julienw]]

This could be because of bug 1541424, I'll check this out Monday.

Comment 13

[Julien Wajsberg [:julienw]]

here is a new try on linux64 only, not rebased, but without the "paths" argument:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=17d76df20a2981c6e91a66d5196063d110d0c51d

If this passes I'll do another one rebased on top of latest master, with more environments.

Comment 14

[Julien Wajsberg [:julienw]]

I looked closer and I've seen that all failures have a skip-if clause. So I'll move forward and land it now.
Thanks for the help !

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/52a2e676ebec
Report transaction timings in the redirect marker r=mayhemer
https://hg.mozilla.org/integration/autoland/rev/726be0bcab09
Report timings for redirects in the child as well r=mayhemer

Comment 16

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/52a2e676ebec
https://hg.mozilla.org/mozilla-central/rev/726be0bcab09