Skip to content

Implement asynchronous query import on startup #2725

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
DL6ER wants to merge 14 commits into
base: development
Choose a base branch
from
Open

Implement asynchronous query import on startup #2725

DL6ER wants to merge 14 commits into from
+317 −243

Conversation

@DL6ER
Copy link
Member

@DL6ER DL6ER commented Nov 25, 2025 •
edited
Loading

What does this implement/fix?

Implement asynchronous importing of queries on startup. While the queries are imported, DNS resolution should be available. Overall, this increases the total workload (due to much more locking/unlocking), however, it is less of an issue now as the entire importing process is happening non-blocking in a dedicated thread after starting up.

TODO

  • Prevent GC from running until import is done
  • Reduce lock/unlock work by blocking in batches of, say, 100 queries (?) to remedy the added workload notably
  • Check if we really need pre-allocate the additional space for domains/clients/upstreams (probably not) because we will not see all of them during the subsequent query parsing. We will, however, need the query space.
  • Check if we should optimize the shared memory resizing by resizing in units of entire pagesizes. In the end, it will still mean we have less than 1 MB per allocation step and memory is cheap these days

Related issue or feature (if applicable): N/A

Pull request in docs with documentation (if applicable): N/A

By submitting this pull request, I confirm the following:

  1. I have read and understood the contributors guide, as well as this entire template. I understand which branch to base my commits and Pull Requests against.
  2. I have commented my proposed changes within the code.
  3. I am willing to help maintain this change if there are issues with it later.
  4. It is compatible with the EUPL 1.2 license
  5. I have squashed any insignificant commits. (git rebase)

Checklist:

  • The code change is tested and works locally.
  • I based my code and PRs against the repositories development branch.
  • I signed off all commits. Pi-hole enforces the DCO for all contributions
  • I signed all my commits. Pi-hole requires signatures to verify authorship
  • I have read the above and my PR is ready for review.

@DL6ER
Implement look-ahead shared memory resizing and move database initial…
5e49b8b 
…ization into a dedicated asynchronous thread

Signed-off-by: Dominik <[email protected]>
DL6ER added 5 commits December 1, 2025 20:11
@DL6ER
Postpose GC runs until async database import is done
a27b105 
Signed-off-by: Dominik <[email protected]>
@DL6ER
Optionally batch querys during import to reduce locking overhead. Thi…
6cd4622 
…s is experimental and disabled for now as it will reduce the time being unlocked, i.e., it reduces the number of ocassions where normal query handling could take place (which is the entire point about implementing async importing)

Signed-off-by: Dominik <[email protected]>
@DL6ER
Remove pre-allocation of domains, clients, and upstreams as we will n…
fd6eaab 
…ot import all of them from disk during import. This will make the SHM objects unnecessarily large - they can grow naturally during importing

Signed-off-by: Dominik <[email protected]>
@DL6ER
Log when queries are imported based on the really imported queries
b8bdf7f 
Signed-off-by: Dominik <[email protected]>
@DL6ER
Merge branch 'development' into tweak/async_import
af0b5bb
@DL6ER DL6ER marked this pull request as ready for review December 2, 2025 19:52
@DL6ER DL6ER requested a review from a team as a code owner December 2, 2025 19:52
@pralor-bot
Copy link

pralor-bot commented Dec 4, 2025

This pull request has been mentioned on Pi-hole Userspace. There might be relevant details there:

https://discourse.pi-hole.net/t/ftl-6-4-1-extremely-slow-startup/83790/2

@sawsanders
Copy link

sawsanders commented Dec 5, 2025

I tried this branch out and it looks like it's roughly double counting the imported domains.

Development 

2025-12-05 09:30:16.341 PST [241926M] INFO: FTL branch: development
2025-12-05 09:30:16.341 PST [241926M] INFO: FTL version: vDev-1635019
2025-12-05 09:30:16.341 PST [241926M] INFO: FTL commit: 16350194
2025-12-05 09:30:16.341 PST [241926M] INFO: FTL date: 2025-12-04 20:32:20 +0100
2025-12-05 09:30:16.341 PST [241926M] INFO: FTL user: pihole
2025-12-05 09:30:16.341 PST [241926M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2025-12-05 09:30:16.344 PST [241926M] INFO: Wrote config file:
2025-12-05 09:30:16.344 PST [241926M] INFO:  - 162 total entries
2025-12-05 09:30:16.344 PST [241926M] INFO:  - 129 entries are default
2025-12-05 09:30:16.344 PST [241926M] INFO:  - 33 entries are modified
2025-12-05 09:30:16.344 PST [241926M] INFO:  - 0 entries are forced through environment
2025-12-05 09:30:16.346 PST [241926M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2025-12-05 09:30:16.346 PST [241926M] INFO: PID file does not exist or not readable
2025-12-05 09:30:16.346 PST [241926M] INFO: No other running FTL process found.
2025-12-05 09:30:16.350 PST [241926M] INFO: PID of FTL process: 241926
2025-12-05 09:30:16.350 PST [241926M] INFO: Not sleeping as system has finished booting
2025-12-05 09:30:16.350 PST [241926M] INFO: listening on 0.0.0.0 port 53
2025-12-05 09:30:16.350 PST [241926M] INFO: listening on :: port 53
2025-12-05 09:30:16.352 PST [241926M] INFO: PID of FTL process: 241926
2025-12-05 09:30:16.353 PST [241926M] INFO: Database version is 21
2025-12-05 09:30:16.354 PST [241926M] INFO: Database successfully initialized
2025-12-05 09:30:18.703 PST [241926M] INFO: Imported 163468 queries from the on-disk database (it has 13148755 rows)
2025-12-05 09:30:18.703 PST [241926M] INFO: Parsing queries in database
2025-12-05 09:30:18.772 PST [241926M] INFO:   10000 queries parsed...
2025-12-05 09:30:18.817 PST [241926M] INFO:   20000 queries parsed...
2025-12-05 09:30:18.859 PST [241926M] INFO:   30000 queries parsed...
2025-12-05 09:30:18.909 PST [241926M] INFO:   40000 queries parsed...
2025-12-05 09:30:18.947 PST [241926M] INFO:   50000 queries parsed...
2025-12-05 09:30:18.985 PST [241926M] INFO:   60000 queries parsed...
2025-12-05 09:30:19.024 PST [241926M] INFO:   70000 queries parsed...
2025-12-05 09:30:19.064 PST [241926M] INFO:   80000 queries parsed...
2025-12-05 09:30:19.100 PST [241926M] INFO:   90000 queries parsed...
2025-12-05 09:30:19.141 PST [241926M] INFO:   100000 queries parsed...
2025-12-05 09:30:19.168 PST [241926M] INFO:   110000 queries parsed...
2025-12-05 09:30:19.196 PST [241926M] INFO:   120000 queries parsed...
2025-12-05 09:30:19.226 PST [241926M] INFO:   130000 queries parsed...
2025-12-05 09:30:19.282 PST [241926M] INFO:   140000 queries parsed...
2025-12-05 09:30:19.316 PST [241926M] INFO:   150000 queries parsed...
2025-12-05 09:30:19.357 PST [241926M] INFO:   160000 queries parsed...
2025-12-05 09:30:19.374 PST [241926M] INFO: Imported 163462 queries from the long-term database
2025-12-05 09:30:19.374 PST [241926M] INFO:  -> Total DNS queries: 163462
2025-12-05 09:30:19.374 PST [241926M] INFO:  -> Cached DNS queries: 53759
2025-12-05 09:30:19.374 PST [241926M] INFO:  -> Forwarded DNS queries: 70121
2025-12-05 09:30:19.374 PST [241926M] INFO:  -> Blocked DNS queries: 38284
2025-12-05 09:30:19.374 PST [241926M] INFO:  -> Unknown DNS queries: 102
2025-12-05 09:30:19.375 PST [241926M] INFO:  -> Unique domains: 5173
2025-12-05 09:30:19.375 PST [241926M] INFO:  -> Unique clients: 72
2025-12-05 09:30:19.375 PST [241926M] INFO:  -> DNS cache records: 3515
2025-12-05 09:30:19.375 PST [241926M] INFO:  -> Known forward destinations: 5
2025-12-05 09:30:19.513 PST [241926M] INFO: FTL is running as user pihole (UID 999)
2025-12-05 09:30:19.513 PST [241926M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2025-12-05 09:30:19.513 PST [241926M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2025-12-05 09:30:19.514 PST [241926M] INFO: Web server ports:
2025-12-05 09:30:19.514 PST [241926M] INFO:   - 0.0.0.0:80 (HTTP, IPv4, OK)
2025-12-05 09:30:19.514 PST [241926M] INFO:   - [::]:80 (HTTP, IPv6, OK)
2025-12-05 09:30:19.514 PST [241926M] INFO:   - 0.0.0.0:443 (HTTPS, IPv4, OK)
2025-12-05 09:30:19.514 PST [241926M] INFO:   - [::]:443 (HTTPS, IPv6, OK)
2025-12-05 09:30:19.514 PST [241926M] INFO: Restored 2 API sessions from the database
2025-12-05 09:30:19.518 PST [241926M] INFO: Blocking status is enabled
2025-12-05 09:30:19.708 PST [241926/T242015] INFO: Compiled 8 allow and 19 deny regex for 72 clients in 91.5 msec
2025-12-05 09:30:23.615 PST [241926/T242014] INFO: Received 8/8 valid NTP replies from time.cloudflare.com
2025-12-05 09:30:23.615 PST [241926/T242014] INFO: Time offset: 1.471383e+00 ms (excluded 1 outliers)
2025-12-05 09:30:23.615 PST [241926/T242014] INFO: Round-trip delay: 7.677759e+00 ms (excluded 1 outliers)
2025-12-05 09:30:24.001 PST [241926/T242014] INFO: Current RTC time is 2025-12-05 17:30:23
2025-12-05 09:30:24.003 PST [241926/T242014] INFO: RTC time set to 2025-12-05 17:30:24
2025-12-05 09:30:24.010 PST [241926/T242134] INFO: NTP server listening on 0.0.0.0:123 (IPv4)

tweak/ascync_import 

2025-12-05 09:46:53.823 PST [246525M] INFO: FTL branch: tweak/async_import
2025-12-05 09:46:53.823 PST [246525M] INFO: FTL version: vDev-af0b5bb
2025-12-05 09:46:53.823 PST [246525M] INFO: FTL commit: af0b5bb0
2025-12-05 09:46:53.823 PST [246525M] INFO: FTL date: 2025-12-02 20:32:57 +0100
2025-12-05 09:46:53.823 PST [246525M] INFO: FTL user: pihole
2025-12-05 09:46:53.823 PST [246525M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2025-12-05 09:46:53.826 PST [246525M] INFO: Wrote config file:
2025-12-05 09:46:53.826 PST [246525M] INFO:  - 162 total entries
2025-12-05 09:46:53.826 PST [246525M] INFO:  - 129 entries are default
2025-12-05 09:46:53.826 PST [246525M] INFO:  - 33 entries are modified
2025-12-05 09:46:53.826 PST [246525M] INFO:  - 0 entries are forced through environment
2025-12-05 09:46:53.828 PST [246525M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2025-12-05 09:46:53.828 PST [246525M] INFO: PID file does not exist or not readable
2025-12-05 09:46:53.828 PST [246525M] INFO: No other running FTL process found.
2025-12-05 09:46:53.831 PST [246525M] INFO: PID of FTL process: 246525
2025-12-05 09:46:53.831 PST [246525M] INFO: Not sleeping as system has finished booting
2025-12-05 09:46:53.832 PST [246525M] INFO: listening on 0.0.0.0 port 53
2025-12-05 09:46:53.832 PST [246525M] INFO: listening on :: port 53
2025-12-05 09:46:53.834 PST [246525M] INFO: PID of FTL process: 246525
2025-12-05 09:46:53.835 PST [246525M] INFO: Database version is 21
2025-12-05 09:46:53.836 PST [246525M] INFO: Database successfully initialized
2025-12-05 09:46:56.177 PST [246525M] INFO: Imported 162511 (162511) queries from the on-disk database (it has 13149456 rows)
2025-12-05 09:46:56.311 PST [246525/T246593] INFO: Parsing queries in database
2025-12-05 09:46:56.311 PST [246525M] INFO: FTL is running as user pihole (UID 999)
2025-12-05 09:46:56.311 PST [246525M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2025-12-05 09:46:56.312 PST [246525M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2025-12-05 09:46:56.312 PST [246525M] INFO: Web server ports:
2025-12-05 09:46:56.312 PST [246525M] INFO:   - 0.0.0.0:80 (HTTP, IPv4, OK)
2025-12-05 09:46:56.312 PST [246525M] INFO:   - [::]:80 (HTTP, IPv6, OK)
2025-12-05 09:46:56.312 PST [246525M] INFO:   - 0.0.0.0:443 (HTTPS, IPv4, OK)
2025-12-05 09:46:56.312 PST [246525M] INFO:   - [::]:443 (HTTPS, IPv6, OK)
2025-12-05 09:46:56.312 PST [246525M] INFO: Restored 2 API sessions from the database
2025-12-05 09:46:56.317 PST [246525M] INFO: Blocking status is enabled
2025-12-05 09:46:56.413 PST [246525/T246593] INFO:   10000 queries parsed...
2025-12-05 09:46:56.467 PST [246525/T246593] INFO:   20000 queries parsed...
2025-12-05 09:46:56.534 PST [246525/T246593] INFO:   30000 queries parsed...
2025-12-05 09:46:56.607 PST [246525/T246593] INFO:   40000 queries parsed...
2025-12-05 09:46:56.661 PST [246525/T246593] INFO:   50000 queries parsed...
2025-12-05 09:46:56.717 PST [246525/T246593] INFO:   60000 queries parsed...
2025-12-05 09:46:56.776 PST [246525/T246593] INFO:   70000 queries parsed...
2025-12-05 09:46:56.828 PST [246525/T246593] INFO:   80000 queries parsed...
2025-12-05 09:46:56.887 PST [246525/T246593] INFO:   90000 queries parsed...
2025-12-05 09:46:56.939 PST [246525/T246593] INFO:   100000 queries parsed...
2025-12-05 09:46:56.983 PST [246525/T246593] INFO:   110000 queries parsed...
2025-12-05 09:46:57.028 PST [246525/T246593] INFO:   120000 queries parsed...
2025-12-05 09:46:57.081 PST [246525/T246593] INFO:   130000 queries parsed...
2025-12-05 09:46:57.145 PST [246525/T246593] INFO:   140000 queries parsed...
2025-12-05 09:46:57.196 PST [246525/T246593] INFO:   150000 queries parsed...
2025-12-05 09:46:57.258 PST [246525/T246593] INFO:   160000 queries parsed...
2025-12-05 09:46:57.272 PST [246525/T246593] INFO: Imported 325029 queries from the long-term database
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Total DNS queries: 325029
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Cached DNS queries: 53468
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Forwarded DNS queries: 69576
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Blocked DNS queries: 38191
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Unknown DNS queries: 106
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Unique domains: 5097
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Unique clients: 72
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> DNS cache records: 3362
2025-12-05 09:46:57.272 PST [246525/T246593] INFO:  -> Known forward destinations: 5
2025-12-05 09:46:57.331 PST [246525/T246593] INFO: Compiled 8 allow and 19 deny regex for 72 clients in 58.3 msec

debug log: https://tricorder.pi-hole.net/QeexpjHy/

@DL6ER
Copy link
Member Author

DL6ER commented Dec 6, 2025

@sawsanders Thanks for checking. I did push a fix for this yesterday but forgot to mention this here.

@sawsanders
Copy link

sawsanders commented Dec 6, 2025

I updated and it seemed to work as expected until I restarted FTL: sudo service pihole-FTL restart

I started to see memory errors. I ran pihole -up and the errors persisted:

FTL Log 

2025-12-06 06:54:33.222 PST [594698M] INFO: ########## FTL started on pi5! ##########
2025-12-06 06:54:33.222 PST [594698M] INFO: FTL branch: tweak/async_import
2025-12-06 06:54:33.222 PST [594698M] INFO: FTL version: vDev-184f80a
2025-12-06 06:54:33.222 PST [594698M] INFO: FTL commit: 184f80a2
2025-12-06 06:54:33.222 PST [594698M] INFO: FTL date: 2025-12-05 19:14:40 +0100
2025-12-06 06:54:33.222 PST [594698M] INFO: FTL user: pihole
2025-12-06 06:54:33.222 PST [594698M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2025-12-06 06:54:33.225 PST [594698M] INFO: Wrote config file:
2025-12-06 06:54:33.225 PST [594698M] INFO:  - 162 total entries
2025-12-06 06:54:33.225 PST [594698M] INFO:  - 129 entries are default
2025-12-06 06:54:33.225 PST [594698M] INFO:  - 33 entries are modified
2025-12-06 06:54:33.225 PST [594698M] INFO:  - 0 entries are forced through environment
2025-12-06 06:54:33.228 PST [594698M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2025-12-06 06:54:33.228 PST [594698M] INFO: PID file does not exist or not readable
2025-12-06 06:54:33.228 PST [594698M] INFO: No other running FTL process found.
2025-12-06 06:54:33.231 PST [594698M] INFO: PID of FTL process: 594698
2025-12-06 06:54:33.231 PST [594698M] INFO: Not sleeping as system has finished booting
2025-12-06 06:54:33.232 PST [594698M] INFO: listening on 0.0.0.0 port 53
2025-12-06 06:54:33.232 PST [594698M] INFO: listening on :: port 53
2025-12-06 06:54:33.234 PST [594698M] INFO: PID of FTL process: 594698
2025-12-06 06:54:33.235 PST [594698M] INFO: Database version is 21
2025-12-06 06:54:33.236 PST [594698M] INFO: Database successfully initialized
2025-12-06 06:54:35.649 PST [594698M] INFO: Imported 171261 queries from the on-disk database (it has 13185899 rows)
2025-12-06 06:54:35.781 PST [594698/T594725] INFO: Parsing queries in database
2025-12-06 06:54:35.781 PST [594698M] INFO: FTL is running as user pihole (UID 999)
2025-12-06 06:54:35.782 PST [594698M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2025-12-06 06:54:35.782 PST [594698M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2025-12-06 06:54:35.782 PST [594698M] INFO: Web server ports:
2025-12-06 06:54:35.783 PST [594698M] INFO:   - 0.0.0.0:80 (HTTP, IPv4, OK)
2025-12-06 06:54:35.783 PST [594698M] INFO:   - [::]:80 (HTTP, IPv6, OK)
2025-12-06 06:54:35.783 PST [594698M] INFO:   - 0.0.0.0:443 (HTTPS, IPv4, OK)
2025-12-06 06:54:35.783 PST [594698M] INFO:   - [::]:443 (HTTPS, IPv6, OK)
2025-12-06 06:54:35.783 PST [594698M] INFO: Restored 2 API sessions from the database
2025-12-06 06:54:35.790 PST [594698M] INFO: Blocking status is enabled
2025-12-06 06:54:35.871 PST [594698/T594725] INFO:   10000 queries parsed...
2025-12-06 06:54:35.932 PST [594698/T594725] INFO:   20000 queries parsed...
2025-12-06 06:54:35.991 PST [594698/T594725] INFO:   30000 queries parsed...
2025-12-06 06:54:36.048 PST [594698/T594725] INFO:   40000 queries parsed...
2025-12-06 06:54:36.102 PST [594698/T594725] INFO:   50000 queries parsed...
2025-12-06 06:54:36.160 PST [594698/T594725] INFO:   60000 queries parsed...
2025-12-06 06:54:36.219 PST [594698/T594725] INFO:   70000 queries parsed...
2025-12-06 06:54:36.272 PST [594698/T594725] INFO:   80000 queries parsed...
2025-12-06 06:54:36.328 PST [594698/T594725] INFO:   90000 queries parsed...
2025-12-06 06:54:36.386 PST [594698/T594725] INFO:   100000 queries parsed...
2025-12-06 06:54:36.439 PST [594698/T594725] INFO:   110000 queries parsed...
2025-12-06 06:54:36.484 PST [594698/T594725] INFO:   120000 queries parsed...
2025-12-06 06:54:36.529 PST [594698/T594725] INFO:   130000 queries parsed...
2025-12-06 06:54:36.571 PST [594698/T594725] INFO:   140000 queries parsed...
2025-12-06 06:54:36.613 PST [594698/T594725] INFO:   150000 queries parsed...
2025-12-06 06:54:36.654 PST [594698/T594725] INFO:   160000 queries parsed...
2025-12-06 06:54:36.717 PST [594698/T594725] INFO:   170000 queries parsed...
2025-12-06 06:54:36.722 PST [594698/T594725] INFO: Imported 171258 queries from the long-term database
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Total DNS queries: 171303
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Cached DNS queries: 56005
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Forwarded DNS queries: 74632
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Blocked DNS queries: 39001
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Unknown DNS queries: 143
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Unique domains: 4706
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Unique clients: 76
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> DNS cache records: 3623
2025-12-06 06:54:36.722 PST [594698/T594725] INFO:  -> Known forward destinations: 5
2025-12-06 06:54:36.786 PST [594698/T594725] INFO: Compiled 8 allow and 19 deny regex for 76 clients in 62.4 msec
2025-12-06 06:54:37.087 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:38.089 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:39.091 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:40.094 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:41.096 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:42.098 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:43.001 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:44.004 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:45.006 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:46.008 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:47.010 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:48.013 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:49.015 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:50.018 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:51.020 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:51.893 PST [594698/T594724] INFO: Received 8/8 valid NTP replies from time.cloudflare.com
2025-12-06 06:54:51.893 PST [594698/T594724] INFO: Time offset: 4.132475e-01 ms (excluded 1 outliers)
2025-12-06 06:54:51.893 PST [594698/T594724] INFO: Round-trip delay: 7.526057e+00 ms (excluded 1 outliers)
2025-12-06 06:54:52.002 PST [594698/T594724] INFO: Current RTC time is 2025-12-06 14:54:51
2025-12-06 06:54:52.003 PST [594698/T594724] INFO: RTC time set to 2025-12-06 14:54:52
2025-12-06 06:54:52.003 PST [594698/T595713] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2025-12-06 06:54:52.023 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:52.349 PST [594698M] ERROR: SQLite3: no such table: main.antigravity in "SELECT adlist_id from vw_antigravity WHERE domain = ? AND group_id IN (13);" (1)
2025-12-06 06:54:52.349 PST [594698M] ERROR: domain_in_list("github.com", 0xffffbbbff4c0, antigravity): Failed to perform step: SQL logic error
2025-12-06 06:54:52.349 PST [594698M] ERROR: SQLite3: no such table: main.gravity in "SELECT adlist_id from vw_gravity WHERE domain = ? AND group_id IN (13);" (1)
2025-12-06 06:54:52.349 PST [594698M] ERROR: domain_in_list("github.com", 0xffffbbbff240, gravity): Failed to perform step: SQL logic error
2025-12-06 06:54:52.352 PST [594698M] ERROR: SQLite3: no such table: main.antigravity in "SELECT adlist_id from vw_antigravity WHERE domain = ? AND group_id IN (13);" (1)
2025-12-06 06:54:52.352 PST [594698M] ERROR: domain_in_list("github.com", 0xffffbbbff4c0, antigravity): Failed to perform step: SQL logic error
2025-12-06 06:54:52.352 PST [594698M] ERROR: SQLite3: no such table: main.gravity in "SELECT adlist_id from vw_gravity WHERE domain = ? AND group_id IN (13);" (1)
2025-12-06 06:54:52.352 PST [594698M] ERROR: domain_in_list("github.com", 0xffffbbbff240, gravity): Failed to perform step: SQL logic error
2025-12-06 06:54:53.026 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:53.027 PST [594698/T594725] INFO: Gravity database has been updated, reloading now
2025-12-06 06:54:53.091 PST [594698/T594725] INFO: Compiled 8 allow and 19 deny regex for 76 clients in 61.2 msec
2025-12-06 06:54:54.092 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:55.095 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:56.097 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:57.000 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:58.003 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:54:59.005 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:00.008 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:01.013 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:02.016 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:03.018 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:04.021 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260
2025-12-06 06:55:05.023 PST [594698/T594725] ERROR: Memory error in queries_to_database() when trying to access query 171260

debug log: https://tricorder.pi-hole.net/RAxHt72C/

@DL6ER
Copy link
Member Author

DL6ER commented Dec 7, 2025

This is indeed interesting, I have not been able to reproduce this myself. Please enable debug.queries, and debug.database, e.g.

sudo pihole-FTL --config debug.queries true
sudo pihole-FTL --config debug.database true

This should add some more relevant lines around this.

The resulting log might be a lot larger so running

cat /var/log/pihole/FTL.log| pihole tricorder

instead may be handy. The log will securely be uploaded to a place where only Pi-hole developers can access it.

@sawsanders
Copy link

sawsanders commented Dec 7, 2025

Ok done. I see errors starting at timestamp 09:29:04.163

https://tricorder.pi-hole.net/nciJHK08/

@DL6ER
Copy link
Member Author

DL6ER commented Dec 7, 2025

Sorry, it's still not very clear what is happening here ... I did two further small changes - any chance you could give it another try? The binaries should be ready in a few minutes (we're looking for commit 80e14ec).

@sawsanders
Copy link

sawsanders commented Dec 8, 2025

Sure thing...

Errors start at timestamp 2025-12-07 18:09:02.050

https://tricorder.pi-hole.net/il4LftA9/

@yubiuser
Copy link
Member

yubiuser commented Dec 8, 2025

I also got the error once, but was unable to re-trigger it.

This PR works nice. It allows queries to be answered while doing the

2025-12-08 08:55:22.020 UTC [24591/T24648] INFO:   10000 queries parsed...
2025-12-08 08:55:22.162 UTC [24591/T24648] INFO:   20000 queries parsed...
2025-12-08 08:55:22.302 UTC [24591/T24648] INFO:   30000 queries parsed...
2025-12-08 08:55:22.436 UTC [24591/T24648] INFO:   40000 queries parsed...
2025-12-08 08:55:22.566 UTC [24591/T24648] INFO:   50000 queries parsed...
2025-12-08 08:55:22.696 UTC [24591/T24648] INFO:   60000 queries parsed...
2025-12-08 08:55:22.832 UTC [24591/T24648] INFO:   70000 queries parsed...

But it's not answering during these steps (might be expected, but is a 8 second pause)

2025-12-08 08:55:13.473 UTC [24591M] INFO: Database version is 21
2025-12-08 08:55:13.475 UTC [24591M] INFO: Database successfully initialized
2025-12-08 08:55:21.377 UTC [24591M] INFO: Imported 119880 queries from the on-disk database (it has 200419 rows)
2025-12-08 08:55:21.763 UTC [24591/T24648] INFO: Parsing queries in database
2025-12-08 08:55:21.764 UTC [24591M] INFO: FTL is running as user pihole (UID 987)

DL6ER added 4 commits December 8, 2025 17:01
@DL6ER
Do not filter on the history windows twice. This can lead to missing …
cfcef20 
…queries in the second run, causing "empty" query slots. They are - themselves - entirely harmless, however, they will cuase "memory error" warnings until they are garbage collected away after a few minutes.

Signed-off-by: Dominik <[email protected]>
@DL6ER
Queries already imported from disk should not be re-exported as these…
6f43665 
… queries cannot receive any further updates. This is a performance optimization mostly relevant for very active (= many queries per second) systems.

Signed-off-by: Dominik <[email protected]>
@DL6ER
Also make the actual importing from disk into memory (happening befor…
07e1e4b 
…e the parsing) taking place asynchronously.

Signed-off-by: Dominik <[email protected]>
@DL6ER
Fix a few possible SQLite3-related memory leaks on user errors and si…
a690bee 
…mplify code by removing unnecessary reset calls

Signed-off-by: Dominik <[email protected]>
@DL6ER
Copy link
Member Author

DL6ER commented Dec 8, 2025

@sawsanders Thank you. This indeed revealed what was going on and also why I have missed to reproduce this. It is fixed now.

Background information The issue was that we selected the time-span we wanted to import from the database *twice*. Once when we read the data from disk and then again when parsing it. During the first round, we computed how many queries we are going to import and store this number. What happened here now is that, during the second round (the parsing), there were already a few queries which are by now too old, i.e., they were not imported. Hence the memory errors, correctly pointing out that there are "empty" queries. This was never a real issue (FTL worked just fine) but we tend to err on the side of caution so getting this fixed is definitely the right thing here.

The correct solution is to filter only once and then parse all of this (already) filtered data in the second step. This is now fixed.

@yubiuser This should be - at least - mitigated (if not entirely fixed) now. Please check if this (mostly) removes this 8 seconds blocker on your setup. Also, how does the initial DNS blocking time now compare on this branch vs. development (or any other recent release)?

Background information We need to know the number of queries we are going to import *before* we can start the DNS resolver. The initial delay you are seeing if from when we copy the data from disk into memory once. We do this here so the data becomes immutable: it ensures that we will process the *exact* number of queries we have imported before. But reading the data from the disk/card is unexpectedly (but not unreasonably) slow.

I wasn't really aware that this is a potential bottleneck, too. My testing doesn't show it as my development Pi-hole is in fact a high-performance x86 micro server. But this does make a lot of sense having slow disks/cards in mind. I changed the code slightly to really do only the minimalist necessities in the (blocking) main worker process (obtain the number of queries we are going to import) and moved the actual reading from disk into the asynchronous database thread as well.

@DL6ER DL6ER force-pushed the tweak/async_import branch from 685ae03 to 4d3bae5 Compare December 8, 2025 18:52
@sawsanders
Copy link

sawsanders commented Dec 8, 2025

Looks good here. No errors and the number of imported queries look proper.

@yubiuser
Copy link
Member

yubiuser commented Dec 8, 2025 •
edited
Loading

On development no queries were answered for the first ~11 seconds during startup (with +/- 0.5 seconds do to the 0.5 sleep I used in my test script). The first query that got answered was sent at 2025-12-08 21:13:37.022, corresponding to those two log lines

2025-12-08 21:13:36.967 UTC [275485M] INFO:   120000 queries parsed...
2025-12-08 21:13:37.043 UTC [275485M] INFO: Imported 124169 queries from the long-term database

On this branch, first query was answered ~8 seconds after startup (2025-12-08 21:19:27.739) corresponding to

2025-12-08 21:19:21.920 UTC [277681/T277717] ERROR: TLS certificate at /etc/pihole/tls.pem is about to expire soon, but it is not a Pi-hole certificate. Please renew it manually!
2025-12-08 21:19:28.200 UTC [277681/T277713] INFO: Imported 124216 queries from the on-disk database (it has 205039 rows)2025-12-08 21:19:21.920 UTC [277681/T277717]

Please check if this (mostly) removes this 8 seconds blocker on your setup.

It does not. From the logs, I can see that after

2025-12-08 21:19:19.413 UTC [277681M] INFO: Database successfully initialized

other stuff is happening now, but there is still the delay before all queries have been imported

2025-12-08 21:19:21.920 UTC [277681/T277717] ERROR: TLS certificate at /etc/pihole/tls.pem is about to expire soon, but it is not a Pi-hole certificate. Please renew it manually!
2025-12-08 21:19:28.200 UTC [277681/T277713] INFO: Imported 124216 queries from the on-disk database (it has 205039 rows)
2025-12-08 21:19:28.201 UTC [277681/T277713] INFO: Parsing queries in database

@DL6ER
Copy link
Member Author

DL6ER commented Dec 9, 2025

If you enable debug.database, when do you see a line like

import_queries_from_disk(): Going to import ... queries from disk database

compared to when queries are answered? Because, almost right after this line, queries should be answered and I was hoping this will happen notably earlier.

Background information We already use a covering index on the `timestamp` column so there isn't much more we can do here to improve things. 
EXPLAIN SELECT COUNT(*) FROM query_storage WHERE timestamp BETWEEN 10 AND 10000;

QUERY PLAN
`--SEARCH query_storage USING COVERING INDEX idx_queries_timestamp (timestamp>? AND timestamp<?)
explained2-blocks

We anyway need a (partial) index scan here but reading (and traversing) the smaller index should be (much) faster than working on the full table. On the other hand, if overall disk latency is the issue here, then I'm not sure if we can do anything.

@yubiuser
Copy link
Member

yubiuser commented Dec 9, 2025

Side note: I see some logspam when the debug flag is enabled

2025-12-09 20:18:01.076 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:02.081 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:02.082 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:03.087 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:03.089 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:04.099 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:04.101 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:05.011 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:05.012 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:06.017 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:06.018 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database
2025-12-09 20:18:07.024 UTC [748587/T748589] DEBUG_DATABASE: Storing queries from ID 88149 to 88148 in in-memory-database
2025-12-09 20:18:07.025 UTC [748587/T748589] DEBUG_DATABASE: Accessing in-memory database

Why is ID from > to?

This is the relevant time frame

2025-12-09 20:19:01.500
;; communications error to 10.0.1.24#53: timed out
2025-12-09 20:19:02.825
142.251.37.14

2025-12-09 20:18:57.050 UTC [749617M] INFO: ########## FTL started on nanopi! ##########
....
2025-12-09 20:18:57.147 UTC [749617M] DEBUG_DATABASE: import_queries_from_disk(): Going to import 88129 queries from disk database
....
2025-12-09 20:18:59.541 UTC [749617/T749623] ERROR: TLS certificate at /etc/pihole/tls.pem is about to expire soon, but it is not a Pi-hole certificate. Please renew it manually!
2025-12-09 20:19:03.190 UTC [749617/T749619] DEBUG_DATABASE: Imported 88129 rows from disk.query_storage

So it's like 6 seconds from the start/import_queries_from_disk today (but only ~88.00 vs 12.400 queries yesterday)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

database performance

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

5 participants

@DL6ER @pralor-bot @sawsanders @yubiuser