From 19178da979e43b3d9c6614695cc4988b503354ad Mon Sep 17 00:00:00 2001
From: bert hubert <bert.hubert@netherlabs.nl>
Date: Fri, 6 Oct 2017 13:20:15 +0200
Subject: [PATCH] Implement experimental metric tracking time spent within
 PowerDNS per query

With this commit, PowerDNS provides metrics on the difference between the time spent waiting for authoritative servers, and the amount of time elapsed between arrival of query
and sending out the response. This metric should be seen as experimental until operational experience proves its relevance.
---
 pdns/pdns_recursor.cc              | 25 +++++++++++++++++-
 pdns/rec_channel_rec.cc            | 10 +++++++
 pdns/recursordist/docs/metrics.rst | 42 ++++++++++++++++++++++++++++++
 pdns/syncres.hh                    |  4 ++-
 4 files changed, 79 insertions(+), 2 deletions(-)

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index 01fc6e3415..55b88eeb0e 100644
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -1237,7 +1237,7 @@ static void startDoResolve(void *p)
     }
 
     sr.d_outqueries ? t_RC->cacheMisses++ : t_RC->cacheHits++;
-
+            
     if(spent < 0.001)
       g_stats.answers0_1++;
     else if(spent < 0.010)
@@ -1253,6 +1253,28 @@ static void startDoResolve(void *p)
     newLat = min(newLat,(uint64_t)(((uint64_t) g_networkTimeoutMsec)*1000)); // outliers of several minutes exist..
     g_stats.avgLatencyUsec=(1-1.0/g_latencyStatSize)*g_stats.avgLatencyUsec + (float)newLat/g_latencyStatSize;
     // no worries, we do this for packet cache hits elsewhere
+
+    auto ourtime = 1000.0*spent-sr.d_totUsec/1000.0; // in msec
+    if(ourtime < 1)
+      g_stats.ourtime0_1++;
+    else if(ourtime < 2)
+      g_stats.ourtime1_2++;
+    else if(ourtime < 4)
+      g_stats.ourtime2_4++;
+    else if(ourtime < 8)
+      g_stats.ourtime4_8++;
+    else if(ourtime < 16)
+      g_stats.ourtime8_16++;
+    else if(ourtime < 32)
+      g_stats.ourtime16_32++;
+    else {
+      //      cerr<<"SLOW: "<<ourtime<<"ms -> "<<dc->d_mdp.d_qname<<"|"<<DNSRecordContent::NumberToType(dc->d_mdp.d_qtype)<<endl;
+      g_stats.ourtimeSlow++;
+    }
+
+    newLat=ourtime*1000; // usec
+    g_stats.avgLatencyOursUsec=(1-1.0/g_latencyStatSize)*g_stats.avgLatencyOursUsec + (float)newLat/g_latencyStatSize;
+    
     //    cout<<dc->d_mdp.d_qname<<"\t"<<MT->getUsec()<<"\t"<<sr.d_outqueries<<endl;
     delete dc;
     dc=0;
@@ -1691,6 +1713,7 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
         updateResponseStats(tmpdh.rcode, fromaddr, response.length(), 0, 0);
       }
       g_stats.avgLatencyUsec=(1-1.0/g_latencyStatSize)*g_stats.avgLatencyUsec + 0.0; // we assume 0 usec
+      g_stats.avgLatencyOursUsec=(1-1.0/g_latencyStatSize)*g_stats.avgLatencyOursUsec + 0.0; // we assume 0 usec
       return 0;
     }
   }
diff --git a/pdns/rec_channel_rec.cc b/pdns/rec_channel_rec.cc
index 0e6b34854e..ee26c9de7a 100644
--- a/pdns/rec_channel_rec.cc
+++ b/pdns/rec_channel_rec.cc
@@ -873,6 +873,15 @@ void registerAllStats()
   addGetStat("answers100-1000", &g_stats.answers100_1000);
   addGetStat("answers-slow", &g_stats.answersSlow);
 
+  addGetStat("x-ourtime0-1", &g_stats.ourtime0_1);
+  addGetStat("x-ourtime1-2", &g_stats.ourtime1_2);
+  addGetStat("x-ourtime2-4", &g_stats.ourtime2_4);
+  addGetStat("x-ourtime4-8", &g_stats.ourtime4_8);
+  addGetStat("x-ourtime8-16", &g_stats.ourtime8_16);
+  addGetStat("x-ourtime16-32", &g_stats.ourtime16_32);
+  addGetStat("x-ourtime-slow", &g_stats.ourtimeSlow);
+  
+  
   addGetStat("auth4-answers0-1", &g_stats.auth4Answers0_1);
   addGetStat("auth4-answers1-10", &g_stats.auth4Answers1_10);
   addGetStat("auth4-answers10-100", &g_stats.auth4Answers10_100);
@@ -887,6 +896,7 @@ void registerAllStats()
 
 
   addGetStat("qa-latency", doGetAvgLatencyUsec);
+  addGetStat("x-our-latency", []() { return g_stats.avgLatencyOursUsec; });
   addGetStat("unexpected-packets", &g_stats.unexpectedCount);
   addGetStat("case-mismatches", &g_stats.caseMismatchCount);
   addGetStat("spoof-prevents", &g_stats.spoofCount);
diff --git a/pdns/recursordist/docs/metrics.rst b/pdns/recursordist/docs/metrics.rst
index 760b06e737..9eb408b22b 100644
--- a/pdns/recursordist/docs/metrics.rst
+++ b/pdns/recursordist/docs/metrics.rst
@@ -439,3 +439,45 @@ number of seconds process has been running (since 3.1.5)
 user-msec
 ^^^^^^^^^
 number of CPU milliseconds spent in 'user' mode
+
+x-our-latency
+^^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. PowerDNS measures per query how much time has been spent waiting on
+authoritative servers. In addition, the Recursor measures the total amount of time needed to answer a question. The
+difference between these two durations is a measure of how much time was spent within PowerDNS. This metric is the average
+of that difference, in microseconds. Since 4.1.
+
+x-ourtime0-1
+^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 0 and 1 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime1-2
+^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 1 and 2 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime2-4
+^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 2 and 4 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime4-8
+^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 4 and 8 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime8-16
+^^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 8 and 16 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime16-32
+^^^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where between 16 and 32 milliseconds was spent within the Recursor. Since 4.1.
+
+x-ourtime-slow
+^^^^^^^^^^^^^^
+New metric, which is not yet proven to be reliable. See x-our-latency for further details. Counts responses
+where more than 32 milliseconds was spent within the Recursor. Since 4.1.
diff --git a/pdns/syncres.hh b/pdns/syncres.hh
index 5e7f20a1a8..e0018d26e8 100644
--- a/pdns/syncres.hh
+++ b/pdns/syncres.hh
@@ -870,7 +870,9 @@ struct RecursorStats
   std::atomic<uint64_t> answers0_1, answers1_10, answers10_100, answers100_1000, answersSlow;
   std::atomic<uint64_t> auth4Answers0_1, auth4Answers1_10, auth4Answers10_100, auth4Answers100_1000, auth4AnswersSlow;
   std::atomic<uint64_t> auth6Answers0_1, auth6Answers1_10, auth6Answers10_100, auth6Answers100_1000, auth6AnswersSlow;
-  double avgLatencyUsec;
+  std::atomic<uint64_t> ourtime0_1, ourtime1_2, ourtime2_4, ourtime4_8, ourtime8_16, ourtime16_32, ourtimeSlow;
+  double avgLatencyUsec{0};
+  double avgLatencyOursUsec{0};
   std::atomic<uint64_t> qcounter;     // not increased for unauth packets
   std::atomic<uint64_t> ipv6qcounter;
   std::atomic<uint64_t> tcpqcounter;
-- 
2.47.3