net.adns: Collect DNS lookup timing metrics

Nice to have this in OpenMetricts instead of debug logs
This commit is contained in:
Kim Alvefur 2025-02-07 09:22:52 +01:00
parent 3d61988313
commit b4e8a8c6c4
3 changed files with 34 additions and 5 deletions

View file

@ -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;
};

View file

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

View file

@ -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();