Feature: SPARQL observability — query logger, cache hit-rate, query counter (Ship 3) - #195
Merged
Merged
Conversation
…nter Goo-owned observability hung off the single client seam (Client#query/#update), all off/inert by default. - Goo::SPARQL::QueryLogger: records generated SPARQL, execution time, result size (rows + response bytes), cache hit/miss, and user; Redis ZSET ring buffer in a separate goo:qlog:* keyspace; OP_QUERIES_LOGGING / OP_QUERIES_LOGGING_FILE (off by default). Includes a back-compat shim (Goo.logger, get_logs, queries_last_n_seconds, users_query_count, info) for AgroPortal's Admin::LoggingController. - cache_hit_rate: lifetime hit/miss tally, gated to cache-eligible reads. - query counter: Goo.count_sparql_queries + assert_max_sparql_queries / assert_sparql_queries (Goo::TestHelpers, reusable by downstream suites) — a deterministic, env-independent signal for N+1 / query-fan-out regressions. Run totals (store-bound queries + cache hits) printed at end of the test run. - fix the queries_debug timing path (process_query_intl -> process_query_init) and repair Goo::Debug (emit ncbo-sparql-query-count; drop the dead :sparql_queries branch). Re-implemented onto ncbo's minitest-6 base (tests use Goo::TestCase + Minitest::Hooks, rubocop-minitest clean), not merged from the alexskr POC fork.
…OUNTS) Capture each test's store-bound SPARQL query delta (before_setup..after_teardown snapshot of Goo.query_count_total) into Goo::SparqlQueryStats. At end of run print a top-15 outliers list to stderr and write a full name-sorted sparql_query_counts.txt — diff that file between two runs (pre/post an optimization) to see per-test deltas. Off by default; OP_SPARQL_QUERY_COUNTS=1 enables, OP_SPARQL_QUERY_COUNTS_FILE overrides the path. Now feasible in goo's own suite since the ncbo port put it on minitest 6 (Goo::TestCase + Minitest::Hooks); previously this lived only in ontologies_linked_data.
…g cache guard Add TestSafety.ensure_backends_reachable! (called at suite startup, before any test): pings redis and runs a trivial SELECT against the triplestore, aborting fast with a clear message if either is unreachable — instead of erroring mid-suite. (Solr is already checked when config.test loads.) Remove test_cache.rb#before_all's `raise if redis.dbsize > 100` guard: it false-tripped mid-run once earlier suites had legitimately filled the shared redis. Production safety is already enforced by the startup host check (localhost/-ut only) plus the new reachability pre-flight, so before_all just flushes the (confirmed test) redis.
Add Goo::SparqlQueryReporter (a Minitest::AbstractReporter, minitest 5+) that prints each test's store-bound SPARQL query count inline as the test completes — a live per-test view alongside minitest's normal output, rather than only the end-of-run summary. Reads the per-test tally SparqlQueryStats already captures in after_teardown; joins the reporter chain via a minitest plugin hook. Opt-in via OP_SPARQL_QUERY_COUNTS (same flag); zero-query tests are skipped. Now possible since the ncbo port put goo on minitest 6 (reporters are a 5+ feature).
…rop plugin-hook hack) Replace the hand-rolled Minitest plugin-hook registration (plugin_goo_sparql_query_counts_init + Minitest.extensions <<, which pokes at minitest internals) with the documented Minitest::Reporters.use! API. SparqlQueryReporter now subclasses Minitest::Reporters::BaseReporter and is appended to the reporter list when OP_SPARQL_QUERY_COUNTS is set; otherwise just the progress reporter runs. Also gives nicer default output and makes adding MeanTimeReporter (slow-test dashboard) or JUnitReporter (CI test reporting) a one-line change later. Aligns goo with ontologies_api, which already uses minitest-reporters.
Both are required from lib -- activesupport by base/settings/settings.rb (core_ext/object/blank), request_store by base/where.rb -- but only the Gemfile declared them, so consumers resolving goo through the gemspec got them by luck of the transitive graph rather than by contract.
Goo::Debug both armed the per-request counter and emitted the ncbo-sparql-query-count header, but the API mounts it only behind `if Goo.queries_debug?` (app.rb:130), which no environment config sets -- so the counter was dead in a default production deploy. Same defect, same middleware, as the equivalent-predicates cache fixed in 0a0478f. Split the two responsibilities. tick_query_count now also feeds a RequestStore-backed per-request tally, exposed as Goo.request_query_count: RequestStore::Middleware is mounted unconditionally by the API and clears per request, and the RequestStore.active? guard keeps cron and scripts inert. Goo::Debug keeps emitting the header, so publishing per-request fan-out to API callers stays opt-in behind QUERIES_DEBUG while collection is unconditional. The header is omitted rather than emitted empty when no request is in flight. Tests drive the middleware stack in the API's order (Goo::Debug outside RequestStore::Middleware) and close the response body -- RequestStore clears from a Rack::BodyProxy on close, so skipping it leaks the store into the next request.
Each logged query cost ~6 sequential round-trips (SET, ZADD, ZINCRBY, EXPIRE, INCR, ZCARD) on a path that already runs thousands of Redis ops per request (review section 2A). Batch every write plus the trim's ZCARD into a single pipeline; the cache hit/miss tally folds in via record's new cache_stat: argument instead of taking its own round-trip, and trim consumes the cardinality the pipeline already returned. Measured against a live Redis, 500 logged queries: 1.10 ms/query unpipelined -> 0.22 ms/query (5.1x). Trim still costs a ZRANGE plus one pipelined ZREM+DEL, but only when actually over max_logs. with_redis still wraps the lot, so a Redis hiccup degrades to file-only rather than breaking the query.
query_logger.rb claimed that disjoint goo:qlog:* vs sparql:* keys meant "log volume never evicts cache memory". Section 7.2 of the review establishes that is wrong: maxmemory/allkeys-lru is per-INSTANCE and ignores both key prefixes and db numbers, so on a shared Redis the log and the cache evict each other. Separate DBs would not fix it either. Add Goo.add_log_redis_backend + Goo.log_redis_client and point QueryLogger at the latter, falling back to the cache Redis when unconfigured so existing deployments are unchanged. add_redis_backend re-runs set_query_logging to pick up that fallback, without clobbering a dedicated handle. Configurable via OP_QUERIES_LOGGING_REDIS_HOST/_PORT; the startup banner names the log Redis and flags when it is shared. Also parse OP_QUERIES_LOGGING for truthiness instead of taking the raw string: OP_QUERIES_LOGGING=false is a non-empty String and was turning logging ON. Same treatment use_cache already had. Correct the comment to say what is true: disjoint prefixes stop collisions, not cross-eviction.
Records what the observability pass changed and why: - Section 7.4 / section 8 item 4: the query counter was armed in Goo::Debug, which is not a production mount point -- the same lesson as 0a0478f. Arming moved to RequestStore; collection is now unconditional while the ncbo-sparql-query-count header stays behind QUERIES_DEBUG, since a response header is visible to every API caller. - Section 6 / 7.2 / section 8 item 12 (D6a): implemented, and the "disjoint keyspaces => no interference" claim is corrected in the doc and in query_logger.rb. Note the unconfigured fallback is still the cache Redis, so the second instance must be provisioned before enabling logging where the cache is load-bearing. - Section 5: records the one benchmark taken -- query-log write amplification, 1.10 -> 0.22 ms per logged query after pipelining. - New section 7.7: AgroPortal's admin-gated Admin::LoggingController as the precedent for reading the log in production, and the recommended NCBO exposure channel over a public response header.
…_backend Two review findings on Ship 3: * QueryLogger#record calls Time#iso8601 but the file required only json, benchmark, securerandom and logger. It worked solely because a dependency happened to load 'time'; in a bare context it raises NoMethodError. Require it explicitly. * add_sparql_backend called set_sparql_cache (the D5 ordering fix) but not set_query_logging, so a host that enabled logging BEFORE registering its backends kept the inert logger built in Client#initialize and logged nothing while the flag said on. Verified: Goo.query_logger.enabled was false in that order before this change, true after.
Review finding on Ship 3. max_logs defaulted to 1000 while §2A measured a single class-tree request at ~2000 reads, so the one request the log exists to explain (attributing that fan-out, checklist #16/#17) trimmed away its own entries before anyone could read them. Neither max_logs nor ttl was reachable from configuration, so raising it needed a code change. * default max_logs 1000 -> 10_000, comfortably outlasting one tree request. Roughly 15-20 MB of JSON-with-SPARQL-text on the log's own Redis instance (D6a), bounded further by the TTL, and only paid while logging is on -- which is off by default. * both settable via Goo.enable_query_logging(max_logs:, ttl:), config (query_logging_max_logs / query_logging_ttl) and env (OP_QUERIES_LOGGING_MAX_LOGS / OP_QUERIES_LOGGING_TTL); documented in config/config.rb.sample. * test asserts the default outlasts a tree request and that a configured depth is both plumbed through and enforced.
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
2 participants
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 this does
Phase 2 of the sparql-client de-fork. Ship 1 (#194) moved the NCBO customizations into goo; this adds the observability that was deliberately left out of that parity-pure port: a reworked SPARQL query logger, a cache hit-rate, a store-bound query counter, and per-test query-count reporting for the test suite.
Everything here is off by default. Logging is a process-wide env opt-in (
OP_QUERIES_LOGGING), and with it off the logger is areturn yield unless @enabledpassthrough. The query counter is a nil-check per query.What's in it
Goo::SPARQL::QueryLogger(lib/goo/sparql/query_logger.rb) — records the generated SPARQL, timing, row/byte counts, cache-hit flag and user. Redis storage is a ZSET index scored by epoch-microseconds plus JSON entries, giving O(log N) time-window queries and a cheap ring-buffer trim — noKEYSscans, no timestamp-from-key parsing, no Marshal-of-JSON (the rough edges of the fork's logger).Goo.loggerplusget_logs/queries_last_n_seconds/users_query_count, which AgroPortal'sAdmin::LoggingControllercalls. De-forked goo stays a drop-in there.Goo.count_sparql_queries { }plusassert_max_sparql_queries/assert_sparql_queries(lib/goo/test_helpers.rb, opt-in for downstream suites). The count is deterministic for a given code path and fixture, unlike wall time, so it catches N+1 / fan-out regressions identically on a laptop and in CI.OP_SPARQL_QUERY_COUNTS=1prints each test's query count inline via a minitest reporter and writes a name-sortedsparql_query_counts.txtfor diffing two runs.Review findings fixed in this branch
The branch was written against the pre-merge de-fork tip. Rebasing it onto current
developmentsurfaced five defects, two of them proven by post-merge fixes ondevelopment:The per-request counter never armed in production. It lived in
Goo::Debug, which the API mounts only behindif Goo.queries_debug?(app.rb:130) — and no environment config sets that. This is the same defect, in the same middleware, that0a0478ffixed for the equivalent-predicates cache. Arming moved toRequestStore(mounted unconditionally atapp.rb:148, cleared per request, guarded byRequestStore.active?so cron and scripts stay inert).Collection and exposure are now deliberately separate: the count is always collected, while the
ncbo-sparql-query-countresponse header stays behindQUERIES_DEBUG, because a header is visible to every API caller and publishing internal query fan-out by default isn't worth the convenience.D6a was unimplemented and the code claimed the opposite.
query_logger.rbasserted that disjointgoo:qlog:*vssparql:*keys meant "log volume never evicts cache memory". §7.2 of the review establishes that's wrong:maxmemory/allkeys-lruis per-instance and ignores key prefixes and db numbers. AddedGoo.add_log_redis_backend/Goo.log_redis_client, defaulting to the cache Redis so existing deployments are unchanged — but that fallback is only safe while logging is off, and the startup banner says so when the two are shared.~6 unpipelined Redis round-trips per logged query, against a baseline §2A measured at ~2000 Redis ops for a single tree request. Batched into one pipeline (the trim's
ZCARDrides along, so trim costs nothing until actually overmax_logs): 1.10 ms → 0.22 ms per logged query, 500 iterations against a live Redis.OP_QUERIES_LOGGING=falseturned logging ON — the raw env string is truthy. Now parsed for truthiness, matching theuse_cacheline two lines below it.Gemspec under-declared its dependencies.
activesupportandrequest_storeare both required fromlibbut only the Gemfile declared them, so consumers resolving goo through the gemspec got them by luck of the transitive graph.Verification
OP_QUERIES_LOGGINGverified acrossfalse/0/off/no/true/1/yes/empty.mastertips, via an uncommittedpath:override):ontologies_linked_data— 325 runs, 18024 assertions, 0 failures, 0 errorsontologies_api— 302 tests, 12486 assertions, 0 failures, 0 errorsclear.Follow-ups (not in this PR)
ncbo/ontologies_api, extended withcache_hit_rate, is the recommended NCBO channel — 403-by-default rather than public-by-default. Recorded as §7.7 in the review doc.ActiveSupport::Notificationsseam consumed by a New Relic or OpenTelemetry subscriber is the right long-term shape for a library used by five apps (andncbo_cronhas no APM at all today), but it's a separate change from stabilizing what exists.feature/sparql-resilience(Ship 2) is stacked on this branch and adds a breaker for the logger's Redis writes.