Skip to content

feat(q): log every request in the core's query log - #12

Merged
protocolstardust merged 1 commit into
RayforceDB:masterfrom
ihrfv:feat/q-server-querylog
Sep 25, 2026
Merged

protocolstardust merged 1 commit into
RayforceDB:masterfrom
ihrfv:feat/q-server-querylog

Conversation

@ihrfv

@ihrfv ihrfv commented Sep 24, 2026

Copy link
Copy Markdown
Contributor

How it looks from the user's side

With the core's query log on, a request that arrives over the q wire now leaves a row in .sys.querylog, as a native IPC request already does:

(.q.send h "(.sys.querylog.enable 1)")
(.q.send h "(+ 1 2)")
(.q.send h "(+ 1 2")                      ; a parse error
(.q.send h "(count (.sys.querylog))")

Before -- the q wire server never writes to the log, so the ring stays empty (test/rfl/server/querylog.rfl against a server built from master):

querylog.rfl:18: expected "2", got "0"  -- src: (.q.send h "(count (.sys.querylog))")
querylog.rfl:19: expected ""(+ 1 2)"", got """"  -- src: (.q.send h "(at (get (.sys.querylog) 'query) 0)")
querylog.rfl:30: expected "true", got "false"  -- src: (.q.send h "(like (last (get (.sys.querylog) 'query)) \"(upd ...) * B\")")
querylog.rfl FAIL (14 assertions)

After -- one row per evaluated request, with its duration (decode included), status and source:

querylog.rfl ok (14 assertions)

Why

The q wire server evaluates every request on the poll thread, beside everything else the runtime does. When a query waited seconds, nothing said which request held the thread: the native IPC server records one row per query in .sys.querylog, and the q wire server recorded none. A publisher's pushes ((upd; table)`) are exactly the requests a query queues behind.

What changed

  • q_read_body brackets decode and evaluation with the core's ray_qlog_begin / ray_qlog_end, so each request is one row once .sys.querylog.enable is on. With the log off, ray_qlog_begin is one relaxed load and the source is never formatted.
  • A string request is logged verbatim, cut at RAY_QLOG_QUERY_MAX (256 bytes). A list request, the shape a publisher pushes, is logged as its head and the frame's size, (upd ...) 132 B: formatting a pushed table back to source would cost more than evaluating it.
  • A RESPONSE frame is data for a parked q_conn_send, not a query, and is not logged.
  • test/rfl/server/querylog.rfl covers a sum, a parse error, the duration and a list request. q_server.h and docs/CHANGELOG.md (Unreleased, Added) describe the same behaviour.

Overlap with open PRs

Merges cleanly with #10. Conflicts with #8 on one line: both add an #include right after core/sock.h (core/timer.h there, core/qlog.h here), and keeping both resolves it.

Tests

git diff --check origin/master...feat/q-server-querylog
CC=clang make test
    # core master at 4eb3b10: codec and exchange selftests ok,
    # 3 server files passed (querylog.rfl 14 assertions);
    # real-q legs skipped, no q binary, as in CI
# before/after above: test/driver built from origin/master and from this
# branch, each serving test/rfl/server/querylog.rfl

- the q wire server evaluated a request without a trace of what it
  cost the poll thread, while the native IPC server records one row
  per query in `.sys.querylog`; a query queued behind a push had no
  number to blame
- bracket decode and evaluation with the core's ray_qlog_begin/end, so
  a request lands as a row with duration and status once the log is on
- a list request, the shape a publisher pushes, is logged as its head
  and the frame's size; formatting a pushed table back to source would
  cost more than the push
@protocolstardust
protocolstardust merged commit f5cf1b5 into RayforceDB:master Sep 25, 2026
@protocolstardust

Copy link
Copy Markdown
Collaborator

Reviewed and merged (f5cf1b5). Thanks, this is a real gap: the q wire was the only entry point that left no trace in .sys.querylog.

No CI ran on this PR (first-contribution gate), so it was run locally instead: core master 31f45a7, querylog.rfl 14 assertions, full suite green with #7, #8, #10 and #11 merged first, and the full rayforce binary built with the glue.

Review

  • ray_qlog_begin / ray_qlog_end bracket decode + eval, so the row's duration is what the poll thread actually paid. RESPONSE frames stay out. With the log off, begin is one relaxed load and the source is never formatted.
  • q_log_source for a list request: head symbol + frame size is the right trade; formatting a pushed table back to source would cost more than the push.
  • After the merge with fix(q): validate handles and wire protocol frames #10 there is now an early return (unknown message type → deregister) between begin and end. ray_qlog_begin only touches the stack context, so nothing leaks today; if ray_query_measure_begin ever acquires global state, that path needs an end too.
  • Cosmetic: a string request is cut at 256 bytes, which can split a multi-byte UTF-8 sequence. Same as the native IPC's rows, so fine for now.

The #include conflict with #8 was resolved by keeping both lines, as the description predicted.

protocolstardust added a commit that referenced this pull request Sep 25, 2026
This reverts commit f5cf1b5, reversing
changes made to 4322f53.
@protocolstardust

Copy link
Copy Markdown
Collaborator

Reverted on master in 92e0d91 (git revert -m 1 f5cf1b5): maintainer decision, the q wire server should not write into the core's query log for now. The change itself was reviewed as sound (see above); nothing in the revert reflects on the code. The suite is green after the revert.

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

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants