From da20da46fa28b1b9fee9a305aa04d5911ccf639a Mon Sep 17 00:00:00 2001 From: Randell Jesup Date: Mon, 30 Oct 2023 03:03:42 +0000 Subject: [PATCH] Bug 1857615: Add Telemetry for OnStopRequest/OnDataFinished/etc r=necko-reviewers,kershaw Also add OnStartRequest telemetry back Differential Revision: https://phabricator.services.mozilla.com/D190470 --- netwerk/metrics.yaml | 80 ++++++++++++++++++++++ netwerk/protocol/http/HttpChannelChild.cpp | 42 +++++++++++- parser/html/nsHtml5StreamParser.cpp | 62 ++++++++++------- parser/html/nsHtml5StreamParser.h | 8 +++ 4 files changed, 166 insertions(+), 26 deletions(-) diff --git a/netwerk/metrics.yaml b/netwerk/metrics.yaml index f6acdccd1d282..df380ee0bcb4c 100644 --- a/netwerk/metrics.yaml +++ b/netwerk/metrics.yaml @@ -197,6 +197,86 @@ networking: - rjesup@mozilla.com expires: 130 + http_content_ondatafinished_delay: + type: timing_distribution + time_unit: millisecond + description: > + The time between dispatching OnDataFinished from the socket thread and processing it. + bugs: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615 + data_reviews: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c + data_sensitivity: + - technical + notification_emails: + - necko@mozilla.com + - rjesup@mozilla.com + expires: 130 + + http_content_ondatafinished_to_onstop_delay: + type: timing_distribution + time_unit: millisecond + description: > + The time between processing OnDataFinished and processing OnStopRequest (if OnDataFinished comes first) + bugs: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615 + data_reviews: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c + data_sensitivity: + - technical + notification_emails: + - necko@mozilla.com + - rjesup@mozilla.com + expires: 130 + + http_content_ondatafinished_to_onstop_delay_negative: + type: timing_distribution + time_unit: millisecond + description: > + The time between processing OnStopRequest and processing OnDataFinished (if OnStopRequest comes first) + bugs: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615 + data_reviews: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c + data_sensitivity: + - technical + notification_emails: + - necko@mozilla.com + - rjesup@mozilla.com + expires: 130 + + http_content_html5parser_ondatafinished_to_onstop_delay: + type: timing_distribution + time_unit: millisecond + description: > + The time between processing OnDataFinished and processing OnStopRequest (if OnDataFinished comes first) + bugs: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926 + data_reviews: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926 + data_sensitivity: + - technical + notification_emails: + - necko@mozilla.com + - rjesup@mozilla.com + expires: 130 + + http_content_html5parser_ondatafinished_to_onstop_delay_negative: + type: timing_distribution + time_unit: millisecond + description: > + The time between processing OnStopRequest and processing OnDataFinished (if OnStopRequest comes first) + bugs: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926 + data_reviews: + - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926 + data_sensitivity: + - technical + notification_emails: + - necko@mozilla.com + - rjesup@mozilla.com + expires: 130 + http_1_download_throughput: type: custom_distribution unit: mbps diff --git a/netwerk/protocol/http/HttpChannelChild.cpp b/netwerk/protocol/http/HttpChannelChild.cpp index 1b522f083e7a6..9b2e15b7d2554 100644 --- a/netwerk/protocol/http/HttpChannelChild.cpp +++ b/netwerk/protocol/http/HttpChannelChild.cpp @@ -833,6 +833,10 @@ void HttpChannelChild::SendOnDataFinished(const nsresult& aChannelStatus) { ("HttpChannelChild::SendOnDataFinished sending data end " "notification[this=%p]\n", this)); + // We want to calculate the delta time between this call and + // ProcessOnStopRequest. Complicating things is that OnStopRequest + // could come first, and that it will run on a different thread, so + // we need to synchronize and lock data. omtEventListener->OnDataFinished(aChannelStatus); } else { LOG( @@ -844,6 +848,28 @@ void HttpChannelChild::SendOnDataFinished(const nsresult& aChannelStatus) { } } +class RecordStopRequestDelta final { + public: + NS_INLINE_DECL_THREADSAFE_REFCOUNTING(RecordStopRequestDelta); + + TimeStamp mOnStopRequestTime; + TimeStamp mOnDataFinishedTime; + + private: + ~RecordStopRequestDelta() { + TimeDuration delta = (mOnStopRequestTime - mOnDataFinishedTime); + if (delta.ToMilliseconds() < 0) { + // Because Telemetry can't handle negatives + delta = -delta; + glean::networking::http_content_ondatafinished_to_onstop_delay_negative + .AccumulateRawDuration(delta); + } else { + glean::networking::http_content_ondatafinished_to_onstop_delay + .AccumulateRawDuration(delta); + } + } +}; + void HttpChannelChild::ProcessOnStopRequest( const nsresult& aChannelStatus, const ResourceTimingStructArgs& aTiming, const nsHttpHeaderArray& aResponseTrailers, @@ -860,13 +886,21 @@ void HttpChannelChild::ProcessOnStopRequest( mTransferSize = aTiming.transferSize(); mEncodedBodySize = aTiming.encodedBodySize(); } + + RefPtr timing(new RecordStopRequestDelta); TimeStamp start = TimeStamp::Now(); if (StaticPrefs::network_send_OnDataFinished()) { mEventQ->RunOrEnqueue(new ChannelFunctionEvent( [self = UnsafePtr(this)]() { return self->GetODATarget(); }, - [self = UnsafePtr(this), status = aChannelStatus]() { + [self = UnsafePtr(this), status = aChannelStatus, + start, timing]() { + TimeStamp now = TimeStamp::Now(); + TimeDuration delay = now - start; + glean::networking::http_content_ondatafinished_delay + .AccumulateRawDuration(delay); + timing->mOnDataFinishedTime = now; self->SendOnDataFinished(status); })); } @@ -874,10 +908,12 @@ void HttpChannelChild::ProcessOnStopRequest( this, [self = UnsafePtr(this), aChannelStatus, aTiming, aResponseTrailers, consoleReports = CopyableTArray{aConsoleReports.Clone()}, - aFromSocketProcess, start]() mutable { - TimeDuration delay = TimeStamp::Now() - start; + aFromSocketProcess, start, timing]() mutable { + TimeStamp now = TimeStamp::Now(); + TimeDuration delay = now - start; glean::networking::http_content_onstop_delay.AccumulateRawDuration( delay); + timing->mOnStopRequestTime = now; self->OnStopRequest(aChannelStatus, aTiming, aResponseTrailers); if (!aFromSocketProcess) { self->DoOnConsoleReport(std::move(consoleReports)); diff --git a/parser/html/nsHtml5StreamParser.cpp b/parser/html/nsHtml5StreamParser.cpp index 8f1af6e932bb4..38dd0c55a3548 100644 --- a/parser/html/nsHtml5StreamParser.cpp +++ b/parser/html/nsHtml5StreamParser.cpp @@ -1395,34 +1395,50 @@ nsresult nsHtml5StreamParser::OnStopRequest( const mozilla::ReentrantMonitorAutoEnter& aProofOfLock) { MOZ_ASSERT_IF(aRequest, mRequest == aRequest); if (mOnStopCalled) { - return NS_OK; - } + if (mOnDataFinishedTime) { + mOnStopRequestTime = TimeStamp::Now(); + } else { + mOnDataFinishedTime = TimeStamp::Now(); + } + } else { + mOnStopCalled = true; + + if (MOZ_UNLIKELY(NS_IsMainThread())) { + mOnStopRequestTime = TimeStamp::Now(); + nsCOMPtr stopper = new nsHtml5RequestStopper(this); + if (NS_FAILED( + mEventTarget->Dispatch(stopper, nsIThread::DISPATCH_NORMAL))) { + NS_WARNING("Dispatching StopRequest event failed."); + } + } else { + mOnDataFinishedTime = TimeStamp::Now(); - mOnStopCalled = true; + if (StaticPrefs::network_send_OnDataFinished_html5parser()) { + MOZ_ASSERT(IsParserThread(), "Wrong thread!"); - if (MOZ_UNLIKELY(NS_IsMainThread())) { - nsCOMPtr stopper = new nsHtml5RequestStopper(this); - if (NS_FAILED( - mEventTarget->Dispatch(stopper, nsIThread::DISPATCH_NORMAL))) { - NS_WARNING("Dispatching StopRequest event failed."); + mozilla::MutexAutoLock autoLock(mTokenizerMutex); + DoStopRequest(); + PostLoadFlusher(); + } else { + // Let the MainThread event handle this, even though it will just + // send it back to this thread, so we can accurately judge the impact + // of this change. This should eventually be removed + } } - return NS_OK; } - - if (!StaticPrefs::network_send_OnDataFinished_html5parser()) { - // Let the MainThread event handle this, even though it will just - // send it back to this thread, so we can accurately judge the impact - // of this change. This should eventually be removed once the PoC is - // complete - mOnStopCalled = false; - return NS_OK; + if (!mOnStopRequestTime.IsNull() && !mOnDataFinishedTime.IsNull()) { + TimeDuration delta = (mOnStopRequestTime - mOnDataFinishedTime); + if (delta.ToMilliseconds() < 0) { + // Because Telemetry can't handle negatives + delta = -delta; + glean::networking:: + http_content_html5parser_ondatafinished_to_onstop_delay_negative + .AccumulateRawDuration(delta); + } else { + glean::networking::http_content_html5parser_ondatafinished_to_onstop_delay + .AccumulateRawDuration(delta); + } } - - MOZ_ASSERT(IsParserThread(), "Wrong thread!"); - - mozilla::MutexAutoLock autoLock(mTokenizerMutex); - DoStopRequest(); - PostLoadFlusher(); return NS_OK; } diff --git a/parser/html/nsHtml5StreamParser.h b/parser/html/nsHtml5StreamParser.h index 8da45cde39457..acc700c0cbd3a 100644 --- a/parser/html/nsHtml5StreamParser.h +++ b/parser/html/nsHtml5StreamParser.h @@ -18,6 +18,7 @@ #include "mozilla/ReentrantMonitor.h" #include "mozilla/RefPtr.h" #include "mozilla/Span.h" +#include "mozilla/TimeStamp.h" #include "mozilla/UniquePtr.h" #include "nsCharsetSource.h" #include "nsCOMPtr.h" @@ -771,6 +772,13 @@ class nsHtml5StreamParser final : public nsISupports { * nsHtml5StreamListener::mDelegateMonitor passed in the OnStopRequest */ bool mOnStopCalled{false}; + + /* + * Used for telemetry about OnStopRequest vs OnDataFinished + */ + // guarded by nsHtml5StreamListener::mDelegateMonitor + mozilla::TimeStamp mOnStopRequestTime; + mozilla::TimeStamp mOnDataFinishedTime; }; #endif // nsHtml5StreamParser_h