[sarkaramrit1993]

SOLR-11994

Description

First step of SOLR-18571 (Query Insights). Adds a node-level hook notified once per client search, on the node that coordinated it, so a module can track slow queries without parsing logs. Nothing changes unless a listener is registered.

Solution

• SearchRequestListener, registered through CoreContainer.addSearchRequestListener.
• capture runs on the request thread once the header has its QTime, and returns what the listener needs, or null to skip. onRequestEnd runs later on one daemon thread per node, so slow listener work doesn't add to latency or QTime.
• SearchRequestInfo holds scalars only. qTimeMs equals the header QTime.
• Bounded queue (solr.search.listener.queue.size, default 1000). When it's full the search is dropped, never blocked, and counted in solr.search.listener.lost.
• Not reported: shard sub-requests, /get, /export, ping, warming, [subquery].

Tests

SearchRequestListenerTest (2-shard cluster) and SearchRequestDispatcherTest (full queue, non-blocking offer, listener errors and interrupts, shutdown).

[sarkaramrit1993]

On a shards.tolerant partial failure, main counts shard cpuTime twice, so the listener sees that too. That's fixed separately in #5239 (SOLR-18591), and this PR picks up the right number once it merges, with no change needed here.

[nick-boss-tech]

Hi Amrit,

🤖 AI text below 🤖 (reviewed by Nick Shanin)

I found one remaining case where a successful client search produces no listener event: a v2-only handler, or an embedded /select request resolved through the named/default handler fallback. The new guard looks up the path in the v1 handler registry, which can lack the handler that actually served the request.

I added three regression tests and a fix that preserves the originally selected handler at dispatch, including through delegation. This keeps ping, pathless internal searches, shard requests and nested subqueries excluded. The follow-up diff is one commit on your current head.

At ede5646e2b2, all 20 listener tests (including testCpuTime) and 18 neighboring tests passed on Linux, with no failures, errors or skips. Tidy was clean, and check -x test passed in a clean full clone with NODE_ENV unset. On your original production code, all three new tests complete the search successfully and then fail on the callback count: expected 1, actual 0.

To take the tested changes as a fast-forward:

git switch solr-11994-hook
git fetch https://github.com/nick-boss-tech/solr.git solr-11994-pr5238-submit
git merge --ff-only ede5646e2b2281bf4fc1483c2867f0f047088527

[sarkaramrit1993]

Thanks @nick-boss-tech, the v2-only and embedded qt fallback cases are real. Pushed a fix in 1f8dc73.

I fixed it a bit differently. Instead of setting the handler in SolrCore.execute and ApiBag, RequestHandlerBase.handleRequest records the first handler that runs for a request, and the guard checks that. Every dispatch route ends up there, so it covers v1, v2, embedded and delegation in one place, without a new context contract on SolrRequestHandler or a change to SolrCore. Ping and other same-request delegation stay excluded because the outer handler is recorded first.

It also covers a case the path lookup missed: a package update swapping the handler instance while a search is still running.

I wrote two smaller regression tests (v2-only handler, embedded qt fallback) on a minimal configset. Both fail on the old guard with expected:<1> but was:<0> and pass now.

[nick-boss-tech]

Thanks, it looks good now.

[epugh]

Have you seen my UBI draft pr that also wants to see search query and its results? Could it hook in here?

[sarkaramrit1993]

Partly, I think. The recording side of UBIComponent in #2452 (the query plus the doc ids it returned, written through the logging stream) could sit on this listener, since it gets rb and rsp once per client search on the coordinator, after every stage, so the merged results are already there. The ubi=true switch, the per-handler setup and the ubi section with query_id belong in a SearchComponent, because the listener is node-wide and isn't configured per handler. Happy to try moving the recording side onto it once this lands, so neither PR waits on the other.

[epugh]

cool... yeah, at the time i did UBIComponent i was still learning (heck, still am!) how to do solr components, and a big thing I never quite grokked was how to make sure the storing of data doesn't impact the querying side of htings. I suspect that is osmething you are solving here!

[sarkaramrit1993]

Not yet. The listener runs on the request thread today, so storing data from it would still slow the query. I'm moving listeners onto a bounded background queue so recording can't hold up a search, details in the PR comment above.

[epugh]

How could a slow ingest be modeled?

[epugh]

Like don't we want our architecture/approach cover both?

[sarkaramrit1993]

I kept this one search-only on purpose. Ingest already has a per-request hook: the update processor chain. LogUpdateProcessorFactory uses it to log updates over slowUpdateThresholdMillis, the same way SolrCore does for slowQueryThresholdMillis, and anyone can add their own processor to a chain today. Search has no equivalent point that sees the whole request once it's done, which is the gap this fills. The fields here (hits, shards, partial results) are search-specific too. If we want a node-wide hook for updates later, it'd be a sibling with its own fields, and I can file a JIRA for it.

[epugh]

makes sense... I am hoping that in th efuture... We have a way to balance query and index workloads intelligently... So you can maiximise what you get out of a node....

[epugh]

Do you need custom solrcongrig?!!

[sarkaramrit1993]

Good call, dropped both in aa03c95. The dispatch collection now uses cloud-minimal, and the test reshapes it with one Config API call: /select re-registered for v2 only (so EmbeddedSolrServer finds no v1 /select and falls back to the default handler), plus /v2-search as a v2-only handler. Both tests still fail on the old guard with expected:<1> but was:<0>. I also renamed the embedded test to testEmbeddedDefaultHandlerReported, since SolrJ strips qt and that's the path it actually takes.

[epugh]

Do we not have a existing helper?

[sarkaramrit1993]

query() now uses SolrClient#query (aa03c95). I kept nodeClient() on purpose: it pins requests to node 0 so the tests can assert which node coordinated. cluster.getSolrClient() would land on a random node.

[epugh]

cool

[nick-boss-tech]

🤖 AI text below 🤖 (reviewed by Nick Shanin)

Amrit, I exercised the preparation/recording split you described with a test-only example. A component prepares the query identity and response metadata; a listener copies query/result data for a recording destination. The only added file is SearchRequestListenerUbiTest.java; the production hook is unchanged.

The nine integration tests cover local and distributed result IDs matching the response, generated and supplied query IDs, one coordinator recording, disabled and unconfigured handlers, destination exceptions, failed/partial searches, and a copied payload used after the embedded request closes. The result tests use ordinary searches with fl=id.

At c2c387064a83def34cece4163eccded28318caeb, all nine tests passed on Linux under both seeds 5238AB1 and 5238AB2. All 19 existing listener tests and 18 neighboring tests also passed, with no failures, errors or skips. Tidy was clean, and root check -x test passed with NODE_ENV unset.

On Eric's storage concern: the callback still runs synchronously on the request thread, so a slow destination can delay a query. These tests establish exception isolation and the copied-payload contract. PR 2452 integration, persistent sinks, core reload/unload, asynchronous lifetime, redaction and production overhead remain follow-up work.

If useful, you can take the tested example as a fast-forward from your current head:

git switch solr-11994-hook
git fetch https://github.com/nick-boss-tech/solr.git solr-11994-pr5238-ubi-submit
git merge --ff-only c2c387064a83def34cece4163eccded28318caeb

[sarkaramrit1993]

Heads-up on a change of approach here.

Right now onRequestEnd runs on the request thread before the response is written, so anything a listener does adds to the client's latency and to QTime. That's fine for an in-memory top-N but not for a listener that writes to a store, which is the UBI case. I'm fixing that in the hook rather than leaving it to every listener.

What's changing:

• Off the request thread. Listeners run on a small worker fed by a bounded queue, like AuditLoggerPlugin's async mode. A full queue drops the event and counts it in a metric, so a search never waits on a listener's work.
• Detached snapshot. SearchRequestInfo drops req, rsp and rb, since they're closed by the time a listener runs. It carries plain values, and a listener can copy anything extra on the request thread through a cheap capture step.
• Reported time is QTime. The hand-off moves to SolrCore.postDecorateResponse, after QTime is computed, so listeners get the exact header value.
• Listener errors stay off the request. They're logged on the worker and never fail a search. Listener errors stay off the request. Anything onRequestEnd throws, other than a VirtualMachineError, is logged on the worker. capture runs on the request thread: an Exception there is logged and skips that listener, an Error fails the request.

Things I'm working through as part of it:

• Dropping under load keeps searches safe, but Query Insights can miss queries while a node is overloaded. The lost count is exposed as a metric and the queue size is configurable.
• UBI doc ids need the open searcher in local mode, so they stay in a SearchComponent, as User Behavior Insights implementation for Apache Solr #2452 does today.
• One worker serves all listeners for now. It can be split per listener if a second real listener needs it.
• The snapshot copies params on every search when a listener is registered. I'll cap the size and post p50/p99 numbers with and without a listener. The snapshot no longer copies params. A listener that needs them copies them in capture. Numbers are in the comment below.

I'll push this as new commits here, and I'm moving the PR back to draft until then.

[sarkaramrit1993]

Batching is in 92a4aa0. The listener thread now drains the queue in batches (take + drainTo, then a 1 ms pause) instead of waking once per search.

JMH SampleTime, single node, 4 threads, q=id:0, 3 forks, about 2.5M searches per fork (µs):

	no listener mean	no listener p50	no-op listener mean	no-op listener p50
before batching	75.5	70.7	79.1	75.8
after batching	73.4	70.1	74.7	70.5

Before batching, a no-op listener added about 5 µs at p50. After batching, the gap is smaller than the fork-to-fork noise on this laptop (a few µs between forks of the same config), so there's no measurable overhead. These are closed-loop runs, so I'm not reading anything into p99.