Log when we grow the cache hash tables
Related to #1775 (closed) (and its successors) and to Support ticket #16212
Although we're aware that resizing (growing) the cache has tables can cause delays in processing client queries by a resolver, particularly when the hash table and cache have reached a significant size, we don't log anything when we do this operation.
This is a bit bizarre - we log when we resize the similar hash tables in ADB.
It was also requested that we add some logging in #1775 (closed), but this appears to have been overlooked:
It would also be really helpful if any hash table growing could be logged - to include what the size is expanding to (this will help admins to tune their servers accordingly).
The customer involved in Support ticket #16212 also suggests that it's probably not necessary to log all cache hash table resizing, just the significant/big events. However, I'd be inclined to: a) Log the initial size (when computed based on max-cache-size and whether or not the server allows recursion) b) Log all resizing/rehash actions
That way, we have something to search for in the logs, if there is a suspicion that hash table resizing - particularly on recursive resolvers of significant size - might have occurred unexpectedly (despite #1775 (closed)) and caused a short (likely a couple of seconds) blackout on the resolver.
Here's the proposed code submitted by the customer:
*** ./lib/dns/rbt.c-orig 2020-08-17 10:29:01.631928214 +0200
--- ./lib/dns/rbt.c 2020-08-17 10:29:33.567261898 +0200
***************
*** 2360,2365 ****
--- 2360,2373 ----
rbt->hashbits = newbits;
newsize = HASHSIZE(rbt->hashbits);
+
+ #ifdef WANT_LOG_REHASH
+ if (oldbits >= 14)
+ isc_log_write(dns_lctx, DNS_LOGCATEGORY_DATABASE, DNS_LOGMODULE_CACHE, ISC_LOG_WARNING,
+ "rehash %p: grow table from %d to %d starting", rbt, (int)oldsize, (int)newsize);
+ #endif
+
+
rbt->hashtable = isc_mem_get(rbt->mctx,
newsize * sizeof(dns_rbtnode_t *));
memset(rbt->hashtable, 0, newsize * sizeof(dns_rbtnode_t *));
***************
*** 2376,2381 ****
--- 2384,2393 ----
}
isc_mem_put(rbt->mctx, oldtable, oldsize * sizeof(dns_rbtnode_t *));
+ #ifdef WANT_LOG_REHASH
+ if (oldbits >= 14)
+ isc_log_write(dns_lctx, DNS_LOGCATEGORY_DATABASE, DNS_LOGMODULE_CACHE, ISC_LOG_WARNING, "rehash %p: grow finished", rbt);
+ #endif
}
static void
Note - I have tagged this as a bug, since I consider it a failure of named not to log something that can affect its responsiveness when it occurs. If possible, I'd like to see this included in the December releases (and also back-ported to 9.11).