From 2a8db2c0d3c5e2b72a8b40a66145781c3109bac0 Mon Sep 17 00:00:00 2001
From: James M Snell <jasnell@gmail.com>
Date: Tue, 9 Jan 2018 23:24:40 -0800
Subject: [PATCH] dns: add basic perf_hooks support

emit simple perf_hooks timings for dns operations.

```js
const { PerformanceObserver, performance } = require('perf_hooks');
const obs = new PerformanceObserver((items) => {
  const entry = items.getEntries()[0];
  console.log(entry.name, entry.duration);
  performance.clearDNS();
});
obs.observe({ entryTypes: ['dns'] });

dns.resolveAny('example.org', console.log);
```
---
 doc/api/dns.md                       |  20 +++
 doc/api/perf_hooks.md                |   4 +-
 lib/perf_hooks.js                    |   5 +-
 src/cares_wrap.cc                    | 196 +++++++++++++++++++++------
 src/node_perf_common.h               |   3 +-
 test/parallel/test-dns-perf_hooks.js |  49 +++++++
 6 files changed, 233 insertions(+), 44 deletions(-)
 create mode 100644 test/parallel/test-dns-perf_hooks.js

diff --git a/doc/api/dns.md b/doc/api/dns.md
index 4ae44a211a0e06..afcbec303d0177 100644
--- a/doc/api/dns.md
+++ b/doc/api/dns.md
@@ -646,6 +646,25 @@ processing that happens on libuv's threadpool that [`dns.lookup()`][] can have.
 They do not use the same set of configuration files than what [`dns.lookup()`][]
 uses. For instance, _they do not use the configuration from `/etc/hosts`_.
 
+## Monitoring DNS Performance
+
+The [Performance Observer][] API may be used to monitor the duration of DNS
+operations:
+
+```js
+const dns = require('dns');
+const { PerformanceObserver, performance } = require('perf_hooks');
+
+const obs = new PerformanceObserver((items) => {
+  const entry = items.getEntries()[0];
+  console.log(entry.name); // example.org
+  console.log(entry.entryType); // dns
+  console.log(entry.startTime);
+  console.log(entry.duration);
+  performance.clearDNS(); // Always clear to prevent memory leaks
+});
+```
+
 [`Error`]: errors.html#errors_class_error
 [`UV_THREADPOOL_SIZE`]: cli.html#cli_uv_threadpool_size_size
 [`dgram.createSocket()`]: dgram.html#dgram_dgram_createsocket_options_callback
@@ -669,5 +688,6 @@ uses. For instance, _they do not use the configuration from `/etc/hosts`_.
 [`util.promisify()`]: util.html#util_util_promisify_original
 [DNS error codes]: #dns_error_codes
 [Implementation considerations section]: #dns_implementation_considerations
+[Performance Observer]: perf_hooks.html
 [rfc5952]: https://tools.ietf.org/html/rfc5952#section-6
 [supported `getaddrinfo` flags]: #dns_supported_getaddrinfo_flags
diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md
index 2f2910af93db34..2fc574773e3617 100644
--- a/doc/api/perf_hooks.md
+++ b/doc/api/perf_hooks.md
@@ -254,8 +254,8 @@ added: v8.5.0
 
 * {string}
 
-The type of the performance entry. Current it may be one of: `'node'`, `'mark'`,
-`'measure'`, `'gc'`, or `'function'`.
+The type of the performance entry. Currently it may be one of: `'node'`,
+`'mark'`, `'measure'`, `'gc'`, `'function'`, `'http2'`, or `'dns'`.
 
 ### performanceEntry.kind
 <!-- YAML
diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js
index 15256a63c0b97c..a14d245bac14db 100644
--- a/lib/perf_hooks.js
+++ b/lib/perf_hooks.js
@@ -19,6 +19,7 @@ const {
   NODE_PERFORMANCE_ENTRY_TYPE_GC,
   NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION,
   NODE_PERFORMANCE_ENTRY_TYPE_HTTP2,
+  NODE_PERFORMANCE_ENTRY_TYPE_DNS,
 
   NODE_PERFORMANCE_MILESTONE_NODE_START,
   NODE_PERFORMANCE_MILESTONE_V8_START,
@@ -63,7 +64,8 @@ const observerableTypes = [
   'measure',
   'gc',
   'function',
-  'http2'
+  'http2',
+  'dns'
 ];
 
 const IDX_STREAM_STATS_ID = 0;
@@ -579,6 +581,7 @@ function mapTypes(i) {
     case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC;
     case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION;
     case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2;
+    case 'dns': return NODE_PERFORMANCE_ENTRY_TYPE_DNS;
   }
 }
 
diff --git a/src/cares_wrap.cc b/src/cares_wrap.cc
index de3cb8f89c1ea2..fe4d54ea6dd98d 100644
--- a/src/cares_wrap.cc
+++ b/src/cares_wrap.cc
@@ -27,6 +27,7 @@
 #include "req_wrap-inl.h"
 #include "util-inl.h"
 #include "uv.h"
+#include "node_perf.h"
 
 #include <errno.h>
 #include <stdlib.h>
@@ -68,6 +69,8 @@ using v8::Object;
 using v8::String;
 using v8::Value;
 
+using node::performance::PerformanceEntry;
+
 namespace {
 
 inline uint16_t cares_get_16bit(const unsigned char* p) {
@@ -178,6 +181,11 @@ class ChannelWrap : public AsyncWrap {
   node_ares_task_list task_list_;
 };
 
+inline bool HasDNSObserver(Environment* env) {
+  uint32_t* observers = env->performance_state()->observers;
+  return observers[performance::NODE_PERFORMANCE_ENTRY_TYPE_DNS] != 0;
+}
+
 ChannelWrap::ChannelWrap(Environment* env,
                          Local<Object> object)
   : AsyncWrap(env, object, PROVIDER_DNSCHANNEL),
@@ -204,21 +212,29 @@ class GetAddrInfoReqWrap : public ReqWrap<uv_getaddrinfo_t> {
  public:
   GetAddrInfoReqWrap(Environment* env,
                      Local<Object> req_wrap_obj,
-                     bool verbatim);
+                     bool verbatim,
+                     const char* name);
   ~GetAddrInfoReqWrap();
 
   size_t self_size() const override { return sizeof(*this); }
   bool verbatim() const { return verbatim_; }
 
+  void EmitStatistics();
+
  private:
   const bool verbatim_;
+  uint64_t start_time_;
+  std::string name_;
 };
 
 GetAddrInfoReqWrap::GetAddrInfoReqWrap(Environment* env,
                                        Local<Object> req_wrap_obj,
-                                       bool verbatim)
+                                       bool verbatim,
+                                       const char* name)
     : ReqWrap(env, req_wrap_obj, AsyncWrap::PROVIDER_GETADDRINFOREQWRAP)
-    , verbatim_(verbatim) {
+    , verbatim_(verbatim)
+    , start_time_(uv_hrtime())
+    , name_(name) {
   Wrap(req_wrap_obj, this);
 }
 
@@ -226,18 +242,46 @@ GetAddrInfoReqWrap::~GetAddrInfoReqWrap() {
   ClearWrap(object());
 }
 
+void GetAddrInfoReqWrap::EmitStatistics() {
+  if (!HasDNSObserver(env()))
+    return;
+  PerformanceEntry* entry =
+      new PerformanceEntry(env(), name_.c_str(), "dns",
+                           start_time_, uv_hrtime());
+  env()->SetImmediate([](Environment* env, void* data) {
+    PerformanceEntry* entry =
+      static_cast<PerformanceEntry*>(data);
+    if (HasDNSObserver(env)) {
+      entry->Notify(env,
+                    node::performance::NODE_PERFORMANCE_ENTRY_TYPE_DNS,
+                    entry->ToObject());
+    }
+    delete entry;
+  }, static_cast<void*>(entry));
+}
+
 
 class GetNameInfoReqWrap : public ReqWrap<uv_getnameinfo_t> {
  public:
-  GetNameInfoReqWrap(Environment* env, Local<Object> req_wrap_obj);
+  GetNameInfoReqWrap(Environment* env,
+                     Local<Object> req_wrap_obj,
+                     const char* name);
   ~GetNameInfoReqWrap();
 
   size_t self_size() const override { return sizeof(*this); }
+
+  void EmitStatistics();
+ private:
+  uint64_t start_time_;
+  std::string name_;
 };
 
 GetNameInfoReqWrap::GetNameInfoReqWrap(Environment* env,
-                                       Local<Object> req_wrap_obj)
-    : ReqWrap(env, req_wrap_obj, AsyncWrap::PROVIDER_GETNAMEINFOREQWRAP) {
+                                       Local<Object> req_wrap_obj,
+                                       const char* name)
+    : ReqWrap(env, req_wrap_obj, AsyncWrap::PROVIDER_GETNAMEINFOREQWRAP)
+    , start_time_(uv_hrtime())
+    , name_(name) {
   Wrap(req_wrap_obj, this);
 }
 
@@ -245,6 +289,23 @@ GetNameInfoReqWrap::~GetNameInfoReqWrap() {
   ClearWrap(object());
 }
 
+void GetNameInfoReqWrap::EmitStatistics() {
+  if (!HasDNSObserver(env()))
+    return;
+  PerformanceEntry* entry =
+      new PerformanceEntry(env(), name_.c_str(), "dns",
+                           start_time_, uv_hrtime());
+  env()->SetImmediate([](Environment* env, void* data) {
+    PerformanceEntry* entry =
+      static_cast<PerformanceEntry*>(data);
+    if (HasDNSObserver(env)) {
+      entry->Notify(env,
+                    node::performance::NODE_PERFORMANCE_ENTRY_TYPE_DNS,
+                    entry->ToObject());
+    }
+    delete entry;
+  }, static_cast<void*>(entry));
+}
 
 /* This is called once per second by loop->timer. It is used to constantly */
 /* call back into c-ares for possibly processing timeouts. */
@@ -581,12 +642,15 @@ void ChannelWrap::EnsureServers() {
   Setup();
 }
 
-
 class QueryWrap : public AsyncWrap {
  public:
-  QueryWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
+  QueryWrap(ChannelWrap* channel,
+            Local<Object> req_wrap_obj,
+            const char* name)
       : AsyncWrap(channel->env(), req_wrap_obj, AsyncWrap::PROVIDER_QUERYWRAP),
-        channel_(channel) {
+        channel_(channel),
+        start_time_(uv_hrtime()),
+        name_(name) {
     Wrap(req_wrap_obj, this);
 
     // Make sure the channel object stays alive during the query lifetime.
@@ -704,6 +768,24 @@ class QueryWrap : public AsyncWrap {
     uv_async_send(async_handle);
   }
 
+  void EmitStatistics() {
+    Environment* env = this->env();
+    if (!HasDNSObserver(env))
+      return;
+    PerformanceEntry* entry =
+      new PerformanceEntry(env, name_.c_str(), "dns", start_time_, uv_hrtime());
+    env->SetImmediate([](Environment* env, void* data) {
+      PerformanceEntry* entry =
+        static_cast<PerformanceEntry*>(data);
+      if (HasDNSObserver(env)) {
+        entry->Notify(env,
+                      node::performance::NODE_PERFORMANCE_ENTRY_TYPE_DNS,
+                      entry->ToObject());
+      }
+      delete entry;
+    }, static_cast<void*>(entry));
+  }
+
   void CallOnComplete(Local<Value> answer,
                       Local<Value> extra = Local<Value>()) {
     HandleScope handle_scope(env()->isolate());
@@ -714,6 +796,7 @@ class QueryWrap : public AsyncWrap {
       extra
     };
     const int argc = arraysize(argv) - extra.IsEmpty();
+    EmitStatistics();
     MakeCallback(env()->oncomplete_string(), argc, argv);
   }
 
@@ -736,6 +819,8 @@ class QueryWrap : public AsyncWrap {
   }
 
   ChannelWrap* channel_;
+  uint64_t start_time_;
+  std::string name_;
 };
 
 
@@ -1180,8 +1265,10 @@ int ParseSoaReply(Environment* env,
 
 class QueryAnyWrap: public QueryWrap {
  public:
-  QueryAnyWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-    : QueryWrap(channel, req_wrap_obj) {
+  QueryAnyWrap(ChannelWrap* channel,
+               Local<Object> req_wrap_obj,
+               const char* name)
+    : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1357,8 +1444,10 @@ class QueryAnyWrap: public QueryWrap {
 
 class QueryAWrap: public QueryWrap {
  public:
-  QueryAWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryAWrap(ChannelWrap* channel,
+             Local<Object> req_wrap_obj,
+             const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1401,8 +1490,10 @@ class QueryAWrap: public QueryWrap {
 
 class QueryAaaaWrap: public QueryWrap {
  public:
-  QueryAaaaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryAaaaWrap(ChannelWrap* channel,
+                Local<Object> req_wrap_obj,
+                const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1445,8 +1536,10 @@ class QueryAaaaWrap: public QueryWrap {
 
 class QueryCnameWrap: public QueryWrap {
  public:
-  QueryCnameWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryCnameWrap(ChannelWrap* channel,
+                 Local<Object> req_wrap_obj,
+                 const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1476,8 +1569,10 @@ class QueryCnameWrap: public QueryWrap {
 
 class QueryMxWrap: public QueryWrap {
  public:
-  QueryMxWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryMxWrap(ChannelWrap* channel,
+              Local<Object> req_wrap_obj,
+              const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1507,8 +1602,10 @@ class QueryMxWrap: public QueryWrap {
 
 class QueryNsWrap: public QueryWrap {
  public:
-  QueryNsWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryNsWrap(ChannelWrap* channel,
+              Local<Object> req_wrap_obj,
+              const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1538,8 +1635,10 @@ class QueryNsWrap: public QueryWrap {
 
 class QueryTxtWrap: public QueryWrap {
  public:
-  QueryTxtWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QueryTxtWrap(ChannelWrap* channel,
+               Local<Object> req_wrap_obj,
+               const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1568,8 +1667,10 @@ class QueryTxtWrap: public QueryWrap {
 
 class QuerySrvWrap: public QueryWrap {
  public:
-  explicit QuerySrvWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  explicit QuerySrvWrap(ChannelWrap* channel,
+                        Local<Object> req_wrap_obj,
+                        const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1597,8 +1698,10 @@ class QuerySrvWrap: public QueryWrap {
 
 class QueryPtrWrap: public QueryWrap {
  public:
-  explicit QueryPtrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  explicit QueryPtrWrap(ChannelWrap* channel,
+                        Local<Object> req_wrap_obj,
+                        const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1628,8 +1731,10 @@ class QueryPtrWrap: public QueryWrap {
 
 class QueryNaptrWrap: public QueryWrap {
  public:
-  explicit QueryNaptrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  explicit QueryNaptrWrap(ChannelWrap* channel,
+                          Local<Object> req_wrap_obj,
+                          const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1658,8 +1763,10 @@ class QueryNaptrWrap: public QueryWrap {
 
 class QuerySoaWrap: public QueryWrap {
  public:
-  QuerySoaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  QuerySoaWrap(ChannelWrap* channel,
+               Local<Object> req_wrap_obj,
+               const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1719,8 +1826,10 @@ class QuerySoaWrap: public QueryWrap {
 
 class GetHostByAddrWrap: public QueryWrap {
  public:
-  explicit GetHostByAddrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
-      : QueryWrap(channel, req_wrap_obj) {
+  explicit GetHostByAddrWrap(ChannelWrap* channel,
+                             Local<Object> req_wrap_obj,
+                             const char* name)
+      : QueryWrap(channel, req_wrap_obj, name) {
   }
 
   int Send(const char* name) override {
@@ -1769,9 +1878,10 @@ static void Query(const FunctionCallbackInfo<Value>& args) {
 
   Local<Object> req_wrap_obj = args[0].As<Object>();
   Local<String> string = args[1].As<String>();
-  Wrap* wrap = new Wrap(channel, req_wrap_obj);
 
   node::Utf8Value name(env->isolate(), string);
+  Wrap* wrap = new Wrap(channel, req_wrap_obj, *name);
+
   channel->ModifyActivityQueryCount(1);
   int err = wrap->Send(*name);
   if (err) {
@@ -1840,6 +1950,7 @@ void AfterGetAddrInfo(uv_getaddrinfo_t* req, int status, struct addrinfo* res) {
   uv_freeaddrinfo(res);
 
   // Make the callback into JavaScript
+  req_wrap->EmitStatistics();
   req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);
 
   delete req_wrap;
@@ -1871,6 +1982,7 @@ void AfterGetNameInfo(uv_getnameinfo_t* req,
   }
 
   // Make the callback into JavaScript
+  req_wrap->EmitStatistics();
   req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);
 
   delete req_wrap;
@@ -1964,7 +2076,9 @@ void GetAddrInfo(const FunctionCallbackInfo<Value>& args) {
     CHECK(0 && "bad address family");
   }
 
-  auto req_wrap = new GetAddrInfoReqWrap(env, req_wrap_obj, args[4]->IsTrue());
+  auto req_wrap = new GetAddrInfoReqWrap(env, req_wrap_obj,
+                                         args[4]->IsTrue(),
+                                         *hostname);
 
   struct addrinfo hints;
   memset(&hints, 0, sizeof(struct addrinfo));
@@ -1979,9 +2093,10 @@ void GetAddrInfo(const FunctionCallbackInfo<Value>& args) {
                            nullptr,
                            &hints);
   req_wrap->Dispatched();
-  if (err)
+  if (err) {
+    req_wrap->EmitStatistics();
     delete req_wrap;
-
+  }
   args.GetReturnValue().Set(err);
 }
 
@@ -2000,7 +2115,7 @@ void GetNameInfo(const FunctionCallbackInfo<Value>& args) {
   CHECK(uv_ip4_addr(*ip, port, reinterpret_cast<sockaddr_in*>(&addr)) == 0 ||
         uv_ip6_addr(*ip, port, reinterpret_cast<sockaddr_in6*>(&addr)) == 0);
 
-  GetNameInfoReqWrap* req_wrap = new GetNameInfoReqWrap(env, req_wrap_obj);
+  GetNameInfoReqWrap* req_wrap = new GetNameInfoReqWrap(env, req_wrap_obj, *ip);
 
   int err = uv_getnameinfo(env->event_loop(),
                            req_wrap->req(),
@@ -2008,9 +2123,10 @@ void GetNameInfo(const FunctionCallbackInfo<Value>& args) {
                            (struct sockaddr*)&addr,
                            NI_NAMEREQD);
   req_wrap->Dispatched();
-  if (err)
+  if (err) {
+    req_wrap->EmitStatistics();
     delete req_wrap;
-
+  }
   args.GetReturnValue().Set(err);
 }
 
diff --git a/src/node_perf_common.h b/src/node_perf_common.h
index 713f126d7f70d9..0b1370c0aed26c 100644
--- a/src/node_perf_common.h
+++ b/src/node_perf_common.h
@@ -39,7 +39,8 @@ extern uint64_t performance_v8_start;
   V(MEASURE, "measure")                                                       \
   V(GC, "gc")                                                                 \
   V(FUNCTION, "function")                                                     \
-  V(HTTP2, "http2")
+  V(HTTP2, "http2")                                                           \
+  V(DNS, "dns")
 
 enum PerformanceMilestone {
 #define V(name, _) NODE_PERFORMANCE_MILESTONE_##name,
diff --git a/test/parallel/test-dns-perf_hooks.js b/test/parallel/test-dns-perf_hooks.js
new file mode 100644
index 00000000000000..ff3b1fbb08facb
--- /dev/null
+++ b/test/parallel/test-dns-perf_hooks.js
@@ -0,0 +1,49 @@
+'use strict';
+
+const common = require('../common');
+const assert = require('assert');
+const dns = require('dns');
+const dnstools = require('../common/dns');
+const dgram = require('dgram');
+const Countdown = require('../common/countdown');
+
+const { PerformanceObserver, performance } = require('perf_hooks');
+
+const obs = new PerformanceObserver(common.mustCall((items) => {
+  const entry = items.getEntries()[0];
+  assert.strictEqual(entry.name, 'example.org');
+  assert.strictEqual(entry.entryType, 'dns');
+  assert.strictEqual(typeof entry.startTime, 'number');
+  assert.strictEqual(typeof entry.duration, 'number');
+  performance.clearDNS();
+}, 3));
+obs.observe({ entryTypes: ['dns'] });
+
+const answers = [
+  { type: 'A', address: '1.2.3.4', ttl: 123 },
+  { type: 'AAAA', address: '::42', ttl: 123 }
+];
+
+const server = dgram.createSocket('udp4');
+
+const countdown = new Countdown(3, () => server.close());
+
+server.on('message', common.mustCall((msg, { address, port }) => {
+  const parsed = dnstools.parseDNSPacket(msg);
+  const domain = parsed.questions[0].domain;
+
+  server.send(dnstools.writeDNSPacket({
+    id: parsed.id,
+    questions: parsed.questions,
+    answers: answers.map((answer) => Object.assign({ domain }, answer)),
+  }), port, address);
+}, 3));
+
+server.bind(0, common.mustCall(() => {
+  const address = server.address();
+  dns.setServers([`127.0.0.1:${address.port}`]);
+
+  dns.resolveAny('example.org', common.mustCall(() => countdown.dec()));
+  dns.resolve4('example.org', common.mustCall(() => countdown.dec()));
+  dns.resolve6('example.org', common.mustCall(() => countdown.dec()));
+}));