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

@@ -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 {

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"],