Merge pull request #2688 from pi-hole/tweak/db_performance

Reduce database locking and add timing debug setting

src/api/config.c

@@ -22,7 +22,7 @@
 #include "config/toml_writer.h"
 // write_dnsmasq_config()
 #include "config/dnsmasq_config.h"
-// shm_lock()
+// lock_shm()
 #include "shmem.h"
 // hash_password()
 #include "config/password.h"

src/api/docs/content/specs/config.yaml

@@ -625,6 +625,8 @@ components:
                   type: boolean
                 netlink:
                   type: boolean
+                timing:
+                  type: boolean
                 all:
                   type: boolean
     topics:
@@ -874,6 +876,7 @@ components:
             reserved: false
             ntp: false
             netlink: false
+            timing: false
             all: false
           took: 0.003
     config_one:

src/config/config.c

@@ -1625,6 +1625,12 @@ void initConfig(struct config *conf)
 	conf->debug.netlink.d.b = false;
 	conf->debug.netlink.c = validate_stub; // Only type-based checking
 
+	conf->debug.timing.k = "debug.timing";
+	conf->debug.timing.h = "Print timing information from various parts of FTL";
+	conf->debug.timing.t = CONF_BOOL;
+	conf->debug.timing.d.b = false;
+	conf->debug.timing.c = validate_stub; // Only type-based checking
+
 	conf->debug.all.k = "debug.all";
 	conf->debug.all.h = "Set all debug flags at once. This is a convenience option to enable all debug flags at once. Note that this option is not persistent, setting it to true will enable all *remaining* debug flags but unsetting it will disable *all* debug flags.";
 	conf->debug.all.t = CONF_ALL_DEBUG_BOOL;

src/config/config.h

@@ -358,6 +358,7 @@ struct config {
 		struct conf_item reserved;
 		struct conf_item ntp;
 		struct conf_item netlink;
+		struct conf_item timing;
 		// all must be the last item in this struct
 		struct conf_item all;
 	} debug;

src/database/common.h

@@ -89,4 +89,30 @@ extern const char *sqlite3ErrName(int rc);
 	}\
 }
 
+// Macro to time a database operation expression EXPR if debug.timing is
+// enabled.
+#define TIMED_DB_OP(EXPR) { \
+	if(!config.debug.timing.v.b) { EXPR; } \
+	else { \
+		struct timespec _timed_start, _timed_end; \
+		clock_gettime(CLOCK_MONOTONIC, &_timed_start); \
+		(EXPR); \
+		clock_gettime(CLOCK_MONOTONIC, &_timed_end); \
+		long _timed_elapsed = (_timed_end.tv_sec - _timed_start.tv_sec) * 10000 + (_timed_end.tv_nsec - _timed_start.tv_nsec) / 100000; \
+		log_debug(DEBUG_TIMING, "Database operation %s took %.1f ms", str(EXPR), 0.1*_timed_elapsed); \
+	}}
+
+// Macro to time a database operation expression EXPR that returns a value if
+// debug.timing is enabled.
+#define TIMED_DB_OP_RESULT(_result, EXPR) { \
+	if(!config.debug.timing.v.b) { _result = EXPR; } \
+	else { \
+		struct timespec _timed_start, _timed_end; \
+		clock_gettime(CLOCK_MONOTONIC, &_timed_start); \
+		 _result = (EXPR); \
+		clock_gettime(CLOCK_MONOTONIC, &_timed_end); \
+		long _timed_elapsed = (_timed_end.tv_sec - _timed_start.tv_sec) * 10000 + (_timed_end.tv_nsec - _timed_start.tv_nsec) / 100000; \
+		log_debug(DEBUG_TIMING, "Database operation %s took %.1f ms", str(EXPR), 0.1*_timed_elapsed); \
+	}}
+
 #endif //DATABASE_COMMON_H

src/database/database-thread.c

@@ -135,7 +135,7 @@ void *DB_thread(void *val)
 
 			// Save data to database
 			DBOPEN_OR_AGAIN();
-			export_queries_to_disk(false);
+			TIMED_DB_OP(export_queries_to_disk(false));
 
 			// Intermediate cancellation-point
 			if(killed)
@@ -144,8 +144,8 @@ void *DB_thread(void *val)
 			// Check if GC should be done on the database
 			if(DBdeleteoldqueries)
 			{
-				// No thread locks needed
-				delete_old_queries_in_DB(db);
+				/* No thread locks needed */
+				TIMED_DB_OP(delete_old_queries_in_DB(db));
 				DBdeleteoldqueries = false;
 			}
 
@@ -163,7 +163,7 @@ void *DB_thread(void *val)
 		if(now - lastAnalyze >= DATABASE_ANALYZE_INTERVAL)
 		{
 			DBOPEN_OR_AGAIN();
-			analyze_database(db);
+			TIMED_DB_OP(analyze_database(db));
 			lastAnalyze = now;
 			DBCLOSE_OR_BREAK();
 		}
@@ -177,7 +177,7 @@ void *DB_thread(void *val)
 		if(now  - lastMACVendor >= DATABASE_MACVENDOR_INTERVAL)
 		{
 			DBOPEN_OR_AGAIN();
-			updateMACVendorRecords(db);
+			TIMED_DB_OP(updateMACVendorRecords(db));
 			lastMACVendor = now;
 			DBCLOSE_OR_BREAK();
 		}
@@ -190,7 +190,7 @@ void *DB_thread(void *val)
 		if(get_and_clear_event(PARSE_NEIGHBOR_CACHE))
 		{
 			DBOPEN_OR_AGAIN();
-			parse_neighbor_cache(db);
+			TIMED_DB_OP(parse_neighbor_cache(db));
 			DBCLOSE_OR_BREAK();
 		}
 
@@ -202,7 +202,7 @@ void *DB_thread(void *val)
 		{
 			DBOPEN_OR_AGAIN();
 			lock_shm();
-			reimport_aliasclients(db);
+			TIMED_DB_OP(reimport_aliasclients(db));
 			unlock_shm();
 			DBCLOSE_OR_BREAK();
 		}

src/database/query-table.c

@@ -238,7 +238,7 @@ bool init_memory_database(void)
 	// queries from the in-memory database (including the query with ID 0)
 	// to the on-disk database.
 	rc = sqlite3_prepare_v3(_memdb, "INSERT INTO disk.query_storage SELECT * FROM query_storage " \
-	                                      "WHERE id > IFNULL((SELECT MAX(id) FROM disk.query_storage), -1) "\
+	                                      "WHERE id > (SELECT IFNULL(MAX(id), -1) FROM disk.query_storage) "\
 	                                        "AND timestamp < ?",
 	                        -1, SQLITE_PREPARE_PERSISTENT, &queries_to_disk_stmt, NULL);
 	if( rc != SQLITE_OK )
@@ -247,11 +247,15 @@ bool init_memory_database(void)
 		return false;
 	}
 
+	// Export linking tables to disk database
+	// We limit the export to new records to avoid the overhead of many
+	// IGNORE executions for records that are already present on disk. It
+	// follows the same logic as for the main query_storage table above.
 	const char *subtable_sql[SUBTABLE_STMTS] = {
-		"INSERT OR IGNORE INTO disk.domain_by_id SELECT * FROM domain_by_id",
-		"INSERT OR IGNORE INTO disk.client_by_id SELECT * FROM client_by_id",
-		"INSERT OR IGNORE INTO disk.forward_by_id SELECT * FROM forward_by_id",
-		"INSERT OR IGNORE INTO disk.addinfo_by_id SELECT * FROM addinfo_by_id",
+		"INSERT OR IGNORE INTO disk.domain_by_id SELECT * FROM domain_by_id WHERE id > (SELECT IFNULL(MAX(id), -1) FROM disk.domain_by_id)",
+		"INSERT OR IGNORE INTO disk.client_by_id SELECT * FROM client_by_id WHERE id > (SELECT IFNULL(MAX(id), -1) FROM disk.client_by_id)",
+		"INSERT OR IGNORE INTO disk.forward_by_id SELECT * FROM forward_by_id WHERE id > (SELECT IFNULL(MAX(id), -1) FROM disk.forward_by_id)",
+		"INSERT OR IGNORE INTO disk.addinfo_by_id SELECT * FROM addinfo_by_id WHERE id > (SELECT IFNULL(MAX(id), -1) FROM disk.addinfo_by_id)",
 		"UPDATE disk.sqlite_sequence SET seq = (SELECT seq FROM sqlite_sequence WHERE disk.sqlite_sequence.name = sqlite_sequence.name)"
 	};
 
@@ -504,7 +508,7 @@ bool detach_database(sqlite3* db, const char **message, const char *alias)
 	return okay;
 }
 
-// Get number of queries either in the temp or in the on-diks database
+// Get number of queries either in the temp or in the on-disk database
 // This routine is used by the API routines.
 int get_number_of_queries_in_DB(sqlite3 *db, const char *tablename, double *earliest_timestamp)
 {

src/dnsmasq_interface.c

@@ -48,7 +48,7 @@
 #include "webserver/webserver.h"
 // type struct sqlite3_stmt_vec
 #include "vector.h"
-// query_to_database()
+// init_memory_database()
 #include "database/query-table.h"
 // reread_config()
 #include "config/config.h"
@@ -1695,11 +1695,11 @@ static bool FTL_check_blocking(const unsigned int queryID, const unsigned int do
 	const char *blockedDomain = domain_lower;
 
 	// Check exact whitelist for match
-	query->flags.allowed = in_allowlist(domain_lower, dns_cache, client) == FOUND;
+	TIMED_DB_OP_RESULT(query->flags.allowed, in_allowlist(domain_lower, dns_cache, client) == FOUND);
 
 	// If not found: Check regex whitelist for match
 	if(!query->flags.allowed)
-		query->flags.allowed = in_regex(domain_lower, dns_cache, client->id, REGEX_ALLOW);
+		TIMED_DB_OP_RESULT(query->flags.allowed, in_regex(domain_lower, dns_cache, client->id, REGEX_ALLOW));
 
 	// Check if this is a special domain
 	if(!query->flags.allowed && special_domain(query, domain_lower))
@@ -1721,7 +1721,8 @@ static bool FTL_check_blocking(const unsigned int queryID, const unsigned int do
 	// Check blacklist (exact + regex) and gravity for queried domain
 	unsigned char new_status = QUERY_UNKNOWN;
 	bool db_okay = true;
-	bool blockDomain = check_domain_blocked(domain_lower, client, query, dns_cache, &new_status, &db_okay);
+	bool blockDomain;
+	TIMED_DB_OP_RESULT(blockDomain, check_domain_blocked(domain_lower, client, query, dns_cache, &new_status, &db_okay));
 
 	// Check blacklist (exact + regex) and gravity for _esni.domain if enabled
 	// (defaulting to true)
@@ -1729,7 +1730,7 @@ static bool FTL_check_blocking(const unsigned int queryID, const unsigned int do
 	   !query->flags.allowed && blockDomain == NOT_FOUND &&
 	   strlen(domain_lower) > 6 && strncasecmp(domain_lower, "_esni.", 6u) == 0)
 	{
-		blockDomain = check_domain_blocked(domain_lower + 6u, client, query, dns_cache, &new_status, &db_okay);
+		TIMED_DB_OP_RESULT(blockDomain, check_domain_blocked(domain_lower + 6u, client, query, dns_cache, &new_status, &db_okay));
 
 		// Update DNS cache status
 		cacheStatus = dns_cache->blocking_status;

src/enums.h

@@ -156,6 +156,7 @@ enum debug_flag {
 	DEBUG_RESERVED,
 	DEBUG_NTP,
 	DEBUG_NETLINK,
+	DEBUG_TIMING,
 	DEBUG_MAX
 } __attribute__ ((packed));
 

src/log.c

@@ -224,6 +224,8 @@ const char *debugstr(const enum debug_flag flag)
 			return "DEBUG_NTP";
 		case DEBUG_NETLINK:
 			return "DEBUG_NETLINK";
+		case DEBUG_TIMING:
+			return "DEBUG_TIMING";
 		case DEBUG_MAX:
 			return "DEBUG_MAX";
 		case DEBUG_NONE: // fall through

src/shmem.c

@@ -134,6 +134,10 @@ typedef struct {
 		volatile pid_t pid;
 		volatile pid_t tid;
 	} owner;
+	struct {
+		struct timespec begin;
+		struct timespec end;
+	} time;
 } ShmLock;
 static ShmLock *shmLock = NULL;
 static ShmSettings *shmSettings = NULL;
@@ -391,6 +395,7 @@ void _lock_shm(const char *func, const int line, const char *file)
 
 	result = pthread_mutex_lock(&shmLock->lock.inner);
 
+	clock_gettime(CLOCK_MONOTONIC, &shmLock->time.begin);
 	log_debug(DEBUG_LOCKS, "Obtained SHM lock for %s() (%s:%i)", func, file, line);
 
 	if(result != 0)
@@ -433,6 +438,15 @@ void _unlock_shm(const char *func, const int line, const char * file)
 	if(result != 0)
 		log_err("Failed to unlock outer SHM lock: %s", strerror(result));
 
+	clock_gettime(CLOCK_MONOTONIC, &shmLock->time.end);
+	if(config.debug.timing.v.b)
+	{
+		const double lock_time = (shmLock->time.end.tv_sec - shmLock->time.begin.tv_sec) / 1000.0 +
+		                         (shmLock->time.end.tv_nsec - shmLock->time.begin.tv_nsec) / 1e6;
+		log_debug(DEBUG_TIMING, "SHM lock held for %.3f ms in %s() (%s:%i)",
+		          lock_time, func, file, line);
+	}
+
 	log_debug(DEBUG_LOCKS, "Removed SHM lock in %s() (%s:%i)", func, file, line);
 }
 

test/pihole.toml

@@ -1,7 +1,7 @@
-# Pi-hole configuration file (v6.2.3-312-g9f1eb768-dirty) on branch (no branch, rebasing misc_dnsmasq_warn)
+# Pi-hole configuration file (v6.3.2-8-g58a618e2-dirty) on branch tweak/db_performance
 # Encoding: UTF-8
 # This file is managed by pihole-FTL
-# Last updated on 2025-10-23 17:03:51 UTC
+# Last updated on 2025-11-01 13:12:20 UTC
 
 [dns]
   # Upstream DNS Servers to be used by Pi-hole. If this is not set, Pi-hole will not
@@ -1667,14 +1667,20 @@
   #     true or false
   netlink = true ### CHANGED, default = false
 
+  # Print timing information from various parts of FTL
+  #
+  # Allowed values are:
+  #     true or false
+  timing = true ### CHANGED, default = false
+
   # Set all debug flags at once. This is a convenience option to enable all debug flags
   # at once. Note that this option is not persistent, setting it to true will enable all
   # *remaining* debug flags but unsetting it will disable *all* debug flags.
   all = true ### CHANGED, default = false
 
 # Configuration statistics:
-# 161 total entries out of which 108 entries are default
-# --> 53 entries are modified
+# 162 total entries out of which 108 entries are default
+# --> 54 entries are modified
 # 3 entries are forced through environment:
 #   - misc.nice
 #   - misc.check.shmem