new: dev: Add DTRACE probes to the delegation cache

The new delegation cache, which stores NS-based and DELEG-based delegations per view, is now instrumented
with static user-space tracing probes so that cache hit rate, insertion and lookup latency, eviction pressure
under memory limits, and removals triggered by rndc flush-delegation can be observed on a running named.

Merge branch 'ondrej/delegdb-dtrace-probes' into 'main'

See merge request isc-projects/bind9!11855

REUSE.toml

@@ -177,7 +177,8 @@ path = [
 	"doc/misc/options",
 	"doc/misc/rndc.grammar",
 	"sonar-project.properties",
-	"tests/bench/names.csv"
+	"tests/bench/names.csv",
+	"dtrace/*"
 ]
 precedence = "aggregate"
 SPDX-FileCopyrightText = "Internet Systems Consortium, Inc. (\"ISC\")"

dtrace/README.md

@@ -0,0 +1,43 @@
+# dtrace/
+
+Example trace scripts for BIND 9's static user-space (USDT) probes.
+
+## What's instrumented
+
+BIND 9 ships USDT probes declared in three providers:
+
+- `lib/dns/probes-dns.d` — provider `libdns` (`xfrin_*`, `delegdb_*`)
+- `lib/ns/probes-ns.d`   — provider `libns`  (`rrl_*`)
+- `lib/isc/probes-isc.d` — provider `libisc` (`rwlock_*`, `job_*`)
+
+The probes compile to zero-cost nops when no consumer is attached, and
+are only wired up when the build finds `dtrace` and `sys/sdt.h` (meson
+option `-Dtracing=auto|enabled`, default `auto`).  With
+`-Dtracing=disabled` the probe macros are stripped entirely.
+
+## Listing available probes
+
+On Linux (SystemTap / USDT):
+
+    stap -l 'process("/path/to/named").mark("*")' | sort
+
+On FreeBSD or macOS (DTrace):
+
+    dtrace -l -n 'libdns*:::*'
+
+## Scripts
+
+| Script | Purpose |
+|---|---|
+| [`delegdb-trace.stp`](delegdb-trace.stp) | Streams every insertion, eviction, and `rndc flush-delegation` removal in the delegation cache. |
+
+## Running a script
+
+The scripts take the `named` binary path as their first positional
+argument, so they work with either an installed or a freshly-built
+named:
+
+    sudo stap dtrace/delegdb-trace.stp /usr/sbin/named -x $(pidof named)
+    sudo stap dtrace/delegdb-trace.stp build/named -c "build/named -g -f"
+
+The `-c` form runs `named` under stap's supervision and exits with it.

dtrace/delegdb-trace.stp

@@ -0,0 +1,46 @@
+#!/usr/bin/env stap
+#
+# delegdb-trace.stp - trace delegation cache mutations
+#
+# Prints every insertion and every removal (both explicit deletes via
+# rndc flush-delegation and implicit SIEVE-LRU evictions under memory
+# pressure) from the delegdb.
+#
+# Usage:
+#   sudo stap delegdb-trace.stp /path/to/named
+#   sudo stap delegdb-trace.stp /path/to/named -x <pid>
+#
+# Output columns: elapsed milliseconds, operation, isc_result_t code (or
+# "-" for evict), and the zonecut name.  Trees deleted via
+# rndc flush-delegation -tree are labelled DELTREE.
+
+global start_time
+
+probe begin {
+	start_time = gettimeofday_ms()
+	printf("%-10s %-8s %-7s %s\n", "ms", "op", "result", "zonecut")
+}
+
+probe process(@1).mark("delegdb_insert_done") {
+	printf("%-10d %-8s %-7d %s\n",
+	       gettimeofday_ms() - start_time,
+	       "INSERT",
+	       $arg3,
+	       user_string($arg2))
+}
+
+probe process(@1).mark("delegdb_delete") {
+	printf("%-10d %-8s %-7d %s\n",
+	       gettimeofday_ms() - start_time,
+	       $arg3 ? "DELTREE" : "DELETE",
+	       $arg4,
+	       user_string($arg2))
+}
+
+probe process(@1).mark("delegdb_evict") {
+	printf("%-10d %-8s %-7s %s\n",
+	       gettimeofday_ms() - start_time,
+	       "EVICT",
+	       "-",
+	       user_string($arg3))
+}

lib/dns/deleg.c

@@ -24,6 +24,8 @@
 #include <dns/qp.h>
 #include <dns/view.h>
 
+#include "probes-dns.h"
+
 #define DELEGDB_NODE_MAGIC	 ISC_MAGIC('D', 'e', 'G', 'N')
 #define VALID_DELEGDB_NODE(node) ISC_MAGIC_VALID(node, DELEGDB_NODE_MAGIC)
 
@@ -225,6 +227,8 @@ dns_delegdb_create(dns_delegdb_t **delegdbp) {
 		ISC_SIEVE_INIT(delegdb->lru[i]);
 	}
 
+	LIBDNS_DELEGDB_CREATE(delegdb);
+
 	*delegdbp = delegdb;
 }
 
@@ -236,6 +240,8 @@ dns_delegdb_reuse(dns_view_t *oldview, dns_view_t *newview) {
 
 	dns_delegdb_attach(oldview->deleg, &newview->deleg);
 	isc_refcount_increment(&oldview->deleg->owners);
+
+	LIBDNS_DELEGDB_REUSE(newview->deleg);
 }
 
 typedef struct nodes_rcu_head {
@@ -355,6 +361,14 @@ dns_delegdb_lookup(dns_delegdb_t *delegdb, const dns_name_t *name,
 	isc_result_t result = ISC_R_SHUTTINGDOWN;
 	dns_qpmulti_t *nodes = NULL;
 	dns_qpread_t qpr = {};
+	char namebuf[DNS_NAME_FORMATSIZE];
+
+	if (LIBDNS_DELEGDB_LOOKUP_START_ENABLED() ||
+	    LIBDNS_DELEGDB_LOOKUP_DONE_ENABLED())
+	{
+		dns_name_format(name, namebuf, sizeof(namebuf));
+	}
+	LIBDNS_DELEGDB_LOOKUP_START(delegdb, namebuf);
 
 	rcu_read_lock();
 	nodes = rcu_dereference(delegdb->nodes);
@@ -367,6 +381,8 @@ dns_delegdb_lookup(dns_delegdb_t *delegdb, const dns_name_t *name,
 	}
 	rcu_read_unlock();
 
+	LIBDNS_DELEGDB_LOOKUP_DONE(delegdb, namebuf, result);
+
 	return result;
 }
 
@@ -465,6 +481,8 @@ delegdb_cleanup(dns_qp_t *qp, dns_delegdb_t *delegdb, size_t requested) {
 		return;
 	}
 
+	LIBDNS_DELEGDB_CLEANUP_START(delegdb, (int)requested);
+
 	while (reclaimed < requested) {
 		node = ISC_SIEVE_NEXT(delegdb->lru[isc_tid()], visited, link);
 
@@ -473,10 +491,19 @@ delegdb_cleanup(dns_qp_t *qp, dns_delegdb_t *delegdb, size_t requested) {
 		}
 		reclaimed += node->size;
 
+		if (LIBDNS_DELEGDB_EVICT_ENABLED()) {
+			char namebuf[DNS_NAME_FORMATSIZE];
+			dns_name_format(&node->zonecut, namebuf,
+					sizeof(namebuf));
+			LIBDNS_DELEGDB_EVICT(delegdb, node, namebuf);
+		}
+
 		ISC_SIEVE_UNLINK(delegdb->lru[isc_tid()], node, link);
 		(void)dns_qp_deletename(qp, &node->zonecut,
 					DNS_DBNAMESPACE_NORMAL, NULL, NULL);
 	}
+
+	LIBDNS_DELEGDB_CLEANUP_DONE(delegdb, (int)reclaimed);
 }
 
 static size_t
@@ -543,6 +570,7 @@ dns_delegset_insert(dns_delegdb_t *delegdb, const dns_name_t *zonecut,
 	dns_qpread_t qpr = {};
 	isc_stdtime_t now = isc_stdtime_now();
 	dns_qpmulti_t *nodes = NULL;
+	char zonecutbuf[DNS_NAME_FORMATSIZE];
 
 	REQUIRE(VALID_DELEGDB(delegdb));
 	REQUIRE(DNS_NAME_VALID(zonecut));
@@ -555,11 +583,17 @@ dns_delegset_insert(dns_delegdb_t *delegdb, const dns_name_t *zonecut,
 	 */
 	REQUIRE(delegset->mctx == delegdb->mctx);
 
+	if (LIBDNS_DELEGDB_INSERT_START_ENABLED() ||
+	    LIBDNS_DELEGDB_INSERT_DONE_ENABLED())
+	{
+		dns_name_format(zonecut, zonecutbuf, sizeof(zonecutbuf));
+	}
+	LIBDNS_DELEGDB_INSERT_START(delegdb, zonecutbuf);
+
 	rcu_read_lock();
 	nodes = rcu_dereference(delegdb->nodes);
 	if (nodes == NULL) {
-		rcu_read_unlock();
-		return ISC_R_SHUTTINGDOWN;
+		CLEANUP(ISC_R_SHUTTINGDOWN);
 	}
 
 	/*
@@ -632,6 +666,8 @@ dns_delegset_insert(dns_delegdb_t *delegdb, const dns_name_t *zonecut,
 cleanup:
 	rcu_read_unlock();
 
+	LIBDNS_DELEGDB_INSERT_DONE(delegdb, zonecutbuf, result);
+
 	return result;
 }
 
@@ -923,6 +959,11 @@ dns_delegdb_delete(dns_delegdb_t *delegdb, const dns_name_t *name, bool tree) {
 	dns_qpmulti_t *nodes = NULL;
 	dns_qp_t *qp = NULL;
 	isc_result_t result = ISC_R_SHUTTINGDOWN;
+	char namebuf[DNS_NAME_FORMATSIZE];
+
+	if (LIBDNS_DELEGDB_DELETE_ENABLED()) {
+		dns_name_format(name, namebuf, sizeof(namebuf));
+	}
 
 	rcu_read_lock();
 	nodes = rcu_dereference(delegdb->nodes);
@@ -940,6 +981,8 @@ dns_delegdb_delete(dns_delegdb_t *delegdb, const dns_name_t *name, bool tree) {
 	}
 	rcu_read_unlock();
 
+	LIBDNS_DELEGDB_DELETE(delegdb, namebuf, (int)tree, result);
+
 	return result;
 }
 
@@ -949,6 +992,7 @@ delegdb_shutdown_async(void *arg) {
 
 	REQUIRE(isc_loop_get(isc_tid()) == isc_loop_main());
 	REQUIRE(delegdb != NULL && VALID_DELEGDB(delegdb));
+
 	if (isc_refcount_decrement(&delegdb->owners) == 1) {
 		dns_qpmulti_t *nodes = rcu_xchg_pointer(&delegdb->nodes, NULL);
 
@@ -961,6 +1005,7 @@ delegdb_shutdown_async(void *arg) {
 			};
 			call_rcu(&nrh->rcu_head, deleg_destroy_qpmulti);
 		}
+		LIBDNS_DELEGDB_SHUTDOWN(delegdb);
 	}
 }
 

lib/dns/meson.build

@@ -10,7 +10,7 @@
 # information regarding copyright ownership.
 
 probe_hdr = dtrace_header.process('probes-dns.d')
-probe_src = [probe_hdr, files('xfrin.c')]
+probe_src = [probe_hdr, files('deleg.c', 'xfrin.c')]
 
 # dns_inc += include_directories('include')
 dns_inc_p += include_directories('.')
@@ -90,7 +90,6 @@ dns_srcset.add(
         'compress.c',
         'db.c',
         'dbiterator.c',
-        'deleg.c',
         'diff.c',
         'dispatch.c',
         'dlz.c',

lib/dns/probes-dns.d

@@ -12,6 +12,17 @@
  */
 
 provider libdns {
+	probe delegdb_cleanup_done(void *, int);
+	probe delegdb_cleanup_start(void *, int);
+	probe delegdb_create(void *);
+	probe delegdb_delete(void *, char *, int, int);
+	probe delegdb_evict(void *, void *, char *);
+	probe delegdb_insert_done(void *, char *, int);
+	probe delegdb_insert_start(void *, char *);
+	probe delegdb_lookup_done(void *, char *, int);
+	probe delegdb_lookup_start(void *, char *);
+	probe delegdb_reuse(void *);
+	probe delegdb_shutdown(void *);
 	probe xfrin_axfr_finalize_begin(void *, char *);
 	probe xfrin_axfr_finalize_end(void *, char *, int);
 	probe xfrin_connected(void *, char *, int);

tests/dns/meson.build

@@ -62,7 +62,23 @@ endif
 master_data = []
 subdir('testdata/master')
 
+deleg_probe_stub = custom_target(
+    'deleg-test-probes-dns',
+    input: files('../../lib/dns/probes-dns.d'),
+    output: 'probes-dns.h',
+    command: [
+        files('../../util/dtrace.sh'),
+        '-h',
+        '-s', '@INPUT@',
+        '-o', '@OUTPUT@',
+    ],
+)
+
 foreach unit : dns_tests
+    extra_sources = []
+    if unit == 'deleg'
+        extra_sources += deleg_probe_stub
+    endif
     test_bin = executable(
         unit,
         files(f'@unit@_test.c'),
@@ -77,7 +93,7 @@ foreach unit : dns_tests
                 meson.project_source_root() / 'bin' / 'tests' / 'system' / 'geoip2' / 'data',
             ),
         ],
-        sources: default_sanitize_options,
+        sources: [default_sanitize_options, extra_sources],
         dependencies: [
             libisc_dep,
             libdns_dep,