net.adns: Collect DNS lookup timing metrics

Nice to have this in OpenMetricts instead of debug logs

3 files changed, 34 insertions, 5 deletions

diff --git a/net/adns.lua b/net/adns.lua
index 2ecd7f53..59f19302 100644
--- a/net/adns.lua
+++ b/net/adns.lua
@@ -74,11 +74,17 @@ local function new_async_socket(sock, resolver)
 	return handler;
 end
 
+local function measure(_qclass, _qtype)
+	return measure;
+end
+
 function async_resolver_methods:lookup(handler, qname, qtype, qclass)
 	local resolver = self._resolver;
+	local m = measure(qclass or "IN", qtype or "A");
 	return coroutine.wrap(function (peek)
 				if peek then
 					log("debug", "Records for %s already cached, using those...", qname);
+					m();
 					handler(peek);
 					return;
 				end
@@ -89,6 +95,7 @@ function async_resolver_methods:lookup(handler, qname, qtype, qclass)
 					log("debug", "Reply for %s (%s)", qname, coroutine.running());
 				end
 				if ok then
+					m();
 					ok, err = pcall(handler, resolver:peek(qname, qtype, qclass));
 				else
 					log("error", "Error sending DNS query: %s", err);
@@ -129,4 +136,5 @@ return {
 	end;
 	resolver = new_async_resolver;
 	new_async_socket = new_async_socket;
+	instrument = function(measure_) measure = measure_; end;
 };
diff --git a/net/unbound.lua b/net/unbound.lua
index 176a6156..557a37fc 100644
--- a/net/unbound.lua
+++ b/net/unbound.lua
@@ -20,7 +20,6 @@ local libunbound = require"lunbound";
 local promise = require"prosody.util.promise";
 local new_id = require "prosody.util.id".short;
 
-local gettime = require"socket".gettime;
 local dns_utils = require"prosody.util.dns";
 local classes, types, errors = dns_utils.classes, dns_utils.types, dns_utils.errors;
 local parsers = dns_utils.parsers;
@@ -116,21 +115,26 @@ local function prep_answer(a)
 	return setmetatable(a, answer_mt);
 end
 
+local function measure(_qclass, _qtype)
+	return measure;
+end
+
 local function lookup(callback, qname, qtype, qclass)
 	if not unbound then initialize(); end
 	qtype = qtype and s_upper(qtype) or "A";
 	qclass = qclass and s_upper(qclass) or "IN";
 	local ntype, nclass = types[qtype], classes[qclass];
-	local startedat = gettime();
+
+	local m;
 	local ret;
 	local log_query = logger.init("unbound.query"..new_id());
 	local function callback_wrapper(a, err)
-		local gotdataat = gettime();
+		m();
 		waiting_queries[ret] = nil;
 		if a then
 			prep_answer(a);
-			log_query("debug", "Results for %s %s %s: %s (%s, %f sec)", qname, qclass, qtype, a.rcode == 0 and (#a .. " items") or a.status,
-				a.secure and "Secure" or a.bogus or "Insecure", gotdataat - startedat); -- Insecure as in unsigned
+			log_query("debug", "Results for %s %s %s: %s (%s)", qname, qclass, qtype, a.rcode == 0 and (#a .. " items") or a.status,
+				a.secure and "Secure" or a.bogus or "Insecure"); -- Insecure as in unsigned
 		else
 			log_query("error", "Results for %s %s %s: %s", qname, qclass, qtype, tostring(err));
 		end
@@ -138,6 +142,7 @@ local function lookup(callback, qname, qtype, qclass)
 		if not ok then log_query("error", "Error in callback: %s", cerr); end
 	end
 	log_query("debug", "Resolve %s %s %s", qname, qclass, qtype);
+	m = measure(qclass, qtype);
 	local err;
 	ret, err = unbound:resolve_async(callback_wrapper, qname, ntype, nclass);
 	if ret then
@@ -225,6 +230,8 @@ local wrapper = {
 	};
 }
 
+_M.instrument = function(measure_) measure = measure_; end;
+
 function _M.resolver() return wrapper; end
 
 return _M;
diff --git a/util/startup.lua b/util/startup.lua
index 2fa2d0b2..34c2f733 100644
--- a/util/startup.lua
+++ b/util/startup.lua
@@ -425,6 +425,19 @@ function startup.init_async()
 	async.set_schedule_function(timer.add_task);
 end
 
+function startup.instrument()
+	local statsmanager = require "prosody.core.statsmanager";
+	local timed = require"prosody.util.openmetrics".timed;
+
+	local adns = require "prosody.net.adns";
+	if adns.instrument then
+		local m = statsmanager.metric("histogram", "prosody_dns", "seconds", "DNS lookups", { "qclass"; "qtype" }, {
+				buckets = { 1 / 1024; 1 / 256; 1 / 64; 1 / 16; 1 / 4; 1; 4 };
+		});
+		adns.instrument(function(qclass, qtype) return timed(m:with_labels(qclass, qtype)); end);
+	end
+end
+
 function startup.init_data_store()
 	require "prosody.core.storagemanager";
 end
@@ -922,6 +935,7 @@ function startup.prosody()
 	startup.load_secondary_libraries();
 	startup.init_promise();
 	startup.init_async();
+	startup.instrument();
 	startup.init_http_client();
 	startup.init_data_store();
 	startup.init_global_protection();