Log when we grow the cache hash tables
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).