Bug 1336182 - Part 1: Add DTLS handshake time telemetry. r=drno, r?bsmedberg draft
authorByron Campen [:bwc] <docfaraday@gmail.com>
Fri, 03 Feb 2017 17:01:05 -0600
changeset 482007 7c28fb37ddaa949f887fd2a64ed7b001e984f16c
parent 479455 12c02bf624c48903b155428f7c8a419ba7a333a6
child 482008 468b600cc3e2c6bf6d49522e6e60c20e03bec9f5
push id44980
push userbcampen@mozilla.com
push dateFri, 10 Feb 2017 21:04:24 +0000
reviewersdrno, bsmedberg
bugs1336182
milestone54.0a1
Bug 1336182 - Part 1: Add DTLS handshake time telemetry. r=drno, r?bsmedberg MozReview-Commit-ID: JczL8eFuzMg
media/mtransport/transportlayerdtls.cpp
media/mtransport/transportlayerdtls.h
toolkit/components/telemetry/Histograms.json
--- a/media/mtransport/transportlayerdtls.cpp
+++ b/media/mtransport/transportlayerdtls.cpp
@@ -11,16 +11,17 @@
 #include <algorithm>
 #include <queue>
 #include <sstream>
 
 #include "dtlsidentity.h"
 #include "keyhi.h"
 #include "logging.h"
 #include "mozilla/Move.h"
+#include "mozilla/Telemetry.h"
 #include "mozilla/UniquePtr.h"
 #include "mozilla/Unused.h"
 #include "nsCOMPtr.h"
 #include "nsComponentManagerUtils.h"
 #include "nsComponentManagerUtils.h"
 #include "nsIEventTarget.h"
 #include "nsNetCID.h"
 #include "nsServiceManagerUtils.h"
@@ -864,16 +865,18 @@ void TransportLayerDtls::StateChange(Tra
       break;
   }
 }
 
 void TransportLayerDtls::Handshake() {
   // Clear the retransmit timer
   timer_->Cancel();
 
+  MOZ_ASSERT(state_ == TS_CONNECTING);
+
   SECStatus rv = SSL_ForceHandshake(ssl_fd_.get());
 
   if (rv == SECSuccess) {
     MOZ_MTLOG(ML_NOTICE,
               LAYER_INFO << "****** SSL handshake completed ******");
     if (!cert_ok_) {
       MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Certificate check never occurred");
       TL_SET_STATE(TS_ERROR);
@@ -1029,16 +1032,44 @@ void TransportLayerDtls::PacketReceived(
           MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "NSS Error " << err);
           TL_SET_STATE(TS_ERROR);
         }
       }
     } while (rv > 0);
   }
 }
 
+void TransportLayerDtls::SetState(State state,
+                                  const char *file,
+                                  unsigned line) {
+  if (state > state_) {
+    switch (state) {
+      case TS_NONE:
+      case TS_INIT:
+        MOZ_ASSERT(false);
+        break;
+      case TS_CONNECTING:
+        handshake_started_ = TimeStamp::Now();
+        break;
+      case TS_OPEN:
+      case TS_CLOSED:
+      case TS_ERROR:
+        timer_->Cancel();
+        if (state_ == TS_CONNECTING) {
+          RecordHandshakeCompletionTelemetry(state);
+        }
+        break;
+    }
+  } else {
+    MOZ_ASSERT(false, "Invalid state transition");
+  }
+
+  TransportLayer::SetState(state, file, line);
+}
+
 TransportResult TransportLayerDtls::SendPacket(const unsigned char *data,
                                                size_t len) {
   CheckThread();
   if (state_ != TS_OPEN) {
     MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Can't call SendPacket() in state "
               << state_);
     return TE_ERROR;
   }
@@ -1254,9 +1285,45 @@ SECStatus TransportLayerDtls::AuthCertif
 void TransportLayerDtls::TimerCallback(nsITimer *timer, void *arg) {
   TransportLayerDtls *dtls = reinterpret_cast<TransportLayerDtls *>(arg);
 
   MOZ_MTLOG(ML_DEBUG, "DTLS timer expired");
 
   dtls->Handshake();
 }
 
+void
+TransportLayerDtls::RecordHandshakeCompletionTelemetry(
+    TransportLayer::State endState) {
+  int32_t delta = (TimeStamp::Now() - handshake_started_).ToMilliseconds();
+
+  switch (endState) {
+    case TransportLayer::State::TS_OPEN:
+      if (role_ == TransportLayerDtls::CLIENT) {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_CLIENT_SUCCESS_TIME,
+                              delta);
+      } else {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_SERVER_SUCCESS_TIME,
+                              delta);
+      }
+      return;
+    case TransportLayer::State::TS_ERROR:
+      if (role_ == TransportLayerDtls::CLIENT) {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_CLIENT_FAILURE_TIME,
+                              delta);
+      } else {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_SERVER_FAILURE_TIME,
+                              delta);
+      }
+      return;
+    case TransportLayer::State::TS_CLOSED:
+      if (role_ == TransportLayerDtls::CLIENT) {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_CLIENT_ABORT_TIME, delta);
+      } else {
+        Telemetry::Accumulate(Telemetry::WEBRTC_DTLS_SERVER_ABORT_TIME, delta);
+      }
+      return;
+    default:
+      MOZ_ASSERT(false);
+  }
+}
+
 }  // close namespace
--- a/media/mtransport/transportlayerdtls.h
+++ b/media/mtransport/transportlayerdtls.h
@@ -11,16 +11,17 @@
 
 #include <queue>
 #include <set>
 
 #include "sigslot.h"
 
 #include "mozilla/RefPtr.h"
 #include "mozilla/UniquePtr.h"
+#include "mozilla/TimeStamp.h"
 #include "nsCOMPtr.h"
 #include "nsIEventTarget.h"
 #include "nsITimer.h"
 #include "ScopedNSSTypes.h"
 #include "m_cpp_utils.h"
 #include "dtlsidentity.h"
 #include "transportflow.h"
 #include "transportlayer.h"
@@ -101,16 +102,19 @@ class TransportLayerDtls final : public 
   void PacketReceived(TransportLayer* layer, const unsigned char *data,
                       size_t len);
 
   // For testing use only.  Returns the fd.
   PRFileDesc* internal_fd() { CheckThread(); return ssl_fd_.get(); }
 
   TRANSPORT_LAYER_ID("dtls")
 
+  protected:
+  void SetState(State state, const char *file, unsigned line) override;
+
   private:
   DISALLOW_COPY_ASSIGN(TransportLayerDtls);
 
   // A single digest to check
   class VerificationDigest {
    public:
     VerificationDigest(std::string algorithm,
                        const unsigned char *value, size_t len) {
@@ -152,16 +156,18 @@ class TransportLayerDtls final : public 
                                 PRBool checksig,
                                 PRBool isServer);
 
   static void TimerCallback(nsITimer *timer, void *arg);
 
   SECStatus CheckDigest(const RefPtr<VerificationDigest>& digest,
                         UniqueCERTCertificate& cert) const;
 
+  void RecordHandshakeCompletionTelemetry(TransportLayer::State endState);
+
   RefPtr<DtlsIdentity> identity_;
   // What ALPN identifiers are permitted.
   std::set<std::string> alpn_allowed_;
   // What ALPN identifier is used if ALPN is not supported.
   // The empty string indicates that ALPN is required.
   std::string alpn_default_;
   // What ALPN string was negotiated.
   std::string alpn_;
@@ -174,13 +180,14 @@ class TransportLayerDtls final : public 
   // Must delete nspr_io_adapter after ssl_fd_ b/c ssl_fd_ causes an alert
   // (ssl_fd_ contains an un-owning pointer to nspr_io_adapter_)
   UniquePtr<TransportLayerNSPRAdapter> nspr_io_adapter_;
   UniquePRFileDesc ssl_fd_;
 
   nsCOMPtr<nsITimer> timer_;
   bool auth_hook_called_;
   bool cert_ok_;
+  TimeStamp handshake_started_;
 };
 
 
 }  // close namespace
 #endif
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -6919,16 +6919,70 @@
     "description": "The H.264 profile number (profile_idc) as extracted from the decoded SPS."
   },
   "VIDEO_H264_SPS_MAX_NUM_REF_FRAMES": {
     "expires_in_version": "55",
     "kind": "enumerated",
     "n_values": 17,
     "description": "SPS.max_num_ref_frames indicates how deep the H.264 queue is going to be, and as such the minimum memory usage by the decoder, from 0 to 16. 17 indicates an invalid value."
   },
+  "WEBRTC_DTLS_CLIENT_SUCCESS_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a client DTLS handshake to complete, given that DTLS succeeded."
+  },
+  "WEBRTC_DTLS_CLIENT_ABORT_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a client DTLS handshake to be aborted due to some external factor (eg; PeerConnection torn down)."
+  },
+  "WEBRTC_DTLS_CLIENT_FAILURE_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a client DTLS handshake to complete, given that it failed."
+  },
+  "WEBRTC_DTLS_SERVER_SUCCESS_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a server DTLS handshake to complete, given that DTLS succeeded."
+  },
+  "WEBRTC_DTLS_SERVER_ABORT_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a server DTLS handshake to be aborted due to some external factor (eg; PeerConnection torn down)."
+  },
+  "WEBRTC_DTLS_SERVER_FAILURE_TIME": {
+    "alert_emails": ["webrtc-dtls-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1336182],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "description": "The length of time (in milliseconds) it took for a server DTLS handshake to complete, given that it failed."
+  },
   "WEBRTC_ICE_FINAL_CONNECTION_STATE": {
     "alert_emails": ["webrtc-ice-telemetry-alerts@mozilla.com"],
     "bug_numbers": [1319268],
     "expires_in_version": "58",
     "kind": "enumerated",
     "n_values": 7,
     "description": "The ICE connection state when the PC was closed"
   },