diff --git a/src/api/config.c b/src/api/config.c index e0868afa..53068b65 100644 --- a/src/api/config.c +++ b/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" diff --git a/src/api/docs/content/specs/config.yaml b/src/api/docs/content/specs/config.yaml index 7a2602fe..f2fc8a7c 100644 --- a/src/api/docs/content/specs/config.yaml +++ b/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: diff --git a/src/config/config.c b/src/config/config.c index bb012c15..c3e3af2c 100644 --- a/src/config/config.c +++ b/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; diff --git a/src/config/config.h b/src/config/config.h index 0ad68605..877c0a0d 100644 --- a/src/config/config.h +++ b/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; diff --git a/src/database/common.h b/src/database/common.h index 6a26a374..f83c6182 100644 --- a/src/database/common.h +++ b/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 diff --git a/src/database/database-thread.c b/src/database/database-thread.c index a3396628..dbbee41f 100644 --- a/src/database/database-thread.c +++ b/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(); } diff --git a/src/database/query-table.c b/src/database/query-table.c index 2c0cbf81..450bb52e 100644 --- a/src/database/query-table.c +++ b/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) { diff --git a/src/dnsmasq_interface.c b/src/dnsmasq_interface.c index eb84f04f..d1977faa 100644 --- a/src/dnsmasq_interface.c +++ b/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; diff --git a/src/enums.h b/src/enums.h index ca524783..99981b78 100644 --- a/src/enums.h +++ b/src/enums.h @@ -156,6 +156,7 @@ enum debug_flag { DEBUG_RESERVED, DEBUG_NTP, DEBUG_NETLINK, + DEBUG_TIMING, DEBUG_MAX } __attribute__ ((packed)); diff --git a/src/log.c b/src/log.c index c5612d0e..5a1d92f3 100644 --- a/src/log.c +++ b/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 diff --git a/src/shmem.c b/src/shmem.c index e3b83945..5e270f2a 100644 --- a/src/shmem.c +++ b/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); } diff --git a/test/pihole.toml b/test/pihole.toml index 4c52db6a..58fb443c 100644 --- a/test/pihole.toml +++ b/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