[JSv4]

The bug

Python evaluates a logging call's arguments before it checks whether the
level is enabled. Every diagnostic of this shape in core_vector_stores.py

_logger.debug(await _safe_queryset_info(queryset, "After vector search"))

therefore runs _safe_queryset_info — a COUNT(*) over the annotation table —
on every search and then discards the string. Four of the sites were
_logger.info, so they ran the count and emitted it in production.

Measurement

On a 4,679-section authority deployment (18-corpus CorpusGroup, warm caches,
no reranker configured), timing one member-corpus search by phase:

phase	before
_agenerate_query_embedding	0.291s
_build_base_queryset	12.887s — three COUNT(*)
search_by_embedding	2.222s
async_search (whole)	16.548s

78% of a search was diagnostics. The single most expensive one is
unfiltered — it counts the entire table:

Initial: Total annotations in DB: 4591881 results

…once per search, to log a number that changes only when someone uploads a
document.

After

	before	after
one corpus search (warm)	16.548s	2.579s
18-corpus search_across_corpora	277.4s	45.3s

6.1× on the fan-out, and it applies to every corpus search in the product.

The change

Guards every _safe_queryset_info call site and every queryset.query
stringification (compiling the SQL is not free either) behind
_diagnostics_enabled(), and demotes the four INFO sites to DEBUG. When
DEBUG logging is on, behaviour is unchanged.

I grepped for every other value reaching the same primitive rather than fixing
only the ones the profile named — that turned up the queryset.query f-string
at the metadata-filter site, which the first pass missed.

Verification

test/verify_diag_guard.py (in the ITAR workspace, not this repo) asserts the
two things that would catch a guard swallowing real work:

corpus 127, 8 hits
  diagnostics ON :   6 guarded lines emitted
  diagnostics OFF:   0 guarded lines emitted
OK — identical results (8 hits), diagnostics deferred not deleted

i.e. the diagnostics still emit at DEBUG (deferred, not deleted), and the
returned annotation ids and scores are identical with the logger at DEBUG
and at INFO.

The repo suite was not run: under local.yml pytest dies at
django.setup() on a duplicate storages app label, before any of this module
is imported, and standing up the test.yml stack risks the compose
project-name collision while a long measurement was in flight. Worth a CI run.

Not included

While measuring this I also found that the asyncio.gather in
search_across_corpora is not concurrent — 45.3s gathered vs 48.8s
sequential, a 1.08× speedup, because the paths below it await
sync_to_async(..., thread_sensitive=True). A fix for that was attempted,
preserved results on all 18 corpora, delivered only 2.26× rather than the
predicted 18×, and then failed on all 18 when the same wrapper was awaited
sequentially after a gather (AsyncToSync finding a running loop in a worker
thread). It was reverted rather than shipped and is not part of this PR.

🤖 Generated with Claude Code

[claude]

Review: perf(vector-stores): stop paying for debug diagnostics that are discarded

Nice catch, and a well-documented one — the measurement methodology (before/after phase timings, the 6.1x fan-out number) makes the fix easy to trust. A few notes.

Correctness - looks solid

• Re-grepped every _safe_queryset_info / _safe_queryset_info_sync / queryset.query site in core_vector_stores.py after the patch; all are now guarded by _diagnostics_enabled(), including the _apply_metadata_filters site that the PR description says was found on a second pass. Good.
• Confirmed _logger.isEnabledFor(logging.DEBUG) will actually be False in both base.py/production.py logging configs (root level is INFO, no per-module override for this logger), so the guard is live in production today, not just in theory.
• The _logger.info left in place for 'No document/corpus scope filters applied...' and the len(annotations)/len(vector_results) info logs elsewhere are static strings or operate on already-materialized lists - correctly left unguarded, no hidden extra query cost there.

Missing: changelog fragment
Per CLAUDE.md's Changelog Maintenance section, production perf fixes like this should get a fragment under changelog.d/ (e.g. changelog.d/2261.fixed.md). This PR only touches core_vector_stores.py - worth adding one given the magnitude of the fix (6x on fan-out searches) so it lands in the next CHANGELOG.md collation.

Test coverage gap
The PR body is upfront that the repo test suite wasn't run (blocked by an unrelated django.setup() duplicate storages app-label issue) and that verification instead happened via an out-of-repo script not included in this PR. That means there's currently no regression test in this repo that would catch someone reintroducing an unguarded _safe_queryset_info/queryset.query call at a new site in the future - which is exactly the class of bug this PR fixes.

Suggest adding a small test (e.g. in opencontractserver/tests/) that:

• Sets the logger level to INFO, patches/spies on the queryset's count method, and asserts .count() is not invoked during _build_base_queryset / _run_vector_only_sync / _async_vector_only.
• Optionally the inverse at DEBUG level, asserting the diagnostic string is still produced (guards against 'guarded -> silently deleted' regressions, matching the intent of the out-of-repo verify script).

This doesn't need a full integration test with real embeddings - mocking/spying on .count and the query-building path should be enough to pin the behavior.

Minor / non-blocking

• _diagnostics_enabled()'s docstring is quite long and embeds specific benchmark figures (4,679-section deployment, 12.9s/16.5s, etc.) that mirror the PR description almost verbatim. Per this repo's comment guidance, consider trimming to the durable WHY (Python eagerly evaluates logging call arguments, so unguarded .count()/queryset.query calls run even when the level is disabled) and letting the changelog fragment/PR carry the measurement narrative, since those numbers will drift out of date long before anyone touches this function again.
• Demoting the four _logger.info sites to DEBUG means these diagnostics disappear from production logs entirely unless DEBUG is explicitly enabled. Consistent with them being per-search diagnostics rather than operational signals, but flagging in case anything downstream was keying off those specific INFO lines.
• Since the in-repo suite couldn't be run locally, it'd be good to confirm this actually goes green in CI before merge (the PR description already flags this itself - just re-raising it as a checklist item).

Overall: the fix is targeted, correctly scoped to the actual expensive call sites, and the measurement work backing it is convincing. Main ask before merge is closing the test-coverage and changelog gaps called out above.

[JSv4]

Swept the rest of the codebase for the same primitive rather than only the sites the profile named:

grep -rn 'logger\.\(debug\|info\)(.*\.count()' --include=*.py opencontractserver/ config/
grep -rn 'logger\.\(debug\|info\)(f\?".*{.*\.query}' --include=*.py opencontractserver/ config/

Everything else that eagerly evaluates a COUNT(*) inside a logging call is in opencontractserver/tests/ (runs once, harmless) plus utils/analyzer.py:218, which is once per corpus-analysis rather than once per search. No .query stringification in a log call outside the file changed here. So the vector store was the only hot-path instance of the class.

[JSv4]

Added opencontractserver/tests/test_vector_store_diagnostics.py so CI checks this rather than taking my measurement on trust.

The regression test: test_no_count_diagnostics_run_when_debug_is_off patches _safe_queryset_info / _safe_queryset_info_sync and asserts they are not called at INFO — i.e. that the logging call's arguments are no longer evaluated before the level is checked. Verified it fails on main and passes here:

# with core_vector_stores.py reverted to main
exit_WITHOUT_fix=1
FAILED test_no_count_diagnostics_run_when_debug_is_off

# with the guard
exit=0   (3 passed)

Two controls against the guard going wrong, since the danger of a change like this is silently removing a diagnostic:

• test_diagnostics_still_run_when_debug_is_on — deferred, not deleted
• test_results_are_identical_either_way — the guard changes timing and nothing else

All three assert the search returned rows first, because all three would otherwise pass vacuously against an empty result set — which is exactly how the fixture was broken while writing them (a made-up embedder_path stored the vectors in a column the store never read back).

Regression run over test_vector_store_diagnostics, test_agent_system_prompt_assembly, test_corpus_isolation_vector_store, test_hybrid_search, test_unified_agent_consumer_delegation: 81 passed, exit 0.

Note for anyone running the suite locally: under local.yml pytest dies at django.setup() with Application labels aren't unique, duplicates: storages, because settings/test.py appends storages unconditionally while base.py also appends it when STORAGE_BACKEND=AWS. STORAGE_BACKEND=LOCAL works around it. Left alone here as out of scope, but it is a latent trap.

[claude]

Review

Nice, well-measured fix. The core diagnosis — Python evaluates a logging call's arguments eagerly, so _logger.debug(await _safe_queryset_info(...)) pays for the COUNT(*) regardless of level — is correct, and I verified the fix is applied consistently:

• I grepped the file for every _safe_queryset_info / _safe_queryset_info_sync / queryset.query call site (3 .query sites, 6 _safe_queryset_info* sites) and confirmed all are now behind _diagnostics_enabled(). None were missed.
• The remaining un-gated _logger.info(...) calls (mode-degradation notice, hybrid-fusion counts, global-search summary, no-scope-filters notice) only touch already-materialized lengths/strings, not querysets — correctly left alone since they are cheap.
• _diagnostics_enabled() uses _logger.isEnabledFor(logging.DEBUG), the standard idiom, and since config/settings/base.py sets root.level = INFO, this defaults to False in prod/test as intended.

Test coverage is thorough and does the right thing for a guard like this: one test proves the count-producing helpers are never called (not just not logged) at INFO, one proves they still fire at DEBUG (deferred, not deleted), and one proves search results are identical at both levels. Using assertLogs(level=logging.INFO) to force the logger's effective level for the negative-case test (rather than relying on ambient settings) is a nice touch.

Things worth addressing before merge:

1. No changelog fragment. Per CLAUDE.md's changelog policy, this should get a changelog.d/<slug>.fixed.md entry (see e.g. changelog.d/2253-case-reporter-bare-f.fixed.md for the convention). This is a real production perf bug (~6x search latency per the PR's own measurements), worth a fixed fragment referencing core_vector_stores.py and the before/after numbers.

2. Full backend suite was not run locally (per the PR description — django.setup() allegedly fails on a duplicate storages app label under local.yml). That sounds like a pre-existing local-env issue rather than something introduced here, but worth confirming test_vector_store_diagnostics.py actually passes in CI (test.yml/pytest-xdist) before merge since it was not verified locally. If that env issue is real and reproducible outside this branch, it is worth its own tracked issue since it would block anyone from running manage.py test locally.

3. Minor/non-blocking: the four demoted INFO to DEBUG sites ("Initial: Total annotations in DB", "After document/corpus scoping", "Annotations after visibility filtering", plus the vector/limit sites) change what is visible to anyone tailing production logs at INFO. Given the measured cost this is clearly the right tradeoff, just flagging in case any dashboards/alerts scrape those specific lines.

Overall: focused, correctly scoped, well-verified perf fix with good regression tests. The changelog fragment is the only thing I would block on; the test-suite verification note is worth a maintainer double-check in CI.

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!

[claude]

Review

Nice, well-scoped fix. The diagnosis is correct — Python evaluates a logging call's arguments before checking whether the level is enabled, so _logger.debug(await _safe_queryset_info(...)) always pays for the COUNT(*) regardless of level. The _diagnostics_enabled() guard mirrors exactly what isEnabledFor(DEBUG) would decide internally, so behavior at DEBUG is unchanged and the win at INFO/WARNING is real.

Verified while reviewing:

• Every _safe_queryset_info/_safe_queryset_info_sync call site and every queryset.query stringification in core_vector_stores.py is now guarded — grepped the whole file, found none left unguarded (core_vector_stores.py:280,465,480,517,519,543,549,572,962,977,1612,1628).
• The four sites demoted from INFO→DEBUG are exactly the ones that were also passed through _safe_queryset_info — no unrelated log-level changes snuck in.
• The remaining unguarded _logger.debug/_logger.info calls (e.g. the hybrid-fusion line at core_vector_stores.py:1093, the mode-degradation notice at :826, len(annotations) at :996-1002) are all cheap — they format already-materialized Python values, not new queries — so leaving them ungated is correct and consistent with the PR's stated scope.
• logging was already imported in this module, so no missing-import risk.
• The new test file (test_vector_store_diagnostics.py) is a good pattern: it asserts the helper is never called at INFO (not just "not logged", which would pass even if the guard leaked), asserts it's still called at DEBUG (catches "guard deletes instead of defers"), and asserts identical search results regardless of log level (catches a guard accidentally short-circuiting real filtering). check_corpus_deletion=False and the default embedder path are both used correctly relative to the store's constructor/embedding column.

Minor, non-blocking:

• _diagnostics_enabled() is called up to ~4 times within a single _build_base_queryset invocation. isEnabledFor is cheap but not free (it walks/caches effective level); could hoist to a single local at the top of the method if you want to shave a little more, but this is negligible next to the COUNT(*) queries it's replacing — not worth the added parameter-passing.
• The changelog fragment and file naming follow changelog.d/README.md conventions correctly.

Process note: the PR body flags that the repo test suite wasn't run locally (a django.setup() failure on a duplicate storages app label under local.yml, unrelated to this change) and instead relies on an out-of-repo verification script plus the new test_vector_store_diagnostics.py. Worth confirming CI is green here before merge, and worth filing/checking whether that storages app-label collision is a known, separate issue blocking local test runs generally.

Also noted: the PR explicitly scopes out the non-concurrent asyncio.gather in search_across_corpora (1.08x instead of true concurrency) as a separate finding — agreed that's out of scope here and worth its own follow-up issue/PR given the sync_to_async calls underneath.

Overall: solid, well-measured performance fix with good regression-test coverage for the specific failure mode (guard-that-deletes vs. guard-that-defers). No security or permissioning concerns — this is internal retrieval-path logging, doesn't touch the permission/visibility filtering logic itself (only when it's logged).

[claude]

Review

Solid, well-scoped perf fix. The core diagnosis (Python evaluates logging-call arguments before checking the level, so _logger.debug(await _safe_queryset_info(qs, ...)) always pays for the COUNT(*)) is correct and the fix — guard every such call site behind _diagnostics_enabled() — is the standard remedy. I verified every _safe_queryset_info/_safe_queryset_info_sync/queryset.query site in core_vector_stores.py is now guarded (grepped the whole file, no stragglers), and the four INFO→DEBUG demotions match the stated rationale (state-changing/cheap logs like the mode-degradation and fusion-summary lines were correctly left ungated since they only format already-materialized lengths).

Nice touches:

• _apply_metadata_filters's queryset.query stringification was also caught and gated — that's a real find beyond what the profile initially named (compiling the SQL isn't free either), and shows the fix was grepped for the whole class of problem rather than patched at the three measured sites only.
• The test suite (test_vector_store_diagnostics.py) asserts the right thing for a guard like this: not just "nothing is logged at INFO" but that _safe_queryset_info/_safe_queryset_info_sync are never called at INFO (via patch + call_count == 0), that they still fire at DEBUG (deferred, not deleted), and that results are byte-identical between the two levels. The follow-up commit closing the must_have_text/modalities/metadata-filter/vector-only branch gaps (patch coverage was 69%) is exactly the right response to that codecov signal rather than padding coverage elsewhere.
• Switching to %s-style lazy logging args (_logger.debug("Query after visibility filter: %s", queryset.query)) inside the now-guarded blocks is a nice belt-and-suspenders touch, even though the outer if _diagnostics_enabled(): already makes it redundant.

Minor observations, none blocking:

1. opencontractserver/llms/vector_stores/core_conversation_vector_stores.py defines its own _safe_queryset_info/_safe_queryset_info_sync (lines 34/46) with the identical queryset.count() shape — but grepping the file, neither is actually called anywhere. Pre-existing dead code, unrelated to this diff, but worth a follow-up cleanup per the repo's "no dead code" guideline since it's the same primitive this PR just spent effort fixing elsewhere.
2. The guard is manual-per-call-site (if _diagnostics_enabled(): _logger.debug(...)), so it's easy for a future contributor to reintroduce this exact bug by adding a new _safe_queryset_info(...) call without the if. Not asking for a rework here (a centralized lazy-eval wrapper would be a bigger change for a perf-fix PR), but might be worth a one-line comment on _safe_queryset_info itself pointing future editors at the _diagnostics_enabled() convention, since the existing docstring on _diagnostics_enabled() already explains the "why" but lives at the guard, not at the expensive primitive.
3. PR description says "four" _logger.info sites were demoted to DEBUG, but by my count in the diff it's five (Initial: Total annotations in DB, After document/corpus scoping, After must_have_text=..., Annotations after visibility filtering, After modalities=...). Purely a description nit, not a code issue.
4. Worth confirming in CI: the PR notes the full backend suite wasn't run locally due to an unrelated django.setup() duplicate-storages-app-label issue under local.yml. Given the new test file touches several distinct search-mode branches, it'd be good to see the CI run (or pytest opencontractserver/tests/test_vector_store_diagnostics.py) green before merge.

Behavior-change callout for reviewers/ops: the four (five) sites demoted from INFO→DEBUG mean these diagnostics no longer appear in production logs at default verbosity. That's clearly the intent (and documented in the changelog fragment), but flagging in case anyone was scraping those specific INFO lines for count-based alerting.

No security or IDOR concerns — this is a pure logging/perf change and doesn't touch any permission-filtering logic.