From 644e9db1092df1477b1facc52cd3ee45ebd13040 Mon Sep 17 00:00:00 2001 From: janekptacijarabaci Date: Thu, 1 Mar 2018 11:52:50 +0100 Subject: DevTools - network - implement the secureConnectionStart property for the PerformanceTiming https://github.com/MoonchildProductions/moebius/pull/116 ("/testing" and "/toolkit" in in the previous commit) --- netwerk/base/nsISocketTransport.idl | 2 ++ netwerk/base/nsITimedChannel.idl | 2 ++ netwerk/base/nsLoadGroup.cpp | 13 ++++++++++++- netwerk/ipc/NeckoMessageUtils.h | 2 ++ netwerk/protocol/http/Http2Session.cpp | 9 +++++++++ netwerk/protocol/http/HttpBaseChannel.cpp | 7 +++++++ netwerk/protocol/http/HttpChannelChild.cpp | 1 + netwerk/protocol/http/HttpChannelParent.cpp | 1 + netwerk/protocol/http/NullHttpChannel.cpp | 8 ++++++++ netwerk/protocol/http/NullHttpTransaction.cpp | 24 ++++++++++++++++++++++++ netwerk/protocol/http/NullHttpTransaction.h | 4 ++++ netwerk/protocol/http/TimingStruct.h | 1 + netwerk/protocol/http/nsHttpChannel.cpp | 9 +++++++++ netwerk/protocol/http/nsHttpChannel.h | 1 + netwerk/protocol/http/nsHttpConnection.cpp | 25 ++++++++++++++++++++++--- netwerk/protocol/http/nsHttpConnection.h | 6 ++++++ netwerk/protocol/http/nsHttpConnectionMgr.cpp | 5 +++++ netwerk/protocol/http/nsHttpTransaction.cpp | 22 ++++++++++++++++++++++ netwerk/protocol/http/nsHttpTransaction.h | 3 +++ 19 files changed, 141 insertions(+), 4 deletions(-) (limited to 'netwerk') diff --git a/netwerk/base/nsISocketTransport.idl b/netwerk/base/nsISocketTransport.idl index 6395d6b5f..9b5bc23fb 100644 --- a/netwerk/base/nsISocketTransport.idl +++ b/netwerk/base/nsISocketTransport.idl @@ -162,6 +162,8 @@ interface nsISocketTransport : nsITransport const unsigned long STATUS_SENDING_TO = 0x804b0005; const unsigned long STATUS_WAITING_FOR = 0x804b000a; const unsigned long STATUS_RECEIVING_FROM = 0x804b0006; + const unsigned long STATUS_TLS_HANDSHAKE_STARTING = 0x804b000c; + const unsigned long STATUS_TLS_HANDSHAKE_ENDED = 0x804b000d; /** * connectionFlags is a bitmask that can be used to modify underlying diff --git a/netwerk/base/nsITimedChannel.idl b/netwerk/base/nsITimedChannel.idl index 6ec2d1ff8..13b65e7b8 100644 --- a/netwerk/base/nsITimedChannel.idl +++ b/netwerk/base/nsITimedChannel.idl @@ -31,6 +31,7 @@ interface nsITimedChannel : nsISupports { [noscript] readonly attribute TimeStamp domainLookupStart; [noscript] readonly attribute TimeStamp domainLookupEnd; [noscript] readonly attribute TimeStamp connectStart; + [noscript] readonly attribute TimeStamp secureConnectionStart; [noscript] readonly attribute TimeStamp connectEnd; [noscript] readonly attribute TimeStamp requestStart; [noscript] readonly attribute TimeStamp responseStart; @@ -69,6 +70,7 @@ interface nsITimedChannel : nsISupports { readonly attribute PRTime domainLookupStartTime; readonly attribute PRTime domainLookupEndTime; readonly attribute PRTime connectStartTime; + readonly attribute PRTime secureConnectionStartTime; readonly attribute PRTime connectEndTime; readonly attribute PRTime requestStartTime; readonly attribute PRTime responseStartTime; diff --git a/netwerk/base/nsLoadGroup.cpp b/netwerk/base/nsLoadGroup.cpp index 3b8cf4434..7b75f7942 100644 --- a/netwerk/base/nsLoadGroup.cpp +++ b/netwerk/base/nsLoadGroup.cpp @@ -888,6 +888,11 @@ nsLoadGroup::TelemetryReportChannel(nsITimedChannel *aTimedChannel, if (NS_FAILED(rv)) return; + TimeStamp secureConnectionStart; + rv = aTimedChannel->GetSecureConnectionStart(&secureConnectionStart); + if (NS_FAILED(rv)) + return; + TimeStamp connectEnd; rv = aTimedChannel->GetConnectEnd(&connectEnd); if (NS_FAILED(rv)) @@ -921,9 +926,15 @@ nsLoadGroup::TelemetryReportChannel(nsITimedChannel *aTimedChannel, domainLookupStart, domainLookupEnd); \ } \ \ + if (!secureConnectionStart.IsNull() && !connectEnd.IsNull()) { \ + Telemetry::AccumulateTimeDelta( \ + Telemetry::HTTP_##prefix##_TLS_HANDSHAKE, \ + secureConnectionStart, connectEnd); \ + } \ + \ if (!connectStart.IsNull() && !connectEnd.IsNull()) { \ Telemetry::AccumulateTimeDelta( \ - Telemetry::HTTP_##prefix##_TCP_CONNECTION, \ + Telemetry::HTTP_##prefix##_TCP_CONNECTION_2, \ connectStart, connectEnd); \ } \ \ diff --git a/netwerk/ipc/NeckoMessageUtils.h b/netwerk/ipc/NeckoMessageUtils.h index 273f049a2..778691369 100644 --- a/netwerk/ipc/NeckoMessageUtils.h +++ b/netwerk/ipc/NeckoMessageUtils.h @@ -147,6 +147,7 @@ struct ParamTraits WriteParam(aMsg, aParam.domainLookupStart); WriteParam(aMsg, aParam.domainLookupEnd); WriteParam(aMsg, aParam.connectStart); + WriteParam(aMsg, aParam.secureConnectionStart); WriteParam(aMsg, aParam.connectEnd); WriteParam(aMsg, aParam.requestStart); WriteParam(aMsg, aParam.responseStart); @@ -169,6 +170,7 @@ struct ParamTraits return ReadParam(aMsg, aIter, &aResult->domainLookupStart) && ReadParam(aMsg, aIter, &aResult->domainLookupEnd) && ReadParam(aMsg, aIter, &aResult->connectStart) && + ReadParam(aMsg, aIter, &aResult->secureConnectionStart) && ReadParam(aMsg, aIter, &aResult->connectEnd) && ReadParam(aMsg, aIter, &aResult->requestStart) && ReadParam(aMsg, aIter, &aResult->responseStart) && diff --git a/netwerk/protocol/http/Http2Session.cpp b/netwerk/protocol/http/Http2Session.cpp index e1440d6a4..55ddbe908 100644 --- a/netwerk/protocol/http/Http2Session.cpp +++ b/netwerk/protocol/http/Http2Session.cpp @@ -2277,6 +2277,15 @@ Http2Session::OnTransportStatus(nsITransport* aTransport, case NS_NET_STATUS_TLS_HANDSHAKE_ENDED: { Http2Stream *target = mStreamIDHash.Get(1); + if (!target) { + // any transaction will do if we can't find the low numbered one + // generally this happens when the initial transaction hasn't been + // assigned a stream id yet. + auto iter = mStreamTransactionHash.Iter(); + if (!iter.Done()) { + target = iter.Data(); + } + } nsAHttpTransaction *transaction = target ? target->Transaction() : nullptr; if (transaction) transaction->OnTransportStatus(aTransport, aStatus, aProgress); diff --git a/netwerk/protocol/http/HttpBaseChannel.cpp b/netwerk/protocol/http/HttpBaseChannel.cpp index 66252b82f..0ff792280 100644 --- a/netwerk/protocol/http/HttpBaseChannel.cpp +++ b/netwerk/protocol/http/HttpBaseChannel.cpp @@ -3448,6 +3448,12 @@ HttpBaseChannel::GetConnectStart(TimeStamp* _retval) { return NS_OK; } +NS_IMETHODIMP +HttpBaseChannel::GetSecureConnectionStart(TimeStamp* _retval) { + *_retval = mTransactionTimings.secureConnectionStart; + return NS_OK; +} + NS_IMETHODIMP HttpBaseChannel::GetConnectEnd(TimeStamp* _retval) { *_retval = mTransactionTimings.connectEnd; @@ -3517,6 +3523,7 @@ IMPL_TIMING_ATTR(AsyncOpen) IMPL_TIMING_ATTR(DomainLookupStart) IMPL_TIMING_ATTR(DomainLookupEnd) IMPL_TIMING_ATTR(ConnectStart) +IMPL_TIMING_ATTR(SecureConnectionStart) IMPL_TIMING_ATTR(ConnectEnd) IMPL_TIMING_ATTR(RequestStart) IMPL_TIMING_ATTR(ResponseStart) diff --git a/netwerk/protocol/http/HttpChannelChild.cpp b/netwerk/protocol/http/HttpChannelChild.cpp index 0de6095e1..f0b9e2136 100644 --- a/netwerk/protocol/http/HttpChannelChild.cpp +++ b/netwerk/protocol/http/HttpChannelChild.cpp @@ -893,6 +893,7 @@ HttpChannelChild::OnStopRequest(const nsresult& channelStatus, mTransactionTimings.domainLookupStart = timing.domainLookupStart; mTransactionTimings.domainLookupEnd = timing.domainLookupEnd; mTransactionTimings.connectStart = timing.connectStart; + mTransactionTimings.secureConnectionStart = timing.secureConnectionStart; mTransactionTimings.connectEnd = timing.connectEnd; mTransactionTimings.requestStart = timing.requestStart; mTransactionTimings.responseStart = timing.responseStart; diff --git a/netwerk/protocol/http/HttpChannelParent.cpp b/netwerk/protocol/http/HttpChannelParent.cpp index 51da1ec8c..fe076a237 100644 --- a/netwerk/protocol/http/HttpChannelParent.cpp +++ b/netwerk/protocol/http/HttpChannelParent.cpp @@ -1216,6 +1216,7 @@ HttpChannelParent::OnStopRequest(nsIRequest *aRequest, mChannel->GetDomainLookupStart(&timing.domainLookupStart); mChannel->GetDomainLookupEnd(&timing.domainLookupEnd); mChannel->GetConnectStart(&timing.connectStart); + mChannel->GetSecureConnectionStart(&timing.secureConnectionStart); mChannel->GetConnectEnd(&timing.connectEnd); mChannel->GetRequestStart(&timing.requestStart); mChannel->GetResponseStart(&timing.responseStart); diff --git a/netwerk/protocol/http/NullHttpChannel.cpp b/netwerk/protocol/http/NullHttpChannel.cpp index 8c048a6b5..61efe3956 100644 --- a/netwerk/protocol/http/NullHttpChannel.cpp +++ b/netwerk/protocol/http/NullHttpChannel.cpp @@ -585,6 +585,13 @@ NullHttpChannel::GetConnectStart(mozilla::TimeStamp *aConnectStart) return NS_OK; } +NS_IMETHODIMP +NullHttpChannel::GetSecureConnectionStart(mozilla::TimeStamp *aSecureConnectionStart) +{ + *aSecureConnectionStart = mAsyncOpenTime; + return NS_OK; +} + NS_IMETHODIMP NullHttpChannel::GetConnectEnd(mozilla::TimeStamp *aConnectEnd) { @@ -757,6 +764,7 @@ IMPL_TIMING_ATTR(AsyncOpen) IMPL_TIMING_ATTR(DomainLookupStart) IMPL_TIMING_ATTR(DomainLookupEnd) IMPL_TIMING_ATTR(ConnectStart) +IMPL_TIMING_ATTR(SecureConnectionStart) IMPL_TIMING_ATTR(ConnectEnd) IMPL_TIMING_ATTR(RequestStart) IMPL_TIMING_ATTR(ResponseStart) diff --git a/netwerk/protocol/http/NullHttpTransaction.cpp b/netwerk/protocol/http/NullHttpTransaction.cpp index 965ffcc2c..bb32a8098 100644 --- a/netwerk/protocol/http/NullHttpTransaction.cpp +++ b/netwerk/protocol/http/NullHttpTransaction.cpp @@ -162,6 +162,30 @@ void NullHttpTransaction::OnTransportStatus(nsITransport* transport, nsresult status, int64_t progress) { + if (status == NS_NET_STATUS_RESOLVING_HOST) { + if (mTimings.domainLookupStart.IsNull()) { + mTimings.domainLookupStart = TimeStamp::Now(); + } + } else if (status == NS_NET_STATUS_RESOLVED_HOST) { + if (mTimings.domainLookupEnd.IsNull()) { + mTimings.domainLookupEnd = TimeStamp::Now(); + } + } else if (status == NS_NET_STATUS_CONNECTING_TO) { + if (mTimings.connectStart.IsNull()) { + mTimings.connectStart = TimeStamp::Now(); + } + } else if (status == NS_NET_STATUS_CONNECTED_TO) { + if (mTimings.connectEnd.IsNull()) { + mTimings.connectEnd = TimeStamp::Now(); + } + } else if (status == NS_NET_STATUS_TLS_HANDSHAKE_ENDED) { + if (mTimings.secureConnectionStart.IsNull() && + !mTimings.connectEnd.IsNull()) { + mTimings.secureConnectionStart = mTimings.connectEnd; + } + mTimings.connectEnd = TimeStamp::Now();; + } + if (mActivityDistributor) { NS_DispatchToMainThread(new CallObserveActivity(mActivityDistributor, mConnectionInfo->GetOrigin(), diff --git a/netwerk/protocol/http/NullHttpTransaction.h b/netwerk/protocol/http/NullHttpTransaction.h index 04f80a9b3..b613ecfba 100644 --- a/netwerk/protocol/http/NullHttpTransaction.h +++ b/netwerk/protocol/http/NullHttpTransaction.h @@ -9,6 +9,7 @@ #include "nsAHttpTransaction.h" #include "mozilla/Attributes.h" +#include "TimingStruct.h" // This is the minimal nsAHttpTransaction implementation. A NullHttpTransaction // can be used to drive connection level semantics (such as SSL handshakes @@ -49,6 +50,8 @@ public: return PR_SecondsToInterval(15); } + TimingStruct Timings() { return mTimings; } + protected: virtual ~NullHttpTransaction(); @@ -68,6 +71,7 @@ private: Atomic mCapsToClear; bool mIsDone; bool mClaimed; + TimingStruct mTimings; protected: RefPtr mConnection; diff --git a/netwerk/protocol/http/TimingStruct.h b/netwerk/protocol/http/TimingStruct.h index b177eee8e..19133c311 100644 --- a/netwerk/protocol/http/TimingStruct.h +++ b/netwerk/protocol/http/TimingStruct.h @@ -14,6 +14,7 @@ struct TimingStruct { TimeStamp domainLookupStart; TimeStamp domainLookupEnd; TimeStamp connectStart; + TimeStamp secureConnectionStart; TimeStamp connectEnd; TimeStamp requestStart; TimeStamp responseStart; diff --git a/netwerk/protocol/http/nsHttpChannel.cpp b/netwerk/protocol/http/nsHttpChannel.cpp index 1c9093495..ce0f45dab 100644 --- a/netwerk/protocol/http/nsHttpChannel.cpp +++ b/netwerk/protocol/http/nsHttpChannel.cpp @@ -6429,6 +6429,15 @@ nsHttpChannel::GetConnectStart(TimeStamp* _retval) { return NS_OK; } +NS_IMETHODIMP +nsHttpChannel::GetSecureConnectionStart(TimeStamp* _retval) { + if (mTransaction) + *_retval = mTransaction->GetSecureConnectionStart(); + else + *_retval = mTransactionTimings.secureConnectionStart; + return NS_OK; +} + NS_IMETHODIMP nsHttpChannel::GetConnectEnd(TimeStamp* _retval) { if (mTransaction) diff --git a/netwerk/protocol/http/nsHttpChannel.h b/netwerk/protocol/http/nsHttpChannel.h index ad8156ec0..7578b1173 100644 --- a/netwerk/protocol/http/nsHttpChannel.h +++ b/netwerk/protocol/http/nsHttpChannel.h @@ -165,6 +165,7 @@ public: NS_IMETHOD GetDomainLookupStart(mozilla::TimeStamp *aDomainLookupStart) override; NS_IMETHOD GetDomainLookupEnd(mozilla::TimeStamp *aDomainLookupEnd) override; NS_IMETHOD GetConnectStart(mozilla::TimeStamp *aConnectStart) override; + NS_IMETHOD GetSecureConnectionStart(mozilla::TimeStamp *aSecureConnectionStart) override; NS_IMETHOD GetConnectEnd(mozilla::TimeStamp *aConnectEnd) override; NS_IMETHOD GetRequestStart(mozilla::TimeStamp *aRequestStart) override; NS_IMETHOD GetResponseStart(mozilla::TimeStamp *aResponseStart) override; diff --git a/netwerk/protocol/http/nsHttpConnection.cpp b/netwerk/protocol/http/nsHttpConnection.cpp index 95a06fd5c..c4564cd8b 100644 --- a/netwerk/protocol/http/nsHttpConnection.cpp +++ b/netwerk/protocol/http/nsHttpConnection.cpp @@ -527,8 +527,15 @@ npnComplete: mNPNComplete = true; mTransaction->OnTransportStatus(mSocketTransport, - NS_NET_STATUS_TLS_HANDSHAKE_ENDED, - 0); + NS_NET_STATUS_TLS_HANDSHAKE_ENDED, 0); + + // this is happening after the bootstrap was originally written to. so update it. + if (mBootstrappedTimings.secureConnectionStart.IsNull() && + !mBootstrappedTimings.connectEnd.IsNull()) { + mBootstrappedTimings.secureConnectionStart = mBootstrappedTimings.connectEnd; + mBootstrappedTimings.connectEnd = TimeStamp::Now(); + } + if (mWaitingFor0RTTResponse) { // Didn't get 0RTT OK, back out of the "attempting 0RTT" state mWaitingFor0RTTResponse = false; @@ -572,8 +579,14 @@ nsHttpConnection::Activate(nsAHttpTransaction *trans, uint32_t caps, int32_t pri LOG(("nsHttpConnection::Activate [this=%p trans=%p caps=%x]\n", this, trans, caps)); - if (!trans->IsNullTransaction()) + if (!mExperienced && !trans->IsNullTransaction()) { mExperienced = true; + nsHttpTransaction *hTrans = trans->QueryHttpTransaction(); + if (hTrans) { + hTrans->BootstrapTimings(mBootstrappedTimings); + } + mBootstrappedTimings = TimingStruct(); + } mTransactionCaps = caps; mPriority = pri; @@ -2414,5 +2427,11 @@ nsHttpConnection::CheckForTraffic(bool check) } } +void +nsHttpConnection::BootstrapTimings(TimingStruct times) +{ + mBootstrappedTimings = times; +} + } // namespace net } // namespace mozilla diff --git a/netwerk/protocol/http/nsHttpConnection.h b/netwerk/protocol/http/nsHttpConnection.h index 1f8500d75..08eea1de2 100644 --- a/netwerk/protocol/http/nsHttpConnection.h +++ b/netwerk/protocol/http/nsHttpConnection.h @@ -16,6 +16,7 @@ #include "TunnelUtils.h" #include "mozilla/Mutex.h" #include "ARefBase.h" +#include "TimingStruct.h" #include "nsIAsyncInputStream.h" #include "nsIAsyncOutputStream.h" @@ -379,6 +380,11 @@ private: bool mEarlyDataNegotiated; //Only used for telemetry nsCString mEarlyNegotiatedALPN; bool mDid0RTTSpdy; + +public: + void BootstrapTimings(TimingStruct times); +private: + TimingStruct mBootstrappedTimings; }; } // namespace net diff --git a/netwerk/protocol/http/nsHttpConnectionMgr.cpp b/netwerk/protocol/http/nsHttpConnectionMgr.cpp index abae51e2f..9271b49af 100644 --- a/netwerk/protocol/http/nsHttpConnectionMgr.cpp +++ b/netwerk/protocol/http/nsHttpConnectionMgr.cpp @@ -3314,6 +3314,11 @@ nsHalfOpenSocket::OnOutputStreamReady(nsIAsyncOutputStream *out) LOG(("nsHalfOpenSocket::OnOutputStreamReady " "Created new nshttpconnection %p\n", conn.get())); + NullHttpTransaction *nullTrans = mTransaction->QueryNullTransaction(); + if (nullTrans) { + conn->BootstrapTimings(nullTrans->Timings()); + } + // Some capabilities are needed before a transaciton actually gets // scheduled (e.g. how to negotiate false start) conn->SetTransactionCaps(mTransaction->Caps()); diff --git a/netwerk/protocol/http/nsHttpTransaction.cpp b/netwerk/protocol/http/nsHttpTransaction.cpp index bc182c6cd..706710d89 100644 --- a/netwerk/protocol/http/nsHttpTransaction.cpp +++ b/netwerk/protocol/http/nsHttpTransaction.cpp @@ -623,6 +623,14 @@ nsHttpTransaction::OnTransportStatus(nsITransport* transport, } else if (status == NS_NET_STATUS_CONNECTED_TO) { SetConnectEnd(TimeStamp::Now(), true); } else if (status == NS_NET_STATUS_TLS_HANDSHAKE_ENDED) { + { + // before overwriting connectEnd, copy it to secureConnectionStart + MutexAutoLock lock(mLock); + if (mTimings.secureConnectionStart.IsNull() && + !mTimings.connectEnd.IsNull()) { + mTimings.secureConnectionStart = mTimings.connectEnd; + } + } SetConnectEnd(TimeStamp::Now(), false); } } @@ -2135,6 +2143,13 @@ nsHttpTransaction::Timings() return timings; } +void +nsHttpTransaction::BootstrapTimings(TimingStruct times) +{ + mozilla::MutexAutoLock lock(mLock); + mTimings = times; +} + void nsHttpTransaction::SetDomainLookupStart(mozilla::TimeStamp timeStamp, bool onlyIfNull) { @@ -2226,6 +2241,13 @@ nsHttpTransaction::GetConnectStart() return mTimings.connectStart; } +mozilla::TimeStamp +nsHttpTransaction::GetSecureConnectionStart() +{ + mozilla::MutexAutoLock lock(mLock); + return mTimings.secureConnectionStart; +} + mozilla::TimeStamp nsHttpTransaction::GetConnectEnd() { diff --git a/netwerk/protocol/http/nsHttpTransaction.h b/netwerk/protocol/http/nsHttpTransaction.h index 788d9c7b3..5bf97d41e 100644 --- a/netwerk/protocol/http/nsHttpTransaction.h +++ b/netwerk/protocol/http/nsHttpTransaction.h @@ -149,6 +149,7 @@ public: // Locked methods to get and set timing info const TimingStruct Timings(); + void BootstrapTimings(TimingStruct times); void SetDomainLookupStart(mozilla::TimeStamp timeStamp, bool onlyIfNull = false); void SetDomainLookupEnd(mozilla::TimeStamp timeStamp, bool onlyIfNull = false); void SetConnectStart(mozilla::TimeStamp timeStamp, bool onlyIfNull = false); @@ -160,6 +161,8 @@ public: mozilla::TimeStamp GetDomainLookupStart(); mozilla::TimeStamp GetDomainLookupEnd(); mozilla::TimeStamp GetConnectStart(); + mozilla::TimeStamp GetSecureConnectionStart(); + mozilla::TimeStamp GetConnectEnd(); mozilla::TimeStamp GetRequestStart(); mozilla::TimeStamp GetResponseStart(); -- cgit v1.2.3