From 885e8292022c451d9612322482d9836846a90ae3 Mon Sep 17 00:00:00 2001
From: Valentin Gosu <valentin.gosu@gmail.com>
Date: Tue, 14 Jan 2020 12:11:46 +0000
Subject: [PATCH] Bug 1608114 - Diagnose ~20ms delay processing a DoH response
 r=dragana

* Enables timing for TRR channels and records telemetry with time elapsed
  between the responseEnd and when the listener is notified with the
  nsHostRecord object

Differential Revision: https://phabricator.services.mozilla.com/D59739

--HG--
extra : moz-landing-system : lando
---
 netwerk/dns/TRR.cpp                          | 28 ++++++++++++++++++++
 toolkit/components/telemetry/Histograms.json | 12 +++++++++
 2 files changed, 40 insertions(+)

diff --git a/netwerk/dns/TRR.cpp b/netwerk/dns/TRR.cpp
index c6ad55e475e1..67b98295e2db 100644
--- a/netwerk/dns/TRR.cpp
+++ b/netwerk/dns/TRR.cpp
@@ -14,6 +14,7 @@
 #include "nsIInputStream.h"
 #include "nsISupportsBase.h"
 #include "nsISupportsUtils.h"
+#include "nsITimedChannel.h"
 #include "nsIUploadChannel2.h"
 #include "nsNetUtil.h"
 #include "nsStringStream.h"
@@ -332,6 +333,10 @@ nsresult TRR::SendHTTPRequest() {
           NS_LITERAL_CSTRING("application/dns-message")))) {
     LOG(("TRR::SendHTTPRequest: couldn't set content-type!\n"));
   }
+
+  nsCOMPtr<nsITimedChannel> timedChan(do_QueryInterface(httpChannel));
+  timedChan->SetTimingEnabled(true);
+
   if (NS_SUCCEEDED(httpChannel->AsyncOpen(this))) {
     NS_NewTimerWithCallback(getter_AddRefs(mTimeout), this,
                             gTRRService->GetRequestTimeout(),
@@ -991,6 +996,28 @@ nsresult TRR::On200Response() {
   return NS_ERROR_FAILURE;
 }
 
+static void RecordProcessingTime(nsIChannel* aChannel) {
+  // This method records the time it took from the last received byte of the
+  // DoH response until we've notified the consumer with a host record.
+  nsCOMPtr<nsITimedChannel> timedChan = do_QueryInterface(aChannel);
+  if (!timedChan) {
+    return;
+  }
+  TimeStamp end;
+  if (NS_FAILED(timedChan->GetResponseEnd(&end))) {
+    return;
+  }
+
+  if (end.IsNull()) {
+    return;
+  }
+
+  Telemetry::AccumulateTimeDelta(Telemetry::DNS_TRR_PROCESSING_TIME, end);
+
+  LOG(("Processing DoH response took %f ms",
+       (TimeStamp::Now() - end).ToMilliseconds()));
+}
+
 NS_IMETHODIMP
 TRR::OnStopRequest(nsIRequest* aRequest, nsresult aStatusCode) {
   // The dtor will be run after the function returns
@@ -1025,6 +1052,7 @@ TRR::OnStopRequest(nsIRequest* aRequest, nsresult aStatusCode) {
     if (NS_SUCCEEDED(rv) && httpStatus == 200) {
       rv = On200Response();
       if (NS_SUCCEEDED(rv)) {
+        RecordProcessingTime(channel);
         return rv;
       }
     } else {
diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json
index a33a2759b485..f5bcd00b54ff 100644
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -3882,6 +3882,18 @@
     "n_buckets": 50,
     "description": "Time for a completed TRR resolution (msec)"
   },
+  "DNS_TRR_PROCESSING_TIME": {
+    "record_in_processes": ["main"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 1000,
+    "releaseChannelCollection": "opt-out",
+    "alert_emails": ["necko@mozilla.com"],
+    "bug_numbers": [1608114],
+    "n_buckets": 50,
+    "description": "Time from the last received byte of the response until we have notified the consumer with a DNS record (msec)"
+  },
   "DNS_NATIVE_LOOKUP_TIME": {
     "record_in_processes": ["main"],
     "products": ["firefox", "fennec", "geckoview"],