Repository navigation
Serve the in-memory query log from shared memory - #3294
Merged
Merged
Conversation
… place Split `api_queries()` into three parts: `parse_queries_request()` reads the request into a `struct qlog_request`, `queries_from_sql()` builds and runs the SQL query from it, and `add_query_item()` builds the JSON object of one query from a `struct qlog_row`. The two structs and `add_query_item()` are declared in the new `src/api/queries.h`, together with the exclusion checks `qlog_domain_excluded()` and `qlog_client_excluded()`. This only moves code. The in-memory and the on-disk path still run the same SQL: the query text, the bound values, the error replies and the JSON are unchanged, the answers to the same requests are identical to those of development. The type, status, reply and DNSSEC filters are now checked before the in-memory database is opened instead of after it, which only matters when it cannot be. It prepares serving the query log from shared memory, which takes the same parameters and has to produce the same JSON. Signed-off-by: 010011110 <duckenheim@posteo.de>
Rows written before the `ede` column was added to `query_storage` have
NULL there. `/api/queries` read them with `sqlite3_column_int()`, which
gives 0, and 0 is a real EDE code ("Other Error"). Since pi-hole#3278, the import
into shared memory treats NULL as no EDE (`query_get_ede()` returns -1 for
them), like a query without one.
Show `"code": -1` for these rows on both query log paths as well, which is
how rows stored without an EDE since that column exists show already. Rows
with a real EDE keep their code, and sorting by `ede` keeps them where
they were: NULL sorts before -1.
This keeps the database path in line with shared memory, from which the
in-memory query log is going to be read.
Signed-off-by: 010011110 <duckenheim@posteo.de>
Contributor
Author
|
the first commit is the differential test from #3291, which is only a tool and not meant to be merged, i will take it out of this PR, the other commits stay as they are |
DL6ER
requested changes
Oct 25, 2026
DL6ER
left a comment
DL6ER
left a comment
Member
There was a problem hiding this comment.
Thanks, this follows the plan from #3275 closely, and the commit split makes it reviewable. Line-specific points are inline, the rest is here.
Tests: taking the #3291 commit out is right, but then 899918d and 11ab417 cannot stay as they are, they extend test/query_log_diff.py/.sh and the hook in test/test_final.bats comes from the commit you drop. More importantly, these are the only tests of the new engine, so without them step 3 has none in the regular suite. Please add a few short tests there instead, covering at least:
- paging through a sort with many equal keys across the middle (the flip), every query exactly once
- a time range (
from/until) - the cursor, including a page with queries arriving meanwhile
- queries at the maximum privacy level being left out, also in
recordsTotal
Questions and answers:
- DNS p99 was measured at 1000 queries/s. How long do query log requests take at several thousand queries/s or with many TCP workers, when
dns_waitingrarely drops to zero? - The behavior changes you list (rows the import skips missing from memory, a memory cursor briefly newer than what
disk=trueaccepts, current client names until 3a) are fine with me. - EDE: yes, keep abb5e7d, rows stored without an EDE show none on both paths.
- The GC wait (about 30 lines): please leave it out, a page that comes back on the next request at 0.007 % is acceptable.
Unrelated to this PR, but it now shows up in the query log in memory: when DB_read_queries() meets an invalid query type, it continues after it already set magic, ID and timestamp of the slot. The half-filled query stays in the array with domain and client 0, and the GC later decrements counters it never incremented. That would be a small separate fix.
The queries array is in ID order, and its timestamps nearly so: a query that a TCP worker creates, or one after the clock was stepped back, can be older than a query before it. `track_query_time()` keeps the newest timestamp in the array, how far the timestamp of a query has fallen behind it at most (`query_time_disorder`) and the ID of the query that fell behind that far, each time a query is created. The import fills its slots while newer queries arrive, so `retrack_query_times()` computes them again once it is done. New queries only ever raise the bound. Once the garbage collector has removed the query that set it, `runGC()` computes it again over the queries left, so it shrinks again after a clock step has left the history. That walks the queries array with the lock held, 7 ms with 2M queries on amd64, at most once per run of the garbage collector. The counters also get `queries_maxprivacy`, the number of queries in memory recorded at the maximum privacy level, kept up when a query is created and when the garbage collector removes one. Nothing reads them yet. The query log from shared memory will use the bound to search time ranges and the count for its totals. The counters change, so `SHARED_MEMORY_VERSION` goes up. Signed-off-by: 010011110 <duckenheim@posteo.de>
Read `/api/queries` without `disk=true` from the queries in shared memory instead of from the in-memory database. `queries_from_shm()` in the new `src/api/queries-shm.c` takes the request as `parse_queries_request()` reads it and builds each row with the same `add_query_item()`, so only the selection of the rows differs. It gives the answers of the SQL query on the in-memory database: the filters work like its WHERE clause, LIKE through SQLite's own `sqlite3_strlike()` with the same escaping, the same exclusion checks and privacy levels, and the order is SQLite's, NULL first and text compared bytewise. Rows with equal sort keys come in ID order in the direction of the sort, which the ORDER BY leaves open. The scan takes the SHM lock per 256 rows. The domain, client and upstream parts of the filters are evaluated once per ID of a request. The default order (newest first), and the time order while no timestamp is out of it, are read straight off the array. Every other order keeps the first start + length rows in a heap, sorted without the lock; in time order and without a filter, the scan stops a little past the last of them. Between two chunks, queries may arrive, the garbage collector may remove the oldest ones and the array may move, so positions are absolute (index plus the queries removed so far) and no pointer into shared memory is kept across an unlock. A row of the heap is read again by its position and only taken if the query there still has its ID, so a query removed meanwhile is missing from the page, never replaced by another one. Strings are copied once per request, into blocks of their own. Between two chunks, the heap, the string table and these blocks get the room for the next chunk, so none of the scan's memory is allocated with the lock held, and a chunk ends early when the newest block cannot take the strings of one more row. One scan runs at a time, so a slow request, a deep page of a sort over millions of queries, makes the query log of every other client wait. Allocation failures answer 500 and release the lock and the gate. Time ranges rely on the bound of the previous commit for how far the timestamp of a query may fall behind one before it in the array. Until the import is done, the query log is still read from the in-memory database. What changes for the in-memory query log: - Queries show up as soon as they are created, the in-memory database got them up to a second later. - Without a cursor, the reply's cursor is the newest query when the request arrived, null before the first query (the in-memory database gave -1), and a cursor up to the newest query is valid. With `disk=true`, a cursor is still checked against the in-memory database, which has the queries up to a second later. - The list ID of a query that is not stored yet is the one of its DNS cache entry, which the next export stores. - Rows the import does not take into shared memory are missing from it and from `recordsTotal`: localhost queries while `dns.ignoreLocalhost` is on, and the rows it rejects. With a database that cannot be read, the in-memory query log is no longer empty. - Client names are the current names of the clients, while the database has the one each query was stored with, and shared memory has none after the import until the resolver has looked the clients up again. `test_final.bats` starts FTL on a new database and checks that the cursor is null, and imports queries with domains long enough that a chunk has to end early for a new string block. Signed-off-by: 010011110 <duckenheim@posteo.de>
The query log takes the SHM lock once per chunk of rows, thousands of times for one request on a busy system. A DNS query that needs the lock during such a scan waits behind each chunk, and these waits add up. DNS-path callers of `_lock_shm()`, the main threads of FTL and of its forked TCP workers (TID == PID), now count themselves in `dns_waiting` next to the lock while they wait for it. `_lock_shm_reader()`, which the query log takes for its chunks, checks that count first and sleeps on it (FUTEX_WAIT) while a DNS-path caller waits, at most 1 ms per round and ten rounds. The last waiting DNS-path caller wakes the sleeping readers once it has the lock (FUTEX_WAKE). Everything else takes the lock as before. A DNS-path caller that dies while it is counted would leave the count up for good, and every chunk of every scan after it would sleep its ten rounds. That is not only a killed TCP worker: dnsmasq ends a TCP worker that still runs after `CHILD_LIFETIME` (300 s) with SIGALRM, whose handler calls `_exit()`, also while the worker waits for the lock. So when all ten rounds time out while nobody holds the lock, the count is reset to zero. One such round is not enough: the waiter it counted may have been woken by the last unlock without having run yet, and once reset away it loses the lock to the reader at every chunk. Under load that kept a DNS-path caller waiting up to 256 ms in 82 of 323727 requests. Ten rounds in a row also catch waiters that have not run for ten milliseconds on a busy CPU, and the decrement in `_lock_shm()` stops at zero, so a waiter that was reset away cannot push the count below. A count that is stuck is still repaired, the first request after it takes 10 ms longer. On a lock that is held nearly all the time, a dead waiter keeps the readers sleeping for longer, until ten such rounds come in a row. The reader only reads, so `_lock_shm()` leaves growing the shared memory arrays to the callers that add entries, which also keeps a long scan from doing that work under its many short holds. The timeout is passed to SYS_futex as two longs. On 32-bit musl (i386, armv6, armv7) `struct timespec` has a 64-bit `tv_sec`, while SYS_futex is the syscall with 32-bit time, which would read a zero timeout. `ShmLock` gets the two counters. Its layout change is covered by the `SHARED_MEMORY_VERSION` bump that came with the query time bound. Signed-off-by: 010011110 <duckenheim@posteo.de>
A page of a sorted query log needs a heap of start + length rows, so a deep page keeps nearly all matching queries in it: the last page of a sort over all queries keeps all of them. With the query ID as the last key the order is total, and the result read backwards is the result of the opposite order. A page in the back half is therefore the mirrored page of the opposite order, read backwards, which needs a heap of only N - start rows, N being the number of matching queries. A sorted request whose heap would hold more than 10,000 rows needs N first. Without a filter, and while no query of the maximum privacy level is in memory, N is every query up to the cursor; otherwise a pass without a heap counts the matching queries. The request then takes the smaller heap of the two orders, and a page past the end is answered from N. The array is read in the direction of the order taken, so rows with equal keys do not push each other out of the heap. The middle of a sorted result stays its most expensive page. Signed-off-by: 010011110 <duckenheim@posteo.de>
A deep page of a sorted result keeps a large heap, and each row of its scan goes through it. With 256 rows per hold of the SHM lock, a hold then takes long enough that the DNS queries waiting behind it queue up: one client paging through the middle of a sort by domain with 2M queries in memory pushed the DNS p99 to 63 ms. 64 rows keep it below 1 ms with 100k, 500k and 2M queries, for a little more time on full scans (the first page of the status sort takes 23 instead of 20 ms with 2M queries). At higher rates that is not enough. A DNS query takes the lock about ten times and waits for a chunk each time, so from 3000 queries/s on the DNS thread falls behind during a deep page: with 2M queries, p99 57 ms and 9 % lost at 6000 queries/s, 65 ms and 24 % lost at 10000/s. Once the heap holds 4096 rows, a chunk therefore has 8 rows, which keeps the p99 at 0.21 and 0.56 ms with nothing lost, at the same request time. A chunk also ends after each evaluation of the domain or the client part of the filters that runs exclusion regexes, as one evaluation runs all of them. With 20 domain regexes and 2M queries, every request that filters ran them for each of the 150k domains under the lock, up to 60 per hold: DNS p99 15 to 28 ms at 1000 queries/s, 120 to 183 ms with 19 to 35 % lost at 6000/s. One evaluation per hold brings it to 0.5 to 0.65 ms with nothing lost at 6000/s, and the requests are not slower, as the per-ID cache makes evaluations rare. An evaluation without regexes takes under 0.1 us and ends no chunk. The sizes measured, from 16 to 1024 rows, and the deep page at 6000 and 10000 queries/s go next to the constants. Signed-off-by: 010011110 <duckenheim@posteo.de>
The query log in memory breaks ties between equal sort keys by query ID in the direction of the sort, reads a page in the back half of a sorted result from the other end once the page ends more than 10000 rows in, and takes the newest query as the cursor of a request without one. `test_queries_sorted_pages` sorts the queries of the suite by status, type and reply type, in both directions, with and without a client filter. Equal keys have to be next to each other and in ID order, one direction has to be the other one backwards, pages of 7 rows have to hold every query once, and pages of 10000 rows from a few starts, which are read from the other end, the rest of the result. A filtered request counts all of its rows in `recordsFiltered`, also on a page past the end. `test_queries_time_range` checks that `from` is inclusive and `until` exclusive, in the default order and sorted by time. A time printed with 15 digits can be a ULP off the stored one, so the range starts and ends at times printed with 17. The test config excludes a client from the query log, which makes every request count its matches. Both tests run without `webserver.api.excludeClients`, so a request without a filter takes the number of queries from shared memory. Clearing and restoring it are two more writes of pihole.toml. `test_cursor_with_queries_arriving` takes a page, sends two DNS queries and expects the next page with the same cursor to continue the first one without them. A request without a cursor shows them first, with the newest query as cursor and `recordsTotal` counting them. It sends DNS queries, so it has a `test_m_*` file of its own that runs after the exact counts of `test_api.py`. At `misc.privacylevel` 3 the query log is empty. Raising the level does not restart FTL, lowering it does, so this test is in `test_final.bats`, where FTL gets level 0 back from the CLI once it has stopped. Signed-off-by: 010011110 <duckenheim@posteo.de>
010011110
force-pushed
the
query-log-from-shm
branch
from
October 25, 2026 14:19
adbf81a to
34044ed
Compare
5 tasks done
Contributor
Author
|
thanks, all points are in, each in the commit it belongs to, and every commit still builds on its own. the ede commit stays, and runGC() does not wait for a scan, the body lists that race as accepted tests: the last commit has the four you asked for, paging through sorts with many equal keys across the flip with every query exactly once, a time range, the cursor while queries arrive, and the empty query log at privacy level 3. for the last one: a query takes the privacy level in force when it is made, and every way of lowering the level restarts FTL, so a test cannot get the engine to meet a level 3 query while a lower level is in force, only the empty log at level 3 can be checked, which was so before as well. the null cursor of an empty history has its own test in test_final.bats load, measured as before with 2M queries in memory and FTL pinned to its own cores, with up to 10000 UDP queries/s or 20 and 50 TCP clients on top:
the half-filled slot of DB_read_queries(): that continue cannot be reached on development, the two type checks agree since 4c98b5d and only disagreed from late January to early February 2025, before v6.0. i have a small cleanup that moves every skip in front of the slot, if you want it as a PR |
DL6ER
reviewed
Oct 25, 2026
DL6ER
left a comment
DL6ER
left a comment
Member
There was a problem hiding this comment.
Thanks, all points are in, and the load measurements were well worth it. The 8-row chunk for a large heap and ending a chunk after each evaluation that runs exclusion regexes are fine with me, the numbers speak for themselves.
CI passed only in the third attempt on riscv64, two small things in the tests are left, see inline. With those, this is ready from my side.
DB_read_queries(): you are right, the earlier check has rejected every such type since 4c98b5d, so that continue cannot be reached. A small PR moving the skips in front of the slot is welcome, it removes the dead branch.
The two new query log tests that restart FTL asked the API as soon as the import from the database had been logged, while the web server could still be starting and the reply was empty. They wait for its ports before they ask now. Two earlier tests only waited for the import as well, the ones of query IDs across a restart and of type 100 imports, and get the same wait. Drop the test of the empty query log at `misc.privacylevel` 3. At that level `api_queries()` returns before either path, as on development, so it checked nothing new and cost a restart of FTL. Signed-off-by: 010011110 <duckenheim@posteo.de>
Contributor
Author
|
thanks, with that commit all three are in. 3a, the client name history, is ready and goes out once this is merged, and step 4 is almost done, it follows your answers on #3275 |
5 tasks done
DL6ER
approved these changes
Oct 25, 2026
DL6ER
left a comment
DL6ER
left a comment
Member
There was a problem hiding this comment.
Thanks, that settles it from my side. Looking forward to 3a.
5 tasks done
5 tasks done
5 tasks done
010011110
added a commit
to 010011110/FTL
that referenced
this pull request
Oct 26, 2026
The test waited two seconds, as queries moved into the in-memory database once per second. Since pi-hole#3294 the query log reads them from shared memory, so a wait is only needed for the reply to the second query: dnsmasq answers that client first and only then runs the FTL hook and logs "reply query is duplicate". `_log_query()` calls `FTL_hook()` before it writes the line, so once the line is in pihole.log the hook has run as well. The test now polls pihole.log for that line, up to five seconds, with `pihole-FTL wait-for` from the size of the log before the queries. Signed-off-by: 010011110 <duckenheim@posteo.de>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What does this implement/fix?
step 3 of the plan in #3275: /api/queries without disk=true is answered from the queries in shared memory, the in-memory database stays until step 4. disk=true keeps its SQL on pihole-FTL.db. the eight commits are meant to be reviewed one by one. the result was checked against the SQL path with the comparison tool in #3291, which is a tool and not meant to be merged. without comments and blank lines the code adds 1408 lines and removes 571, the tests add 205
measured as in #3275, FTL's own time (took), median of 10 warm runs, synthetic data with 2M queries in memory and 3M more on disk, amd64 (FTL pinned to its own cores), development -> this branch: domain search 857 -> 34 ms, the whole window sorted by domain 2017 -> 36 ms, blocked only 464 -> 16 ms, the first page the web interface opens with 0.1 ms on both. the last page sorted by domain 2721 -> 38 ms, the middle one 2646 -> 1007 ms, the worst case, it takes 37 MiB (the SQL sort 16 MiB). the first pages of unfiltered sorts by status, type, reply type, reply time or dnssec take 23 to 32 ms instead of 0.1 ms, as discussed in #3275. with 100k queries in memory the middle page is 92 -> 30 ms and those first pages 1.1 to 1.6 ms. DNS p99 while one client pages through the middle of the sort by domain with 2M queries: 0.16 -> 0.25 ms at 1000 queries/s, and 0.21 / 0.56 ms at 6000 / 10000 queries/s, nothing lost, where 64-row holds alone had 57 / 65 ms with 9 / 24 % lost. with 20 exclusion regexes at 6000 queries/s DNS stays at p99 0.5 to 0.65 ms with nothing lost, 120 to 183 ms with 19 to 35 % lost without the rule for them
what changes for the query log in memory: queries show up as soon as they are created, and a request without cursor gets the newest query at its arrival as cursor. for about a second, such a cursor can be newer than what disk=true accepts, which checks it against the in-memory database. a query still in flight can show newer values than it was sorted by. rows the import does not put into shared memory are missing from it and from its recordsTotal, disk=true still has them: localhost queries while dns.ignoreLocalhost is on and broken rows. with a database that cannot be read, the query log in memory is no longer empty. client names are the current ones until the name history (3a) follows, the import brings none, so imported queries get theirs once the resolver has looked their clients up again
a GC run during a request can take rows of its page away before they are read, for an ascending sort with many equal keys that can be the whole first page, the next request shows it again. the chance is about the request time over the 10 minute GC interval, 0.007 % for 40 ms at 2M queries. a plain wait for the scan in runGC() hangs FTL at shutdown when the GC thread is cancelled while it waits, a wait of at most a second with cancellation disabled works and is about 30 lines, it is left out and the race accepted
rows stored before the ede column existed have NULL there, which the disk path showed as code 0 ("Other Error") and shared memory as none since #3278. the ede commit above (2.) lets the disk path show none for them too
rows of type 100 (qtype 0) are imported into shared memory since #3292, so they stay in the query log in memory. #3244 changes the two compile_filter_regex() calls that move into parse_queries_request() here. #3224 and #3016 also raise SHARED_MEMORY_VERSION and change countersStruct, whichever lands later takes the next number. #3016 keeps the localhost queries it hides in shared memory, merged with this the engine has to leave them out as well, in query_matches(), recordsTotal and the count of the flip. the two pihole.toml writes of the new tests raise the config rotation count in test_final.bats, which #2943, #3017, #3020, #3069, #3169, #3198 and #3199 raise as well, the counts add up. #3016 raises it from 53 to 55 too, git merges that without a conflict, so whichever lands later has to add its two by hand. the other open PRs merge with this as they do with development
How to test the change during review
the query log of the web interface with filters, sorting and paging, and the /api/queries tests of the API suite
Additional information
Related issue or feature (if applicable): #3275
Pull request in docs with documentation (if applicable): N/A
By submitting this pull request, I confirm the following:
git rebase)src/dnsmasq/. That tree is a verbatim copy of upstream dnsmasq and we do not carry anything in it that deviates from upstream. Fixes have to go through thednsmasq-discussmailing list first, we merge them once they are in dnsmasq master.Checklist:
developmentbranch.