[Debt] Add DB query timing and batch auth principal resolution #259

New Issue

2026-07-14T00:13:18+02:00

zemion commented

2026-07-14 00:13:18 +02:00

Current Cost

The slow-request logger now identifies expensive routes, but it does not yet show query count, query duration, or repeated query patterns. Auth principal resolution and _me_response() likely perform redundant role/group/system-role/function/delegation lookups.

Desired Shape

Add request-scoped DB query timing/count instrumentation, then batch the auth/principal data loads that dominate /auth/me and protected page requests.

Scope

Owning repositories: govoplan-core, govoplan-access.
Add request-scoped SQLAlchemy query count and cumulative DB time for slow request logs.
Use those measurements to reduce repeated auth queries.
Batch roles, groups, system roles, tenant memberships, function assignments, and delegations where practical.
Avoid changing permission semantics.

Checklist

Add query count/time to slow request logs.
Capture before/after timings for /auth/me, address, calendar, and files page bootstrap requests.
Batch repeated auth/principal queries.
Add focused tests around effective scopes, groups, roles, and delegation/function context.

Verification Target

Existing auth and admin smoke tests pass.
Slow logs include route duration, DB query count, and DB time for requests over threshold.
/api/v1/auth/me query count and duration are reduced measurably.

## Current Cost The slow-request logger now identifies expensive routes, but it does not yet show query count, query duration, or repeated query patterns. Auth principal resolution and `_me_response()` likely perform redundant role/group/system-role/function/delegation lookups. ## Desired Shape Add request-scoped DB query timing/count instrumentation, then batch the auth/principal data loads that dominate `/auth/me` and protected page requests. ## Scope - Owning repositories: `govoplan-core`, `govoplan-access`. - Add request-scoped SQLAlchemy query count and cumulative DB time for slow request logs. - Use those measurements to reduce repeated auth queries. - Batch roles, groups, system roles, tenant memberships, function assignments, and delegations where practical. - Avoid changing permission semantics. ## Checklist - [ ] Add query count/time to slow request logs. - [ ] Capture before/after timings for `/auth/me`, address, calendar, and files page bootstrap requests. - [ ] Batch repeated auth/principal queries. - [ ] Add focused tests around effective scopes, groups, roles, and delegation/function context. ## Verification Target - Existing auth and admin smoke tests pass. - Slow logs include route duration, DB query count, and DB time for requests over threshold. - `/api/v1/auth/me` query count and duration are reduced measurably.

zemion commented

2026-07-14 12:04:00 +02:00

Implemented the main #259 slice on 2026-07-14.

Changes made:

Added request-scoped SQLAlchemy query metrics in core and instrumented engines created through create_database_engine() / DatabaseHandle.
Slow request logs now include db_query_count, db_time_ms, db_slowest_ms, and db_error_count for success and failure paths.
Added focused tests for query metrics and slow-request log fields.
Batched/reused access authorization context for built-in access principal resolution: tenant roles, system roles, groups, scopes, function assignment IDs, and delegation IDs are now collected once for principal construction.
Avoided the PrincipalRef -> ApiPrincipal re-load round trip for the built-in access resolver while keeping the public resolver contract intact.
Reused active tenant roles in legacy /auth/me membership output instead of recalculating them.
Skipped the impossible API-key probe for cookie-sourced session tokens.

Smoke-app measurements after the change, using isolated SQLite smoke data, cookie session, 30 requests per endpoint, slow-request logs parsed for DB counts:

Endpoint	median ms	p95 ms	median DB queries	median DB time ms
`/api/v1/auth/session`	5.142	5.812	4	0.100
`/api/v1/auth/shell`	9.816	10.469	10	0.300
`/api/v1/auth/profile`	6.340	7.249	7	0.200
`/api/v1/auth/roles`	8.820	9.944	9	0.300
`/api/v1/auth/groups`	5.650	6.938	5	0.200
legacy `/api/v1/auth/me`	14.403	15.569	19	0.900

Reference before this slice:

Before #259, after #258 split: legacy /api/v1/auth/me was ~68.167 ms median without DB query counters.
First #259 measurement before the final duplicate-load cleanup: /api/v1/auth/me was ~18.371 ms median / 28 queries.
After membership-role reuse: /api/v1/auth/me was ~15.699 ms median / 24 queries.
Final after built-in resolver context reuse and cookie-token API-key skip: /api/v1/auth/me is ~14.403 ms median / 19 queries.

Verification run:

python -m unittest tests.test_query_metrics in govoplan-core: OK.
python -m unittest tests.test_api_smoke.ApiSmokeTests.test_cookie_session_requires_csrf_for_mutations in govoplan-core: OK.
python -m unittest tests.test_module_system in govoplan-core: OK, 105 tests.
python -m unittest discover -s tests in govoplan-access: OK, 15 tests.
python -m govoplan_core.devserver --smoke --no-reload: OK.

Leaving this issue open for now only because the checklist also mentions capturing address/calendar/files page-bootstrap measurements. The core instrumentation needed for those measurements now exists, so that can be done from the running UI or a dedicated follow-up scenario without guessing endpoint bundles.

Implemented the main `#259` slice on 2026-07-14. Changes made: - Added request-scoped SQLAlchemy query metrics in core and instrumented engines created through `create_database_engine()` / `DatabaseHandle`. - Slow request logs now include `db_query_count`, `db_time_ms`, `db_slowest_ms`, and `db_error_count` for success and failure paths. - Added focused tests for query metrics and slow-request log fields. - Batched/reused access authorization context for built-in access principal resolution: tenant roles, system roles, groups, scopes, function assignment IDs, and delegation IDs are now collected once for principal construction. - Avoided the `PrincipalRef -> ApiPrincipal` re-load round trip for the built-in access resolver while keeping the public resolver contract intact. - Reused active tenant roles in legacy `/auth/me` membership output instead of recalculating them. - Skipped the impossible API-key probe for cookie-sourced session tokens. Smoke-app measurements after the change, using isolated SQLite smoke data, cookie session, 30 requests per endpoint, slow-request logs parsed for DB counts: | Endpoint | median ms | p95 ms | median DB queries | median DB time ms | | --- | ---: | ---: | ---: | ---: | | `/api/v1/auth/session` | 5.142 | 5.812 | 4 | 0.100 | | `/api/v1/auth/shell` | 9.816 | 10.469 | 10 | 0.300 | | `/api/v1/auth/profile` | 6.340 | 7.249 | 7 | 0.200 | | `/api/v1/auth/roles` | 8.820 | 9.944 | 9 | 0.300 | | `/api/v1/auth/groups` | 5.650 | 6.938 | 5 | 0.200 | | legacy `/api/v1/auth/me` | 14.403 | 15.569 | 19 | 0.900 | Reference before this slice: - Before `#259`, after `#258` split: legacy `/api/v1/auth/me` was ~68.167 ms median without DB query counters. - First `#259` measurement before the final duplicate-load cleanup: `/api/v1/auth/me` was ~18.371 ms median / 28 queries. - After membership-role reuse: `/api/v1/auth/me` was ~15.699 ms median / 24 queries. - Final after built-in resolver context reuse and cookie-token API-key skip: `/api/v1/auth/me` is ~14.403 ms median / 19 queries. Verification run: - `python -m unittest tests.test_query_metrics` in `govoplan-core`: OK. - `python -m unittest tests.test_api_smoke.ApiSmokeTests.test_cookie_session_requires_csrf_for_mutations` in `govoplan-core`: OK. - `python -m unittest tests.test_module_system` in `govoplan-core`: OK, 105 tests. - `python -m unittest discover -s tests` in `govoplan-access`: OK, 15 tests. - `python -m govoplan_core.devserver --smoke --no-reload`: OK. Leaving this issue open for now only because the checklist also mentions capturing address/calendar/files page-bootstrap measurements. The core instrumentation needed for those measurements now exists, so that can be done from the running UI or a dedicated follow-up scenario without guessing endpoint bundles.

zemion commented

2026-07-14 13:11:50 +02:00

Codex State: progress

Summary

Recorded address/calendar/files page-bootstrap baseline after the query metrics + auth batching work.
Method: isolated FastAPI TestClient app on SQLite, cookie session after login, 5 warmups + 30 measured runs, seeded with 1 address book/contact, 1 local calendar/event, and 1 managed folder/file.
Scope: backend request bootstrap metrics from the current WebUI call graph, not frontend render/paint timing. Parallel-aware estimate uses the page's first-load grouping, while serial sum is the measured sequential request bundle.

Page Baseline

Page	Requests	Serial request sum median / p95	Parallel-aware estimate	DB queries median / p95	DB time median / p95
Addresses	4	43.4 ms / 47.0 ms	22.55 ms	64 / 64	3.0 ms / 3.3 ms
Calendar	3	31.4 ms / 33.3 ms	21.4 ms	43 / 43	2.1 ms / 2.3 ms
Files	4	47.5 ms / 51.2 ms	46.85 ms	66 / 66	3.3 ms / 3.5 ms

Endpoint Medians

Endpoint	Duration median / p95	DB queries median	DB time median
`GET /api/v1/addresses/address-books`	10.4 ms / 11.8 ms	15	0.7 ms
`GET /api/v1/addresses/address-lists`	10.4 ms / 11.3 ms	15	0.7 ms
`GET /api/v1/addresses/sync-sources`	10.4 ms / 11.8 ms	15	0.7 ms
`GET /api/v1/addresses/contacts`	12.15 ms / 12.7 ms	19	0.9 ms
`GET /api/v1/calendar/calendars`	9.9 ms / 11.1 ms	14	0.7 ms
`GET /api/v1/calendar/sync-sources`	10.4 ms / 11.5 ms	14	0.7 ms
`GET /api/v1/calendar/events/delta`	11.0 ms / 12.5 ms	15	0.7 ms
`GET /api/v1/files/spaces`	10.7 ms / 11.6 ms	15	0.7 ms
`GET /api/v1/files/folders`	11.1 ms / 12.0 ms	15	0.8 ms
`GET /api/v1/files`	12.4 ms / 14.5 ms	18	0.9 ms
`GET /api/v1/files/delta`	12.65 ms / 13.9 ms	18	0.9 ms

Verification

Ad-hoc isolated FastAPI TestClient measurement script completed successfully; every measured endpoint returned 200.
Calendar default continuous range used for the run: 2026-05-17T22:00:00.000Z to 2026-10-04T22:00:00.000Z.

## Codex State: progress ### Summary - Recorded address/calendar/files page-bootstrap baseline after the query metrics + auth batching work. - Method: isolated FastAPI TestClient app on SQLite, cookie session after login, 5 warmups + 30 measured runs, seeded with 1 address book/contact, 1 local calendar/event, and 1 managed folder/file. - Scope: backend request bootstrap metrics from the current WebUI call graph, not frontend render/paint timing. Parallel-aware estimate uses the page's first-load grouping, while serial sum is the measured sequential request bundle. ### Page Baseline | Page | Requests | Serial request sum median / p95 | Parallel-aware estimate | DB queries median / p95 | DB time median / p95 | | --- | ---: | ---: | ---: | ---: | ---: | | Addresses | 4 | 43.4 ms / 47.0 ms | 22.55 ms | 64 / 64 | 3.0 ms / 3.3 ms | | Calendar | 3 | 31.4 ms / 33.3 ms | 21.4 ms | 43 / 43 | 2.1 ms / 2.3 ms | | Files | 4 | 47.5 ms / 51.2 ms | 46.85 ms | 66 / 66 | 3.3 ms / 3.5 ms | ### Endpoint Medians | Endpoint | Duration median / p95 | DB queries median | DB time median | | --- | ---: | ---: | ---: | | `GET /api/v1/addresses/address-books` | 10.4 ms / 11.8 ms | 15 | 0.7 ms | | `GET /api/v1/addresses/address-lists` | 10.4 ms / 11.3 ms | 15 | 0.7 ms | | `GET /api/v1/addresses/sync-sources` | 10.4 ms / 11.8 ms | 15 | 0.7 ms | | `GET /api/v1/addresses/contacts` | 12.15 ms / 12.7 ms | 19 | 0.9 ms | | `GET /api/v1/calendar/calendars` | 9.9 ms / 11.1 ms | 14 | 0.7 ms | | `GET /api/v1/calendar/sync-sources` | 10.4 ms / 11.5 ms | 14 | 0.7 ms | | `GET /api/v1/calendar/events/delta` | 11.0 ms / 12.5 ms | 15 | 0.7 ms | | `GET /api/v1/files/spaces` | 10.7 ms / 11.6 ms | 15 | 0.7 ms | | `GET /api/v1/files/folders` | 11.1 ms / 12.0 ms | 15 | 0.8 ms | | `GET /api/v1/files` | 12.4 ms / 14.5 ms | 18 | 0.9 ms | | `GET /api/v1/files/delta` | 12.65 ms / 13.9 ms | 18 | 0.9 ms | ### Verification - Ad-hoc isolated FastAPI TestClient measurement script completed successfully; every measured endpoint returned `200`. - Calendar default continuous range used for the run: `2026-05-17T22:00:00.000Z` to `2026-10-04T22:00:00.000Z`. ### Next - The data points at shared per-request auth/principal overhead as the remaining common cost: almost every endpoint still starts around 14-19 queries before module-specific work dominates.

zemion commented

2026-07-14 14:01:20 +02:00

Codex State: note

Summary

Decision after reviewing the address/calendar/files page-bootstrap baseline: leave the remaining shared auth/principal-query reduction open but do not prioritize it immediately.
Current backend bootstrap numbers are acceptable for now: roughly 20-50 ms per page bundle on isolated SQLite, with only about 2-3 ms actual DB time per bundle.
The high per-endpoint query count remains useful as a scalability warning and future optimization target.

Next / Blocked

Revisit when production/Postgres measurements show materially higher latency, pages add more parallel bootstrap calls, or we touch shared auth/principal lookup code anyway.

## Codex State: note ### Summary - Decision after reviewing the address/calendar/files page-bootstrap baseline: leave the remaining shared auth/principal-query reduction open but do not prioritize it immediately. - Current backend bootstrap numbers are acceptable for now: roughly 20-50 ms per page bundle on isolated SQLite, with only about 2-3 ms actual DB time per bundle. - The high per-endpoint query count remains useful as a scalability warning and future optimization target. ### Next / Blocked - Revisit when production/Postgres measurements show materially higher latency, pages add more parallel bootstrap calls, or we touch shared auth/principal lookup code anyway.

zemion commented

2026-07-29 13:25:59 +02:00

Codex State: progress

The July audit tranche reduced request-path work before closing this measurement issue:

authentication activity timestamps are written through a configurable window instead of on every request;
principal memberships, roles, groups, and ownership data are eagerly/batch loaded;
no-op authentication requests no longer commit a session;
system account directory response assembly and tenant Access counts now use bounded aggregate queries;
tenant list summaries no longer invoke unrelated deletion providers.

Verification includes the full Core suite (361 passed, 3 skipped, 215 subtests) before the final focused refactors, the module-system suite (117 passed, 185 subtests) afterward, and the consolidated focused platform check.

Keep this issue open for representative production-like query timing and baseline comparison. Safe principal caching remains separately tracked by #260.

## Codex State: progress The July audit tranche reduced request-path work before closing this measurement issue: - authentication activity timestamps are written through a configurable window instead of on every request; - principal memberships, roles, groups, and ownership data are eagerly/batch loaded; - no-op authentication requests no longer commit a session; - system account directory response assembly and tenant Access counts now use bounded aggregate queries; - tenant list summaries no longer invoke unrelated deletion providers. Verification includes the full Core suite (`361 passed, 3 skipped, 215 subtests`) before the final focused refactors, the module-system suite (`117 passed, 185 subtests`) afterward, and the consolidated focused platform check. Keep this issue open for representative production-like query timing and baseline comparison. Safe principal caching remains separately tracked by #260.

zemion added the area/auth area/db area/security codex/ready module/core

labels 2026-07-29 14:15:06 +02:00

zemion commented

2026-07-29 14:20:49 +02:00

Codex State: done

All written acceptance criteria are complete and published on main at 68328f3.

Slow request logs include query count, cumulative DB time, slowest query time, and DB error count.
Auth principal resolution batches/reuses role, group, scope, function, delegation, and membership context without changing permission semantics.
Before/after /auth/me measurements and address/calendar/files bootstrap measurements are recorded in this issue.
Core verification includes the full suite (361 passed, 3 skipped, 215 subtests) and the consolidated cross-module check.

Further safe principal caching remains independently tracked by #260; tenant-provider batching remains tracked by #273. Those follow-ups no longer need to keep this measurement/implementation ticket open.

## Codex State: done All written acceptance criteria are complete and published on `main` at `68328f3`. - Slow request logs include query count, cumulative DB time, slowest query time, and DB error count. - Auth principal resolution batches/reuses role, group, scope, function, delegation, and membership context without changing permission semantics. - Before/after `/auth/me` measurements and address/calendar/files bootstrap measurements are recorded in this issue. - Core verification includes the full suite (`361 passed, 3 skipped, 215 subtests`) and the consolidated cross-module check. Further safe principal caching remains independently tracked by #260; tenant-provider batching remains tracked by #273. Those follow-ups no longer need to keep this measurement/implementation ticket open.

zemion closed this issue

2026-07-29 14:20:49 +02:00

zemion removed the codex/ready

status

ready

labels 2026-07-29 14:20:49 +02:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: GovOPlaN/govoplan-core#259