start documenting usdt probes

Start documenting the USDT probes provided. While the names are mostly
self-explanatory, the arguments need clarification.

contrib/scripts/qp-usdt.stp

@@ -0,0 +1,58 @@
+/*
+ * Copyright (C) Internet Systems Consortium, Inc. ("ISC")
+ *
+ * SPDX-License-Identifier: MPL-2.0
+ *
+ * This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, you can obtain one at https://mozilla.org/MPL/2.0/.
+ *
+ * See the COPYRIGHT file distributed with this work for additional
+ * information regarding copyright ownership.
+ */
+
+/* Sample SystemTap script for tracing addrdataset DNS DB opertaion in qpcache */
+
+global qp_timer
+
+global addrdataset_normal
+global addrdataset_overmem
+
+probe
+process("libdns.so").mark("qpcache_addrdataset_start")
+{
+    qp_timer[$arg1, $arg2] = ktime_get_ns()
+}
+
+probe
+process("libdns.so").mark("qpcache_addrdataset_done")
+{
+    duration = ktime_get_ns() - qp_timer[$arg1, $arg2]
+    delete qp_timer[$arg1, $arg2]
+
+    if ($arg3 != 0) {
+        addrdataset_overmem[pid(), $arg1]  <<< duration
+    } else {
+        addrdataset_normal[pid(), $arg1]  <<< duration
+    }
+}
+
+probe
+timer.s(5),
+end
+{
+    foreach ([p, a] in addrdataset_normal) {
+        printf(">>>> [NORMAL] pid: %ld, qpcache: 0x%xl\n", p, a)
+        print(@hist_log(addrdataset_normal[p, a]))
+    }
+
+    foreach ([p, a] in addrdataset_overmem) {
+        printf(">>>> [OVERMEM] pid: %ld, qpcache: 0x%xl\n", p, a)
+        print(@hist_log(addrdataset_overmem[p, a]))
+    }
+
+    printf("====\n\n");
+
+    delete addrdataset_normal
+    delete addrdataset_overmem
+}

doc/dev/usdt.md

@@ -0,0 +1,341 @@
+<!--
+Copyright (C) Internet Systems Consortium, Inc. ("ISC")
+
+SPDX-License-Identifier: MPL-2.0
+
+This Source Code Form is subject to the terms of the Mozilla Public
+License, v. 2.0.  If a copy of the MPL was not distributed with this
+file, you can obtain one at https://mozilla.org/MPL/2.0/.
+
+See the COPYRIGHT file distributed with this work for additional
+information regarding copyright ownership.
+-->
+
+## Userland Static Defined Tracing
+
+The probes and parameters are not stable.
+In general, pointers should only be used to match `_start` and `_end` probes.
+
+### Contents
+
+1. [libdns](#libdns)
+    * [qp](#qp)
+    * [qpmulti](#qpmulti)
+    * [qpcache](#qpcache)
+    * [rbtdb](#rbtdb)
+    * [rbtdb-cache](#rbtdb-cache)
+
+### <a name="libdns"></a>libdns
+
+#### <a name="qp"></a>qp
+
+- `qp_compact_start`: Fires when compation starts. This only includes the compaction phase of `dns_qp_compact`, the recycling part is fired separately.
+    - `void *` qp-trie pointer
+    - `uint32_t` number of leaf nodes
+    - `uint32_t` number of used nodes
+    - `uint32_t` number of free nodes
+    - `uint32_t` number of free cells that cannot be recovered right now
+
+- `qp_compact_done`: Fires when compaction finishes. This only includes the compaction phase of `dns_qp_compact`, the recycling part is fired separately.
+    - `void *` qp-trie pointer
+    - `uint32_t` number of leaf nodes
+    - `uint32_t` number of used nodes
+    - `uint32_t` number of free nodes
+    - `uint32_t` number of free cells that cannot be recovered right now
+
+- `qp_deletekey_start`: Fires when a node deletion by name starts.
+    - `void *` qp-trie pointer
+    - `void *` key pointer
+
+- `qp_deletekey_done`: Fires when a node deletion by name finishes.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+    - `bool` true if a leaf node is deleted
+
+- `qp_deletename_start`: Fires when a node deletion by name starts.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+
+- `qp_deletename_done`: Fires when a node deletion by name finishes.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+    - `void *` key pointer of name
+
+- `qp_getkey_start`: Fires when a leaf node lookup by key starts.
+    - `void *` qp-trie pointer
+    - `void *` key pointer
+
+- `qp_getkey_done`: Fires when a leaf node lookup by key finishes.
+    - `void *` qp-trie pointer
+    - `void *` key pointer
+    - `bool` true if a leaf node is found
+
+- `qp_getname_start`: Fires when a leaf node lookup by name starts.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+
+- `qp_getname_done`: Fires when a leaf node lookup by name finishes.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+    - `void *` key pointer of name
+
+- `qp_insert_start`: Fires when a leaf node insertion starts.
+    - `void *` qp-trie pointer
+    - `void *` leaf pointer
+    - `uint32_t` leaf integer
+
+- `qp_insert_done`: Fires when a leaf node insertion finishes.
+    - `void *` qp-trie pointer
+    - `void *` leaf pointer
+    - `uint32_t` leaf integer
+
+- `qp_lookup_start`: Fires when a leaf lookup starts.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+    - `void *` optional iterator pointer
+    - `void *` optional chain pointer
+
+- `qp_lookup_done`: Fires when a leaf lookup finishes.
+    - `void *` qp-trie pointer
+    - `void *` name pointer
+    - `void *` optional iterator pointer
+    - `void *` optional chain pointer
+    - `bool` true if an leaf is matched
+    - `bool` true if it was a partial match
+
+- `qp_reclaim_chunks_start`: Fires when chunk reclamation finishes.
+    - `void *` qp-trie pointer
+
+- `qp_reclaim_chunks_done`: Fires when chunk reclamation finishes.
+    - `void *` qp-trie pointer
+    - `uint32_t` number of chunks reclaimed
+    - `uint32_t` number of leaf nodes
+    - `uint32_t` number of used nodes
+    - `uint32_t` number of free nodes
+    - `uint32_t` number of free cells that cannot be recovered right now
+
+- `qp_recycle_start`: Fires when node recycling starts.
+    - `void *` qp-trie pointer
+
+- `qp_recycle_done`: Fires when node recycling finishes.
+    - `void *` qp-trie pointer
+    - `uint32_t` number of nodes recycled
+    - `uint32_t` number of leaf nodes
+    - `uint32_t` number of used nodes
+    - `uint32_t` number of free nodes
+    - `uint32_t` number of free cells that cannot be recovered right now
+
+#### <a name="qpmulti"></a>qpmulti
+
+- `qpmulti_marksweep_start`: Fires when chunk cleanup starts.
+    - `void *` qpmulti pointer
+    - `void *` writer qp-trie pointer
+
+- `qpmulti_marksweep_done`: Fires when chunk cleanup is finished.
+    - `void *` qpmulti pointer
+    - `void *` writer qp-trie pointer
+    - `uint32_t` number of chunks freed
+    - `uint32_t` number of leaf nodes
+    - `uint32_t` number of used nodes
+    - `uint32_t` number of free nodes
+    - `uint32_t` number of free cells that cannot be recovered right now
+
+- `qpmulti_txn_query`: Fires when a lightweight read-only transaction starts.
+    - `void *` qpmulti pointer
+    - `void *` read-only qp-trie pointer
+
+- `qpmulti_txn_lockedread`: Fires when a mutex-taking read-only transaction starts.
+    - `void *` qpmulti pointer
+    - `void *` read-only qp-trie pointer
+
+- `qpmulti_txn_snapshot`: Fires when a heavyweight read-only transaction starts.
+    - `void *` qpmulti pointer
+    - `void *` snapshot qp-trie pointer
+
+- `qpmulti_txn_update`: Fires when a heavyweight write transaction starts.
+    - `void *` qpmulti pointer
+    - `void *` modifiable qp-trie pointer
+
+- `qpmulti_txn_write`: Fires when a lightweight write transaction starts.
+    - `void *` qpmulti pointer
+    - `void *` modifiable qp-trie pointer
+
+- `qpmulti_txn_commit_start`: Fires when a transaction commit starts.
+    - `void *` qpmulti pointer
+    - `void *` transacting qp-trie pointer
+
+- `qpmulti_txn_commit_done`: Fires when a transaction commit is finished.
+    - `void *` qpmulti pointer
+    - `void *` transacting qp-trie pointer
+
+- `qpmulti_txn_rollback_start`: Fires when a transaction rollback starts.
+    - `void *` qpmulti pointer
+    - `void *` transacting qp-trie pointer
+
+- `qpmulti_txn_rollback_done`: Fires when a transaction rollback is finished.
+    - `void *` qpmulti pointer
+    - `void *` transacting qp-trie pointer
+    - `uint32_t` number of reclaimed chunks
+
+#### <a name="qpcache"></a>qpcache
+
+- `qpcache_expire_ttl_start`: Fires when TTL based cleanup starts.
+    - `void *` database pointer
+    - `unsigned int` lock number
+    - `uint32_t` cleanup timestamp
+
+- `qpcache_expire_ttl_done`: Fires when TTL based cleanup is finished.
+    - `void *` database pointer
+    - `unsigned int` lock number
+    - `uint32_t` cleanup timestamp
+    - `size_t` number of purged entries
+
+- `qpcache_expire_lru_start`: Fires when LRU based cleanup starts.
+    - `void *` database pointer
+    - `unsigned int` lock number
+    - `size_t` purge target number
+
+- `qpcache_expire_lru_done`: Fires when LRU based cleanup is finished.
+    - `void *` database pointer
+    - `unsigned int` lock number
+    - `size_t` number of purged entries
+
+- `qpcache_overmem_start` Fires when overmem cleanup starts.
+    - `void *` database pointer
+
+- `qpcache_overmem_done` Fires when overmem cleanup is finished.
+    - `void *` database pointer
+    - `size_t` number of purged entries
+    - `size_t` number of passes done
+
+- `qpcache_addrdataset_start`: Fires when a `addrdataset` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` rdataset pointer
+
+- `qpcache_addrdataset_done`: Fires when a `addrdataset` DNS DB operation finishes.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` rdataset pointer
+    - `bool` true if the cache is overmem
+
+- `qpcache_deletedata_start`: Fires when a `deletedata` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer containing data to be deleted
+    - `void *` data pointer
+
+- `qpcache_deletedata_done`: Fires when a `deletedata` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer containing data to be deleted
+    - `void *` data pointer
+
+- `qpcache_deleterdataset_start`: Fires when a `deleterdataset` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` database version pointer
+    - `uint16_t` opaque rdataset type value to be deleted
+    - `uint16_t` opaque coverage value
+
+- `qpcache_deleterdataset_done`: Fires when a `deleterdataset` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` database version pointer
+    - `uint16_t` opaque rdataset type value to be deleted
+    - `uint16_t` opaque coverage value
+    - `int32_t` result value
+
+- `qpcache_expiredata_start`: Fires when a `expiredata` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` data pointer
+
+- `qpcache_expiredata_done`: Fires when a `expiredata` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` data pointer
+
+- `qpcache_find_start`: Fires a `find` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` name pointer
+    - `uint32_t` given current timestamp
+    - `unsigned int` options flag
+
+- `qpcache_find_done`: Fires a `find` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` name pointer
+    - `uint32_t` given current timestamp
+    - `unsigned int` options flag
+    - `int32_t` result value
+
+- `qpcache_locknode`: Fires when a `locknode` DNS DB operation is called.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `bool` true if the operation is a write lock
+
+- `qpcache_unlocknode`: Fires when a `unlocknode` DNS DB operation is called.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `bool` true if the operation is a write lock
+
+#### <a name="rbtdb"></a>rbtdb
+
+- `rbtdb_addrdataset_start`: Fires when a `addrdataset` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` rdataset
+
+- `rbtdb_addrdataset_done`: Fires when a `addrdataset` DNS DB operation finishes.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` rdataset pointer
+    - `bool` true if the cache is overmem
+
+- `rbtdb_deletedata_start`: Fires when a `deletedata` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer containing data to be deleted
+    - `void *` data pointer
+
+- `rbtdb_deletedata_done`: Fires when a `deletedata` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer containing data to be deleted
+    - `void *` data pointer
+
+- `rbtdb_deleterdataset_start`: Fires when a `deleterdataset` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` database version pointer
+    - `uint16_t` opaque rdataset type value to be deleted
+    - `uint16_t` opaque coverage value
+
+- `rbtdb_deleterdataset_done`: Fires when a `deleterdataset` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` database version pointer
+    - `uint16_t` opaque rdataset type value to be deleted
+    - `uint16_t` opaque coverage value
+    - `int32_t` result value
+
+#### <a name="rbtdb-cache"></a>rbtdb-cache
+
+- `rbtdb_cache_expiredata_start`: Fires when a `expiredata` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` data pointer
+
+- `rbtdb_cache_expiredata_done`: Fires when a `expiredata` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` node pointer
+    - `void *` data pointer
+
+- `rbtdb_cache_find_start`: Fires a `find` DNS DB operation starts.
+    - `void *` database pointer
+    - `void *` name pointer
+    - `uint32_t` given current timestamp
+    - `unsigned int` options flag
+
+- `rbtdb_cache_find_done`: Fires a `find` DNS DB operation is finished.
+    - `void *` database pointer
+    - `void *` name pointer
+    - `uint32_t` given current timestamp
+    - `unsigned int` options flag
+    - `int32_t` result value

lib/dns/Makefile.am

@@ -341,8 +341,19 @@ libdns_la_LIBADD += $(LMDB_LIBS)
 endif
 
 if !HAVE_SYSTEMTAP
-DTRACE_DEPS = libdns_la-xfrin.lo
-DTRACE_OBJS = .libs/libdns_la-xfrin.$(OBJEXT)
+DTRACE_DEPS =			\
+	libdns_la-xfrin.lo	\
+	libdns_la-qp.lo		\
+	libdns_la-qpcache.lo	\
+	libdns_la-rbtdb.lo	\
+	libdns_la-rbt-cachedb.lo
+
+DTRACE_OBJS =					\
+	.libs/libdns_la-xfrin.$(OBJEXT)		\
+	.libs/libdns_la-qp.$(OBJEXT)		\
+	.libs/libdns_la-qpcache.$(OBJEXT)	\
+	.libs/libdns_la-rbtdb.$(OBJEXT)		\
+	.libs/libdns_la-rbt-cachedb.$(OBJEXT)
 endif
 
 include $(top_srcdir)/Makefile.dtrace

lib/dns/probes.d

@@ -12,6 +12,74 @@
  */
 
 provider libdns {
+	probe qp_compact_done(void *, uint32_t, uint32_t, uint32_t, uint32_t);
+	probe qp_compact_start(void *, uint32_t, uint32_t, uint32_t, uint32_t);
+	probe qp_deletekey_done(void *, void *, bool);
+	probe qp_deletekey_start(void *, void *);
+	probe qp_deletename_done(void *, void *, void *);
+	probe qp_deletename_start(void *, void *);
+	probe qp_getkey_done(void *, void *, bool);
+	probe qp_getkey_start(void *, void *);
+	probe qp_getname_done(void *, void *, void *);
+	probe qp_getname_start(void *, void *);
+	probe qp_insert_done(void *, void *, uint32_t);
+	probe qp_insert_start(void *, void *, uint32_t);
+	probe qp_lookup_done(void *, void *, void *, void *, bool, bool);
+	probe qp_lookup_start(void *, void *, void *, void *);
+	probe qp_reclaim_chunks_done(void *, uint32_t, uint32_t, uint32_t, uint32_t, uint32_t);
+	probe qp_reclaim_chunks_start(void *);
+	probe qp_recycle_done(void *, uint32_t, uint32_t, uint32_t, uint32_t, uint32_t);
+	probe qp_recycle_start(void *);
+
+	probe qpmulti_marksweep_done(void *, void *, uint32_t, uint32_t, uint32_t, uint32_t, uint32_t);
+	probe qpmulti_marksweep_start(void *, void *);
+
+	probe qpmulti_txn_lockedread(void *, void *);
+	probe qpmulti_txn_query(void *, void *);
+	probe qpmulti_txn_snapshot(void *, void *);
+	probe qpmulti_txn_update(void *, void *);
+	probe qpmulti_txn_write(void *, void *);
+	probe qpmulti_txn_commit_done(void *, void *);
+	probe qpmulti_txn_commit_start(void *, void *);
+	probe qpmulti_txn_rollback_done(void *, void *, uint32_t);
+	probe qpmulti_txn_rollback_start(void *, void *);
+
+	probe qpcache_expire_ttl_start(void *, unsigned int locknum, uint32_t);
+	probe qpcache_expire_ttl_done(void *, unsigned int locknum, uint32_t, size_t expired);
+	probe qpcache_expire_lru_start(void *, unsigned int locknum, size_t purgesize);
+	probe qpcache_expire_lru_done(void *, unsigned int locknum, size_t purged);
+	probe qpcache_overmem_done(void *, size_t purged, size_t passes);
+	probe qpcache_overmem_start(void *);
+
+	/* dns_db interface */
+	probe qpcache_addrdataset_done(void *, void *, void *, int32_t, bool);
+	probe qpcache_addrdataset_start(void *, void *, void *);
+	probe qpcache_deletedata_done(void *, void *, void *);
+	probe qpcache_deletedata_start(void *, void *, void *);
+	probe qpcache_deleterdataset_done(void *, void *, void *, uint16_t, uint16_t, int32_t);
+	probe qpcache_deleterdataset_start(void *, void *, void *, uint16_t, uint16_t);
+	probe qpcache_expiredata_done(void *, void *, void *);
+	probe qpcache_expiredata_start(void *, void *, void *);
+	probe qpcache_find_done(void *, void *, uint32_t, unsigned int, int32_t);
+	probe qpcache_find_start(void *, void *, uint32_t, unsigned int);
+	probe qpcache_locknode(void *, void *, bool);
+	probe qpcache_unlocknode(void *, void *, bool);
+
+	/* dns_db interface */
+	probe rbtdb_addrdataset_done(void *, void *, void *, bool);
+	probe rbtdb_addrdataset_start(void *, void *, void *);
+	probe rbtdb_deletedata_done(void *, void *, void *);
+	probe rbtdb_deletedata_start(void *, void *, void *);
+	probe rbtdb_deleterdataset_done(void *, void *, void *, uint16_t, uint16_t, int32_t);
+	probe rbtdb_deleterdataset_start(void *, void *, void *, uint16_t, uint16_t);
+	probe rbtdb_locknode(void *, void *, bool);
+	probe rbtdb_unlocknode(void *, void *, bool);
+
+	probe rbtdb_cache_expiredata_done(void *, void *, void *);
+	probe rbtdb_cache_expiredata_start(void *, void *, void *);
+	probe rbtdb_cache_find_done(void *, void *, uint32_t, unsigned int, int);
+	probe rbtdb_cache_find_start(void *, void *, uint32_t, unsigned int);
+
 	probe xfrin_axfr_finalize_begin(void *, char *);
 	probe xfrin_axfr_finalize_end(void *, char *, int);
 	probe xfrin_connected(void *, char *, int);

lib/dns/qp.c

@@ -46,36 +46,13 @@
 #include <dns/qp.h>
 #include <dns/types.h>
 
+#include "probes.h"
 #include "qp_p.h"
 
-#ifndef DNS_QP_LOG_STATS
-#define DNS_QP_LOG_STATS 1
-#endif
 #ifndef DNS_QP_TRACE
 #define DNS_QP_TRACE 0
 #endif
 
-/*
- * very basic garbage collector statistics
- *
- * XXXFANF for now we're logging GC times, but ideally we should
- * accumulate stats more quietly and report via the statschannel
- */
-static atomic_uint_fast64_t compact_time;
-static atomic_uint_fast64_t recycle_time;
-static atomic_uint_fast64_t rollback_time;
-
-/* for LOG_STATS() format strings */
-#define PRItime " %" PRIu64 " ns "
-
-#if DNS_QP_LOG_STATS
-#define LOG_STATS(...)                                            \
-	isc_log_write(DNS_LOGCATEGORY_DATABASE, DNS_LOGMODULE_QP, \
-		      ISC_LOG_DEBUG(1), __VA_ARGS__)
-#else
-#define LOG_STATS(...)
-#endif
-
 #if DNS_QP_TRACE
 /*
  * TRACE is generally used in allocation-related functions so it doesn't
@@ -664,28 +641,23 @@ chunk_free(dns_qp_t *qp, dns_qpchunk_t chunk) {
  */
 static void
 recycle(dns_qp_t *qp) {
-	unsigned int free = 0;
+	ISC_ATTR_UNUSED uint32_t recycled = 0;
 
-	isc_nanosecs_t start = isc_time_monotonic();
+	LIBDNS_QP_RECYCLE_START(qp);
 
 	for (dns_qpchunk_t chunk = 0; chunk < qp->chunk_max; chunk++) {
 		if (chunk != qp->bump && chunk_usage(qp, chunk) == 0 &&
 		    qp->usage[chunk].exists && !qp->usage[chunk].immutable)
 		{
 			chunk_free(qp, chunk);
-			free++;
+			if (LIBDNS_QP_RECYCLE_DONE_ENABLED()) {
+				recycled++;
+			}
 		}
 	}
 
-	isc_nanosecs_t time = isc_time_monotonic() - start;
-	atomic_fetch_add_relaxed(&recycle_time, time);
-
-	if (free > 0) {
-		LOG_STATS("qp recycle" PRItime "free %u chunks", time, free);
-		LOG_STATS("qp recycle leaf %u live %u used %u free %u hold %u",
-			  qp->leaf_count, qp->used_count - qp->free_count,
-			  qp->used_count, qp->free_count, qp->hold_count);
-	}
+	LIBDNS_QP_RECYCLE_DONE(qp, recycled, qp->leaf_count, qp->used_count,
+			       qp->free_count, qp->hold_count);
 }
 
 /*
@@ -703,8 +675,9 @@ reclaim_chunks_cb(struct rcu_head *arg) {
 	dns_qp_t *qp = &multi->writer;
 	REQUIRE(QP_VALID(qp));
 
-	unsigned int free = 0;
-	isc_nanosecs_t start = isc_time_monotonic();
+	LIBDNS_QP_RECLAIM_CHUNKS_START(qp);
+
+	ISC_ATTR_UNUSED uint32_t reclaimed = 0;
 
 	for (unsigned int i = 0; i < rcuctx->count; i++) {
 		dns_qpchunk_t chunk = rcuctx->chunk[i];
@@ -713,22 +686,18 @@ reclaim_chunks_cb(struct rcu_head *arg) {
 			qp->usage[chunk].snapfree = true;
 		} else {
 			chunk_free(qp, chunk);
-			free++;
+			if (LIBDNS_QP_RECLAIM_CHUNKS_DONE_ENABLED()) {
+				reclaimed++;
+			}
 		}
 	}
 
 	isc_mem_putanddetach(&rcuctx->mctx, rcuctx,
 			     STRUCT_FLEX_SIZE(rcuctx, chunk, rcuctx->count));
 
-	isc_nanosecs_t time = isc_time_monotonic() - start;
-	recycle_time += time;
-
-	if (free > 0) {
-		LOG_STATS("qp reclaim" PRItime "free %u chunks", time, free);
-		LOG_STATS("qp reclaim leaf %u live %u used %u free %u hold %u",
-			  qp->leaf_count, qp->used_count - qp->free_count,
-			  qp->used_count, qp->free_count, qp->hold_count);
-	}
+	LIBDNS_QP_RECLAIM_CHUNKS_DONE(qp, reclaimed, qp->leaf_count,
+				      qp->used_count, qp->free_count,
+				      qp->hold_count);
 
 	UNLOCK(&multi->mutex);
 }
@@ -776,8 +745,6 @@ reclaim_chunks(dns_qpmulti_t *multi) {
 	}
 
 	call_rcu(&rcuctx->rcu_head, reclaim_chunks_cb);
-
-	LOG_STATS("qp will reclaim %u chunks", count);
 }
 
 /*
@@ -786,12 +753,12 @@ reclaim_chunks(dns_qpmulti_t *multi) {
  */
 static void
 marksweep_chunks(dns_qpmulti_t *multi) {
-	unsigned int free = 0;
-
-	isc_nanosecs_t start = isc_time_monotonic();
+	ISC_ATTR_UNUSED uint32_t sweeped = 0;
 
 	dns_qp_t *qpw = &multi->writer;
 
+	LIBDNS_QPMULTI_MARKSWEEP_START(multi, qpw);
+
 	for (dns_qpsnap_t *qps = ISC_LIST_HEAD(multi->snapshots); qps != NULL;
 	     qps = ISC_LIST_NEXT(qps, link))
 	{
@@ -809,20 +776,15 @@ marksweep_chunks(dns_qpmulti_t *multi) {
 		qpw->usage[chunk].snapmark = false;
 		if (qpw->usage[chunk].snapfree && !qpw->usage[chunk].snapshot) {
 			chunk_free(qpw, chunk);
-			free++;
+			if (LIBDNS_QPMULTI_MARKSWEEP_DONE_ENABLED()) {
+				sweeped++;
+			}
 		}
 	}
 
-	isc_nanosecs_t time = isc_time_monotonic() - start;
-	recycle_time += time;
-
-	if (free > 0) {
-		LOG_STATS("qp marksweep" PRItime "free %u chunks", time, free);
-		LOG_STATS(
-			"qp marksweep leaf %u live %u used %u free %u hold %u",
-			qpw->leaf_count, qpw->used_count - qpw->free_count,
-			qpw->used_count, qpw->free_count, qpw->hold_count);
-	}
+	LIBDNS_QPMULTI_MARKSWEEP_DONE(multi, qpw, sweeped, qpw->leaf_count,
+				      qpw->used_count, qpw->free_count,
+				      qpw->hold_count);
 }
 
 /***********************************************************************
@@ -927,11 +889,8 @@ compact_recursive(dns_qp_t *qp, dns_qpnode_t *parent) {
 
 static void
 compact(dns_qp_t *qp) {
-	LOG_STATS("qp compact before leaf %u live %u used %u free %u hold %u",
-		  qp->leaf_count, qp->used_count - qp->free_count,
-		  qp->used_count, qp->free_count, qp->hold_count);
-
-	isc_nanosecs_t start = isc_time_monotonic();
+	LIBDNS_QP_COMPACT_START(qp, qp->leaf_count, qp->used_count,
+				qp->free_count, qp->hold_count);
 
 	if (qp->usage[qp->bump].free > QP_MAX_FREE) {
 		alloc_reset(qp);
@@ -942,13 +901,8 @@ compact(dns_qp_t *qp) {
 	}
 	qp->compact_all = false;
 
-	isc_nanosecs_t time = isc_time_monotonic() - start;
-	atomic_fetch_add_relaxed(&compact_time, time);
-
-	LOG_STATS("qp compact" PRItime
-		  "leaf %u live %u used %u free %u hold %u",
-		  time, qp->leaf_count, qp->used_count - qp->free_count,
-		  qp->used_count, qp->free_count, qp->hold_count);
+	LIBDNS_QP_COMPACT_DONE(qp, qp->leaf_count, qp->used_count,
+			       qp->free_count, qp->hold_count);
 }
 
 void
@@ -961,6 +915,7 @@ dns_qp_compact(dns_qp_t *qp, dns_qpgc_t mode) {
 		alloc_reset(qp);
 		qp->compact_all = true;
 	}
+
 	compact(qp);
 	recycle(qp);
 }
@@ -1068,14 +1023,6 @@ dns_qpmulti_memusage(dns_qpmulti_t *multi) {
 	return (memusage);
 }
 
-void
-dns_qp_gctime(isc_nanosecs_t *compact_p, isc_nanosecs_t *recycle_p,
-	      isc_nanosecs_t *rollback_p) {
-	*compact_p = atomic_load_relaxed(&compact_time);
-	*recycle_p = atomic_load_relaxed(&recycle_time);
-	*rollback_p = atomic_load_relaxed(&rollback_time);
-}
-
 /***********************************************************************
  *
  *  read-write transactions
@@ -1140,6 +1087,8 @@ dns_qpmulti_write(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 		alloc_reset(qp);
 	}
 	qp->transaction_mode = QP_WRITE;
+
+	LIBDNS_QPMULTI_TXN_WRITE(multi, qp);
 }
 
 /*
@@ -1187,6 +1136,8 @@ dns_qpmulti_update(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 	multi->rollback = rollback;
 
 	alloc_reset(qp);
+
+	LIBDNS_QPMULTI_TXN_UPDATE(multi, qp);
 }
 
 void
@@ -1199,6 +1150,8 @@ dns_qpmulti_commit(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 	dns_qp_t *qp = *qptp;
 	TRACE("");
 
+	LIBDNS_QPMULTI_TXN_COMMIT_START(multi, qp);
+
 	if (qp->transaction_mode == QP_UPDATE) {
 		INSIST(multi->rollback != NULL);
 		/* paired with dns_qpmulti_update() */
@@ -1245,6 +1198,8 @@ dns_qpmulti_commit(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 	/* schedule the rest for later */
 	reclaim_chunks(multi);
 
+	LIBDNS_QPMULTI_TXN_COMMIT_DONE(multi, qp);
+
 	*qptp = NULL;
 	UNLOCK(&multi->mutex);
 }
@@ -1254,7 +1209,7 @@ dns_qpmulti_commit(dns_qpmulti_t *multi, dns_qp_t **qptp) {
  */
 void
 dns_qpmulti_rollback(dns_qpmulti_t *multi, dns_qp_t **qptp) {
-	unsigned int free = 0;
+	ISC_ATTR_UNUSED uint32_t reclaimed = 0;
 
 	REQUIRE(QPMULTI_VALID(multi));
 	REQUIRE(multi->writer.transaction_mode == QP_UPDATE);
@@ -1263,12 +1218,15 @@ dns_qpmulti_rollback(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 	dns_qp_t *qp = *qptp;
 	TRACE("");
 
-	isc_nanosecs_t start = isc_time_monotonic();
+	LIBDNS_QPMULTI_TXN_ROLLBACK_START(multi, qptp);
 
 	for (dns_qpchunk_t chunk = 0; chunk < qp->chunk_max; chunk++) {
 		if (qp->base->ptr[chunk] != NULL && !qp->usage[chunk].immutable)
 		{
 			chunk_free(qp, chunk);
+			if (LIBDNS_QPMULTI_TXN_ROLLBACK_DONE_ENABLED()) {
+				reclaimed++;
+			}
 			/*
 			 * we need to clear its base pointer in the rollback
 			 * trie, in case the arrays were resized
@@ -1277,7 +1235,6 @@ dns_qpmulti_rollback(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 				INSIST(!multi->rollback->usage[chunk].exists);
 				multi->rollback->base->ptr[chunk] = NULL;
 			}
-			free++;
 		}
 	}
 
@@ -1297,10 +1254,7 @@ dns_qpmulti_rollback(dns_qpmulti_t *multi, dns_qp_t **qptp) {
 	isc_mem_free(qp->mctx, multi->rollback);
 	INSIST(multi->rollback == NULL);
 
-	isc_nanosecs_t time = isc_time_monotonic() - start;
-	atomic_fetch_add_relaxed(&rollback_time, time);
-
-	LOG_STATS("qp rollback" PRItime "free %u chunks", time, free);
+	LIBDNS_QPMULTI_TXN_ROLLBACK_DONE(multi, qptp, reclaimed);
 
 	*qptp = NULL;
 	UNLOCK(&multi->mutex);
@@ -1337,6 +1291,8 @@ dns_qpmulti_query(dns_qpmulti_t *multi, dns_qpread_t *qp) {
 
 	dns_qpmulti_t *whence = reader_open(multi, qp);
 	INSIST(whence == multi);
+
+	LIBDNS_QPMULTI_TXN_QUERY(multi, qp);
 }
 
 void
@@ -1392,6 +1348,8 @@ dns_qpmulti_snapshot(dns_qpmulti_t *multi, dns_qpsnap_t **qpsp) {
 	UNLOCK(&multi->mutex);
 
 	rcu_read_unlock();
+
+	LIBDNS_QPMULTI_TXN_SNAPSHOT(multi, qpsp);
 }
 
 void
@@ -1572,6 +1530,8 @@ dns_qp_insert(dns_qp_t *qp, void *pval, uint32_t ival) {
 
 	REQUIRE(QP_VALID(qp));
 
+	LIBDNS_QP_INSERT_START(qp, pval, ival);
+
 	new_leaf = make_leaf(pval, ival);
 	new_keylen = leaf_qpkey(qp, &new_leaf, new_key);
 
@@ -1583,6 +1543,7 @@ dns_qp_insert(dns_qp_t *qp, void *pval, uint32_t ival) {
 		attach_leaf(qp, new_twigs);
 		qp->leaf_count++;
 		qp->root_ref = new_ref;
+		LIBDNS_QP_INSERT_DONE(qp, pval, ival);
 		return (ISC_R_SUCCESS);
 	}
 
@@ -1607,6 +1568,7 @@ dns_qp_insert(dns_qp_t *qp, void *pval, uint32_t ival) {
 	old_keylen = leaf_qpkey(qp, n, old_key);
 	offset = qpkey_compare(new_key, new_keylen, old_key, old_keylen);
 	if (offset == QPKEY_EQUAL) {
+		LIBDNS_QP_INSERT_DONE(qp, pval, ival);
 		return (ISC_R_EXISTS);
 	}
 	new_bit = qpkey_bit(new_key, new_keylen, offset);
@@ -1648,6 +1610,7 @@ newbranch:
 	attach_leaf(qp, &new_leaf);
 	qp->leaf_count++;
 
+	LIBDNS_QP_INSERT_DONE(qp, pval, ival);
 	return (ISC_R_SUCCESS);
 
 growbranch:
@@ -1680,6 +1643,7 @@ growbranch:
 	}
 	qp->leaf_count++;
 
+	LIBDNS_QP_INSERT_DONE(qp, pval, ival);
 	return (ISC_R_SUCCESS);
 }
 
@@ -1689,8 +1653,10 @@ dns_qp_deletekey(dns_qp_t *qp, const dns_qpkey_t search_key,
 	REQUIRE(QP_VALID(qp));
 	REQUIRE(search_keylen < sizeof(dns_qpkey_t));
 
+	LIBDNS_QP_DELETEKEY_START(qp, (void *)search_key);
+
 	if (get_root(qp) == NULL) {
-		return (ISC_R_NOTFOUND);
+		goto notfound;
 	}
 
 	dns_qpshift_t bit = 0; /* suppress warning */
@@ -1700,7 +1666,7 @@ dns_qp_deletekey(dns_qp_t *qp, const dns_qpkey_t search_key,
 		prefetch_twigs(qp, n);
 		bit = branch_keybit(n, search_key, search_keylen);
 		if (!branch_has_twig(n, bit)) {
-			return (ISC_R_NOTFOUND);
+			goto notfound;
 		}
 		make_twigs_mutable(qp, n);
 		parent = n;
@@ -1712,7 +1678,7 @@ dns_qp_deletekey(dns_qp_t *qp, const dns_qpkey_t search_key,
 	if (qpkey_compare(search_key, search_keylen, found_key, found_keylen) !=
 	    QPKEY_EQUAL)
 	{
-		return (ISC_R_NOTFOUND);
+		goto notfound;
 	}
 
 	SET_IF_NOT_NULL(pval_r, leaf_pval(n));
@@ -1726,7 +1692,7 @@ dns_qp_deletekey(dns_qp_t *qp, const dns_qpkey_t search_key,
 		INSIST(n == get_root(qp));
 		free_twigs(qp, qp->root_ref, 1);
 		qp->root_ref = INVALID_REF;
-		return (ISC_R_SUCCESS);
+		goto found;
 	}
 
 	/* step back to parent node */
@@ -1755,15 +1721,28 @@ dns_qp_deletekey(dns_qp_t *qp, const dns_qpkey_t search_key,
 		squash_twigs(qp, ref + size - 1, 1);
 	}
 
+found:
+	LIBDNS_QP_DELETEKEY_DONE(qp, (void *)search_key, true);
 	return (ISC_R_SUCCESS);
+
+notfound:
+	LIBDNS_QP_DELETEKEY_DONE(qp, (void *)search_key, false);
+	return (ISC_R_NOTFOUND);
 }
 
 isc_result_t
 dns_qp_deletename(dns_qp_t *qp, const dns_name_t *name, void **pval_r,
 		  uint32_t *ival_r) {
+	isc_result_t result;
 	dns_qpkey_t key;
-	size_t keylen = dns_qpkey_fromname(key, name);
-	return (dns_qp_deletekey(qp, key, keylen, pval_r, ival_r));
+	size_t keylen;
+
+	LIBDNS_QP_DELETENAME_START(qp, (void *)name);
+	keylen = dns_qpkey_fromname(key, name);
+	result = dns_qp_deletekey(qp, key, keylen, pval_r, ival_r);
+	LIBDNS_QP_DELETENAME_DONE(qp, (void *)name, key);
+
+	return (result);
 }
 
 /***********************************************************************
@@ -1982,8 +1961,11 @@ dns_qp_getkey(dns_qpreadable_t qpr, const dns_qpkey_t search_key,
 	REQUIRE(QP_VALID(qp));
 	REQUIRE(search_keylen < sizeof(dns_qpkey_t));
 
+	LIBDNS_QP_GETKEY_START(qp, (void *)search_key);
+
 	n = get_root(qp);
 	if (n == NULL) {
+		LIBDNS_QP_GETKEY_DONE(qp, (void *)search_key, false);
 		return (ISC_R_NOTFOUND);
 	}
 
@@ -1991,6 +1973,7 @@ dns_qp_getkey(dns_qpreadable_t qpr, const dns_qpkey_t search_key,
 		prefetch_twigs(qp, n);
 		bit = branch_keybit(n, search_key, search_keylen);
 		if (!branch_has_twig(n, bit)) {
+			LIBDNS_QP_GETKEY_DONE(qp, (void *)search_key, false);
 			return (ISC_R_NOTFOUND);
 		}
 		n = branch_twig_ptr(qp, n, bit);
@@ -2000,20 +1983,31 @@ dns_qp_getkey(dns_qpreadable_t qpr, const dns_qpkey_t search_key,
 	if (qpkey_compare(search_key, search_keylen, found_key, found_keylen) !=
 	    QPKEY_EQUAL)
 	{
+		LIBDNS_QP_GETKEY_DONE(qp, (void *)search_key, false);
 		return (ISC_R_NOTFOUND);
 	}
 
 	SET_IF_NOT_NULL(pval_r, leaf_pval(n));
 	SET_IF_NOT_NULL(ival_r, leaf_ival(n));
+
+	LIBDNS_QP_GETKEY_DONE(qp, (void *)search_key, true);
+
 	return (ISC_R_SUCCESS);
 }
 
 isc_result_t
 dns_qp_getname(dns_qpreadable_t qpr, const dns_name_t *name, void **pval_r,
 	       uint32_t *ival_r) {
+	isc_result_t result;
 	dns_qpkey_t key;
-	size_t keylen = dns_qpkey_fromname(key, name);
-	return (dns_qp_getkey(qpr, key, keylen, pval_r, ival_r));
+	size_t keylen;
+
+	LIBDNS_QP_GETNAME_START(qpr.qp, (void *)name);
+	keylen = dns_qpkey_fromname(key, name);
+	result = dns_qp_getkey(qpr, key, keylen, pval_r, ival_r);
+	LIBDNS_QP_GETNAME_DONE(qpr.qp, (void *)name, key);
+
+	return (result);
 }
 
 static inline void
@@ -2204,6 +2198,8 @@ dns_qp_lookup(dns_qpreadable_t qpr, const dns_name_t *name,
 	REQUIRE(QP_VALID(qp));
 	REQUIRE(foundname == NULL || ISC_MAGIC_VALID(name, DNS_NAME_MAGIC));
 
+	LIBDNS_QP_LOOKUP_START(qp, (void *)name, iter, chain);
+
 	searchlen = dns_qpkey_fromname(search, name);
 
 	if (chain == NULL) {
@@ -2218,6 +2214,8 @@ dns_qp_lookup(dns_qpreadable_t qpr, const dns_name_t *name,
 
 	n = get_root(qp);
 	if (n == NULL) {
+		LIBDNS_QP_LOOKUP_DONE(qpr.qp, (void *)name, iter, chain, false,
+				      false);
 		return (ISC_R_NOTFOUND);
 	}
 	iter->stack[0] = n;
@@ -2306,6 +2304,8 @@ dns_qp_lookup(dns_qpreadable_t qpr, const dns_name_t *name,
 		SET_IF_NOT_NULL(pval_r, leaf_pval(n));
 		SET_IF_NOT_NULL(ival_r, leaf_ival(n));
 		maybe_set_name(qp, n, foundname);
+		LIBDNS_QP_LOOKUP_DONE(qp, (void *)name, iter, chain, true,
+				      result == DNS_R_PARTIALMATCH);
 		return (result);
 	}
 
@@ -2320,6 +2320,8 @@ dns_qp_lookup(dns_qpreadable_t qpr, const dns_name_t *name,
 			SET_IF_NOT_NULL(pval_r, leaf_pval(n));
 			SET_IF_NOT_NULL(ival_r, leaf_ival(n));
 			maybe_set_name(qp, n, foundname);
+			LIBDNS_QP_LOOKUP_DONE(qp, (void *)name, iter, chain,
+					      true, true);
 			return (DNS_R_PARTIALMATCH);
 		} else {
 			/*
@@ -2332,6 +2334,7 @@ dns_qp_lookup(dns_qpreadable_t qpr, const dns_name_t *name,
 	}
 
 	/* nothing was found at all */
+	LIBDNS_QP_LOOKUP_DONE(qp, (void *)name, iter, chain, false, false);
 	return (ISC_R_NOTFOUND);
 }
 

lib/dns/qpcache.c

@@ -60,6 +60,7 @@
 #include <dns/zonekey.h>
 
 #include "db_p.h"
+#include "probes.h"
 #include "qpcache_p.h"
 
 #define CHECK(op)                            \
@@ -1559,6 +1560,8 @@ find(dns_db_t *db, const dns_name_t *name, dns_dbversion_t *version,
 	REQUIRE(VALID_QPDB((qpcache_t *)db));
 	REQUIRE(version == NULL);
 
+	LIBDNS_QPCACHE_FIND_START(db, (void *)name, now, options);
+
 	if (now == 0) {
 		now = isc_stdtime_now();
 	}
@@ -1973,6 +1976,9 @@ tree_exit:
 	}
 
 	update_cachestats(search.qpdb, result);
+
+	LIBDNS_QPCACHE_FIND_DONE(db, (void *)name, now, options, result);
+
 	return (result);
 }
 
@@ -2323,11 +2329,15 @@ expiredata(dns_db_t *db, dns_dbnode_t *node, void *data) {
 	isc_rwlocktype_t nlocktype = isc_rwlocktype_none;
 	isc_rwlocktype_t tlocktype = isc_rwlocktype_none;
 
+	LIBDNS_QPCACHE_EXPIREDATA_START(db, node, data);
+
 	NODE_WRLOCK(&qpdb->node_locks[qpnode->locknum].lock, &nlocktype);
 	expireheader(header, &nlocktype, &tlocktype,
 		     dns_expire_flush DNS__DB_FILELINE);
 	NODE_UNLOCK(&qpdb->node_locks[qpnode->locknum].lock, &nlocktype);
 	INSIST(tlocktype == isc_rwlocktype_none);
+
+	LIBDNS_QPCACHE_EXPIREDATA_DONE(db, node, data);
 }
 
 static size_t
@@ -2347,6 +2357,8 @@ expire_lru_headers(qpcache_t *qpdb, unsigned int locknum,
 	dns_slabheader_t *header = NULL;
 	size_t purged = 0;
 
+	LIBDNS_QPCACHE_EXPIRE_LRU_START(qpdb, locknum, purgesize);
+
 	for (header = ISC_LIST_TAIL(qpdb->lru[locknum]);
 	     header != NULL && header->last_used <= qpdb->last_used &&
 	     purged <= purgesize;
@@ -2367,6 +2379,8 @@ expire_lru_headers(qpcache_t *qpdb, unsigned int locknum,
 		purged += header_size;
 	}
 
+	LIBDNS_QPCACHE_EXPIRE_LRU_DONE(qpdb, locknum, purgesize);
+
 	return (purged);
 }
 
@@ -2389,6 +2403,8 @@ overmem(qpcache_t *qpdb, dns_slabheader_t *newheader,
 	isc_stdtime_t min_last_used = 0;
 	size_t max_passes = 8;
 
+	LIBDNS_QPCACHE_OVERMEM_START(qpdb);
+
 	/*
 	 * Maximum estimated size of the data being added: The size
 	 * of the rdataset, plus a new QP database node and nodename,
@@ -2435,6 +2451,8 @@ again:
 			}
 		}
 	}
+
+	LIBDNS_QPCACHE_OVERMEM_DONE(qpdb, purged, 8 - max_passes);
 }
 
 /*%
@@ -3407,6 +3425,8 @@ addrdataset(dns_db_t *db, dns_dbnode_t *node, dns_dbversion_t *version,
 	REQUIRE(VALID_QPDB(qpdb));
 	REQUIRE(version == NULL);
 
+	LIBDNS_QPCACHE_ADDRDATASET_START(db, node, rdataset);
+
 	if (now == 0) {
 		now = isc_stdtime_now();
 	}
@@ -3562,6 +3582,9 @@ addrdataset(dns_db_t *db, dns_dbnode_t *node, dns_dbversion_t *version,
 	}
 	INSIST(tlocktype == isc_rwlocktype_none);
 
+	LIBDNS_QPCACHE_ADDRDATASET_DONE(db, node, rdataset, result,
+					cache_is_overmem);
+
 	return (result);
 }
 
@@ -3577,10 +3600,18 @@ deleterdataset(dns_db_t *db, dns_dbnode_t *node, dns_dbversion_t *version,
 	REQUIRE(VALID_QPDB(qpdb));
 	REQUIRE(version == NULL);
 
+	LIBDNS_QPCACHE_DELETERDATASET_START(qpdb, node, version, type, covers);
+
 	if (type == dns_rdatatype_any) {
+		LIBDNS_QPCACHE_DELETERDATASET_DONE(qpdb, node, version, type,
+						   covers,
+						   ISC_R_NOTIMPLEMENTED);
 		return (ISC_R_NOTIMPLEMENTED);
 	}
 	if (type == dns_rdatatype_rrsig && covers == 0) {
+		LIBDNS_QPCACHE_DELETERDATASET_DONE(qpdb, node, version, type,
+						   covers,
+						   ISC_R_NOTIMPLEMENTED);
 		return (ISC_R_NOTIMPLEMENTED);
 	}
 
@@ -3595,6 +3626,9 @@ deleterdataset(dns_db_t *db, dns_dbnode_t *node, dns_dbversion_t *version,
 		     isc_rwlocktype_none DNS__DB_FLARG_PASS);
 	NODE_UNLOCK(&qpdb->node_locks[qpnode->locknum].lock, &nlocktype);
 
+	LIBDNS_QPCACHE_DELETERDATASET_DONE(qpdb, node, version, type, covers,
+					   result);
+
 	return (result);
 }
 
@@ -3649,6 +3683,8 @@ locknode(dns_db_t *db, dns_dbnode_t *node, isc_rwlocktype_t type) {
 	qpcache_t *qpdb = (qpcache_t *)db;
 	qpcnode_t *qpnode = (qpcnode_t *)node;
 
+	LIBDNS_QPCACHE_LOCKNODE(db, node, type == isc_rwlocktype_write);
+
 	RWLOCK(&qpdb->node_locks[qpnode->locknum].lock, type);
 }
 
@@ -3658,6 +3694,8 @@ unlocknode(dns_db_t *db, dns_dbnode_t *node, isc_rwlocktype_t type) {
 	qpcnode_t *qpnode = (qpcnode_t *)node;
 
 	RWUNLOCK(&qpdb->node_locks[qpnode->locknum].lock, type);
+
+	LIBDNS_QPCACHE_UNLOCKNODE(db, node, type == isc_rwlocktype_write);
 }
 
 isc_result_t
@@ -4300,6 +4338,8 @@ deletedata(dns_db_t *db ISC_ATTR_UNUSED, dns_dbnode_t *node ISC_ATTR_UNUSED,
 	dns_slabheader_t *header = data;
 	qpcache_t *qpdb = (qpcache_t *)header->db;
 
+	LIBDNS_QPCACHE_DELETEDATA_START(qpdb, node, data);
+
 	if (header->heap != NULL && header->heap_index != 0) {
 		isc_heap_delete(header->heap, header->heap_index);
 	}
@@ -4318,6 +4358,8 @@ deletedata(dns_db_t *db ISC_ATTR_UNUSED, dns_dbnode_t *node ISC_ATTR_UNUSED,
 	if (header->closest != NULL) {
 		dns_slabheader_freeproof(db->mctx, &header->closest);
 	}
+
+	LIBDNS_QPCACHE_DELETEDATA_DONE(qpdb, node, data);
 }
 
 /*
@@ -4329,6 +4371,8 @@ expire_ttl_headers(qpcache_t *qpdb, unsigned int locknum,
 		   isc_stdtime_t now, bool cache_is_overmem DNS__DB_FLARG) {
 	isc_heap_t *heap = qpdb->heaps[locknum];
 
+	LIBDNS_QPCACHE_EXPIRE_TTL_START(qpdb, locknum, now);
+
 	for (size_t i = 0; i < DNS_QPDB_EXPIRE_TTL_COUNT; i++) {
 		dns_slabheader_t *header = isc_heap_element(heap, 1);
 
@@ -4351,12 +4395,16 @@ expire_ttl_headers(qpcache_t *qpdb, unsigned int locknum,
 			 * the same heap can be eligible for expiry, either;
 			 * exit cleaning.
 			 */
+			LIBDNS_QPCACHE_EXPIRE_TTL_DONE(qpdb, locknum, now, i);
 			return;
 		}
 
 		expireheader(header, nlocktypep, tlocktypep,
 			     dns_expire_ttl DNS__DB_FLARG_PASS);
 	}
+
+	LIBDNS_QPCACHE_EXPIRE_TTL_DONE(qpdb, locknum, now,
+				       DNS_QPDB_EXPIRE_TTL_COUNT);
 }
 
 static void

lib/dns/rbt-cachedb.c

@@ -61,6 +61,7 @@
 #include <dns/zonekey.h>
 
 #include "db_p.h"
+#include "probes.h"
 #include "rbtdb_p.h"
 
 #define CHECK(op)                            \
@@ -786,6 +787,8 @@ cache_find(dns_db_t *db, const dns_name_t *name, dns_dbversion_t *version,
 	REQUIRE(VALID_RBTDB((dns_rbtdb_t *)db));
 	REQUIRE(version == NULL);
 
+	LIBDNS_RBTDB_CACHE_FIND_START(db, (void *)name, now, options);
+
 	if (now == 0) {
 		now = isc_stdtime_now();
 	}
@@ -1175,6 +1178,9 @@ tree_exit:
 	dns_rbtnodechain_reset(&search.chain);
 
 	update_cachestats(search.rbtdb, result);
+
+	LIBDNS_RBTDB_CACHE_FIND_DONE(db, (void *)name, now, options, result);
+
 	return (result);
 }
 
@@ -1544,11 +1550,15 @@ expiredata(dns_db_t *db, dns_dbnode_t *node, void *data) {
 	isc_rwlocktype_t nlocktype = isc_rwlocktype_none;
 	isc_rwlocktype_t tlocktype = isc_rwlocktype_none;
 
+	LIBDNS_RBTDB_CACHE_EXPIREDATA_START(db, node, data);
+
 	NODE_WRLOCK(&rbtdb->node_locks[rbtnode->locknum].lock, &nlocktype);
 	dns__cacherbt_expireheader(header, &tlocktype,
 				   dns_expire_flush DNS__DB_FILELINE);
 	NODE_UNLOCK(&rbtdb->node_locks[rbtnode->locknum].lock, &nlocktype);
 	INSIST(tlocktype == isc_rwlocktype_none);
+
+	LIBDNS_RBTDB_CACHE_EXPIREDATA_DONE(db, node, data);
 }
 
 dns_dbmethods_t dns__rbtdb_cachemethods = {

lib/dns/rbtdb.c

@@ -61,6 +61,7 @@
 #include <dns/zonekey.h>
 
 #include "db_p.h"
+#include "probes.h"
 #include "rbtdb_p.h"
 
 #define CHECK(op)                            \
@@ -3272,6 +3273,8 @@ dns__rbtdb_addrdataset(dns_db_t *db, dns_dbnode_t *node,
 	REQUIRE(VALID_RBTDB(rbtdb));
 	INSIST(rbtversion == NULL || rbtversion->rbtdb == rbtdb);
 
+	LIBDNS_RBTDB_ADDRDATASET_START(db, node, rdataset);
+
 	if (!IS_CACHE(rbtdb)) {
 		/*
 		 * SOA records are only allowed at top of zone.
@@ -3477,6 +3480,8 @@ dns__rbtdb_addrdataset(dns_db_t *db, dns_dbnode_t *node,
 	}
 	INSIST(tlocktype == isc_rwlocktype_none);
 
+	LIBDNS_RBTDB_ADDRDATASET_DONE(db, node, rdataset, cache_is_overmem);
+
 	return (result);
 }
 
@@ -3716,10 +3721,16 @@ dns__rbtdb_deleterdataset(dns_db_t *db, dns_dbnode_t *node,
 	REQUIRE(VALID_RBTDB(rbtdb));
 	INSIST(rbtversion == NULL || rbtversion->rbtdb == rbtdb);
 
+	LIBDNS_RBTDB_DELETERDATASET_START(db, node, version, type, covers);
+
 	if (type == dns_rdatatype_any) {
+		LIBDNS_RBTDB_DELETERDATASET_DONE(db, node, version, type,
+						 covers, ISC_R_NOTIMPLEMENTED);
 		return (ISC_R_NOTIMPLEMENTED);
 	}
 	if (type == dns_rdatatype_rrsig && covers == 0) {
+		LIBDNS_RBTDB_DELETERDATASET_DONE(db, node, version, type,
+						 covers, ISC_R_NOTIMPLEMENTED);
 		return (ISC_R_NOTIMPLEMENTED);
 	}
 
@@ -3750,6 +3761,9 @@ dns__rbtdb_deleterdataset(dns_db_t *db, dns_dbnode_t *node,
 		dns__rbtdb_setsecure(db, version, rbtdb->origin_node);
 	}
 
+	LIBDNS_RBTDB_DELETERDATASET_DONE(db, node, version, type, covers,
+					 result);
+
 	return (result);
 }
 
@@ -3842,6 +3856,8 @@ dns__rbtdb_locknode(dns_db_t *db, dns_dbnode_t *node, isc_rwlocktype_t type) {
 	dns_rbtdb_t *rbtdb = (dns_rbtdb_t *)db;
 	dns_rbtnode_t *rbtnode = (dns_rbtnode_t *)node;
 
+	LIBDNS_RBTDB_LOCKNODE(db, node, type == isc_rwlocktype_write);
+
 	RWLOCK(&rbtdb->node_locks[rbtnode->locknum].lock, type);
 }
 
@@ -3851,6 +3867,8 @@ dns__rbtdb_unlocknode(dns_db_t *db, dns_dbnode_t *node, isc_rwlocktype_t type) {
 	dns_rbtnode_t *rbtnode = (dns_rbtnode_t *)node;
 
 	RWUNLOCK(&rbtdb->node_locks[rbtnode->locknum].lock, type);
+
+	LIBDNS_RBTDB_UNLOCKNODE(db, node, type == isc_rwlocktype_write);
 }
 
 isc_result_t
@@ -4924,6 +4942,8 @@ dns__rbtdb_deletedata(dns_db_t *db ISC_ATTR_UNUSED,
 	dns_slabheader_t *header = data;
 	dns_rbtdb_t *rbtdb = (dns_rbtdb_t *)header->db;
 
+	LIBDNS_RBTDB_DELETEDATA_START(db, node, data);
+
 	if (header->heap != NULL && header->heap_index != 0) {
 		isc_heap_delete(header->heap, header->heap_index);
 	}
@@ -4946,6 +4966,8 @@ dns__rbtdb_deletedata(dns_db_t *db ISC_ATTR_UNUSED,
 			dns_slabheader_freeproof(db->mctx, &header->closest);
 		}
 	}
+
+	LIBDNS_RBTDB_DELETEDATA_DONE(db, node, data);
 }
 
 /*

tests/bench/qp-dump.c

@@ -236,8 +236,6 @@ main(int argc, char *argv[]) {
 		size_t smallbytes = wirebytes + labels +
 				    names * sizeof(isc_refcount_t);
 		dns_qp_memusage_t memusage = dns_qp_memusage(qp);
-		uint64_t compaction_us, recovery_us, rollback_us;
-		dns_qp_gctime(&compaction_us, &recovery_us, &rollback_us);
 
 		printf("leaves %zu\n"
 		       " nodes %zu\n"
@@ -250,10 +248,6 @@ main(int argc, char *argv[]) {
 		       memusage.free, memusage.hold, memusage.chunk_count,
 		       memusage.bytes);
 
-		printf("%f compaction\n", (double)compaction_us / 1000000);
-		printf("%f recovery\n", (double)recovery_us / 1000000);
-		printf("%f rollback\n", (double)rollback_us / 1000000);
-
 		size_t bytes = memusage.bytes;
 		print_megabytes("file size", filesize);
 		print_megabytes("names", wirebytes);

tests/dns/qpdb_test.c

@@ -31,14 +31,6 @@
 #include <dns/rdatastruct.h>
 #define KEEP_BEFORE
 
-/* Include the main file */
-
-#pragma GCC diagnostic push
-#pragma GCC diagnostic ignored "-Wshadow"
-#undef CHECK
-#include "qpcache.c"
-#pragma GCC diagnostic pop
-
 #undef CHECK
 #include <tests/dns.h>