Raised from the Avni sync load-test plan. Plan: avni-perf/docs/sync-simulation-plan.md — section F.
Measurement only. No fixes in this issue.
Reading avni-server while writing the load-test plan produced several plausible choke points. They are hypotheses, not findings. This card attaches a cost to each one. Fixes become separate cards, raised only for suspects that prove to matter.
Two reasons that discipline matters here rather than just being tidy. A cheap-looking fix applied to something that turns out to cost 0.3% burns review and deploy cycles while the real bottleneck stays hidden. And several of these suspects are doing necessary work — the organisation interceptor enforces row-level security, syncDetails exists to cut the client's request count — so the question is never "is this expensive?" but "is it expensive relative to what it buys?"
Prerequisite: most of the instrumentation needed is configuration in avni-infra, not code here — New Relic is already the APM, attached by javaagent. See avniproject/avni-infra#112. The blocker is that configure/group_vars/ has no perf or loadtest environment file yet.
Suspects to cost
1. The organisation JDBC interceptor
framework/tomcat/SetOrganisationJdbcInterceptor.java runs on every pooled connection borrow:
- On borrow (
reset): set role "<dbUser>"; then set application_name to "<dbUser>"; — two separate statement.execute() calls
- On release (
invoke, method close): RESET ROLE — a third
Three Postgres round trips wrapped around every connection use, before any application query runs.
Second cost in the same class: invoke builds a TRACE log line for nearly every proxied connection method, and its argument is connection.getMetaData().getConnection().hashCode(). Parameterised logging defers formatting but not argument evaluation, so getMetaData() runs on every prepareStatement, createStatement, commit and setAutoCommit regardless of log level.
Note requests needing no database still pay it whenever wrapped in @Transactional — GET /media/uploadUrl/{fileName} is @Transactional(readOnly = true) and issues no SQL of its own.
If it proves significant, candidate fixes are collapsing the two SET statements into one round trip and removing the unconditional getMetaData() evaluation. Not in scope here.
2. syncDetails — cost and benefit
SyncController.getChangedEntities does a nested linear scan, and filterChangedEntities issues one query per entity + type row. For an org with many subject types, programs and encounter types that is potentially hundreds of queries on the endpoint every sync calls first.
That cost is the point of the endpoint, so measuring it alone would be misleading. It tells the client which entities changed so the client requests only those instead of polling all ~60.
|
|
| Cost |
One filterChangedEntities query per row, plus the nested scan. Scales with org complexity, not data volume. |
| Saves |
One paginated request per unchanged entity — each otherwise an HTTP round trip, an auth filter pass, a connection borrow with suspect 1's three SET statements, and a query returning zero rows. |
The trade swings on how many entities actually change between syncs — strongly positive for incremental sync, pure overhead for a full sync where everything changed anyway.
Read Q9 as: fraction changed near 0 means syncDetails earns its cost many times over and effort belongs elsewhere; near 1 means it is mostly ceremony.
If the cost proves significant, the outcome is to make it cheaper — batching the per-row checks into one query, or a per-organisation last-modified summary — not to send the client back to polling every entity.
Interacts with page size: at the client's real page size of 1000, the per-request overhead syncDetails saves is amortised over ten times fewer requests than when the endpoint was designed, which weakens the benefit side.
3. Row-level security and tenancy
Every org-scoped table carries USING (organisation_id = ANY (public.rls_visible_org_ids())); reference tables use the wider rls_visible_org_ids_with_ancestors(), which walks the org hierarchy. current_user is the org's db_user, set by suspect 1's set role — RLS and the interceptor are one mechanism, not two.
V1_398__IndexableRLSOrgPolicies.sql exists because the earlier policy referenced organisation.db_user directly and was not index-friendly, so this has already been a real problem here once.
4. Storage IO ceiling
Production runs against a fixed 3,000 IOPS / 125 MiB/s, with a working set of ~134 GB.
A 134 GB working set behind GIN indexes on observations, serving sync reads at page size 1000, against a hard 3,000 IOPS ceiling. Once the active set exceeds shared_buffers, that ceiling is plausibly the constraint rather than any query-level suspect above.
Note this constrains remediation as well as diagnosis: production's IO ceiling cannot simply be raised in place. The options and their cost are an infrastructure question (avniproject/avni-infra#112), but any of them forfeits parity with today's production — so a finding here changes what subsequent runs measure against.
5. ETL contention on the same IO budget
avni-etl maintains a flat analytical schema per organisation, converting every JSONB key to a column, plus passthrough tables and materialised views dropped and recreated at the end of every run. A Quartz job runs it every 90 minutes.
It reads the public schema in direct competition with sync reads, writes the org schema, and rebuilds those views — all against the same fixed 3,000 IOPS. An ETL cycle coinciding with the start-of-day sync herd is a scheduled, recurring production event, not a hypothetical.
Scale: 62 GB across 10,367 relations in org schemas, against 70 GB and 143 relations in public. ETL is not enabled for every organisation, so the per-enabled-org multiplier is higher than that aggregate suggests.
6. Connection pool size
spring.datasource.type=org.apache.tomcat.jdbc.pool.DataSource (application.properties:14) and no pool size is configured, so it sits at the Tomcat JDBC default.
Falsifiable prediction: concurrency beyond that default should produce borrow waits before anything else saturates.
(The pool is Tomcat JDBC, not HikariCP — HikariCP is on the classpath but unused, so Hikari metrics read zero and Hikari-shaped dashboards silently show nothing.)
7. Per-request logging
AuthenticationFilter logs at INFO twice per request — on receipt, and on completion with timing — including the full query string.
Also in this repo, unrelated to measurement
Related
Raised from the Avni sync load-test plan. Plan:
avni-perf/docs/sync-simulation-plan.md— section F.Measurement only. No fixes in this issue.
Reading avni-server while writing the load-test plan produced several plausible choke points. They are hypotheses, not findings. This card attaches a cost to each one. Fixes become separate cards, raised only for suspects that prove to matter.
Two reasons that discipline matters here rather than just being tidy. A cheap-looking fix applied to something that turns out to cost 0.3% burns review and deploy cycles while the real bottleneck stays hidden. And several of these suspects are doing necessary work — the organisation interceptor enforces row-level security,
syncDetailsexists to cut the client's request count — so the question is never "is this expensive?" but "is it expensive relative to what it buys?"Suspects to cost
1. The organisation JDBC interceptor
framework/tomcat/SetOrganisationJdbcInterceptor.javaruns on every pooled connection borrow:reset):set role "<dbUser>";thenset application_name to "<dbUser>";— two separatestatement.execute()callsinvoke, methodclose):RESET ROLE— a thirdThree Postgres round trips wrapped around every connection use, before any application query runs.
Second cost in the same class:
invokebuilds a TRACE log line for nearly every proxied connection method, and its argument isconnection.getMetaData().getConnection().hashCode(). Parameterised logging defers formatting but not argument evaluation, sogetMetaData()runs on everyprepareStatement,createStatement,commitandsetAutoCommitregardless of log level.Note requests needing no database still pay it whenever wrapped in
@Transactional—GET /media/uploadUrl/{fileName}is@Transactional(readOnly = true)and issues no SQL of its own.If it proves significant, candidate fixes are collapsing the two
SETstatements into one round trip and removing the unconditionalgetMetaData()evaluation. Not in scope here.2.
syncDetails— cost and benefitSyncController.getChangedEntitiesdoes a nested linear scan, andfilterChangedEntitiesissues one query per entity + type row. For an org with many subject types, programs and encounter types that is potentially hundreds of queries on the endpoint every sync calls first.That cost is the point of the endpoint, so measuring it alone would be misleading. It tells the client which entities changed so the client requests only those instead of polling all ~60.
filterChangedEntitiesquery per row, plus the nested scan. Scales with org complexity, not data volume.SETstatements, and a query returning zero rows.The trade swings on how many entities actually change between syncs — strongly positive for incremental sync, pure overhead for a full sync where everything changed anyway.
/v2/syncDetails, and how it scales with the number of entity + type rowsEXPLAINthefilterChangedEntitiesquery pathsRead Q9 as: fraction changed near 0 means
syncDetailsearns its cost many times over and effort belongs elsewhere; near 1 means it is mostly ceremony.If the cost proves significant, the outcome is to make it cheaper — batching the per-row checks into one query, or a per-organisation last-modified summary — not to send the client back to polling every entity.
Interacts with page size: at the client's real page size of 1000, the per-request overhead
syncDetailssaves is amortised over ten times fewer requests than when the endpoint was designed, which weakens the benefit side.3. Row-level security and tenancy
Every org-scoped table carries
USING (organisation_id = ANY (public.rls_visible_org_ids())); reference tables use the widerrls_visible_org_ids_with_ancestors(), which walks the org hierarchy.current_useris the org'sdb_user, set by suspect 1'sset role— RLS and the interceptor are one mechanism, not two.V1_398__IndexableRLSOrgPolicies.sqlexists because the earlier policy referencedorganisation.db_userdirectly and was not index-friendly, so this has already been a real problem here once.set rolechurn under multi-tenant load affects plan or prepared-statement caching — invisible in any single-tenant test4. Storage IO ceiling
Production runs against a fixed 3,000 IOPS / 125 MiB/s, with a working set of ~134 GB.
A 134 GB working set behind GIN indexes on
observations, serving sync reads at page size 1000, against a hard 3,000 IOPS ceiling. Once the active set exceedsshared_buffers, that ceiling is plausibly the constraint rather than any query-level suspect above.ReadIOPS+WriteIOPSagainst 3,000,ReadThroughput+WriteThroughputagainst 125 MiB/s, at peakDiskQueueDepth— sustained non-zero is the signal that IO is the binding constraintNote this constrains remediation as well as diagnosis: production's IO ceiling cannot simply be raised in place. The options and their cost are an infrastructure question (avniproject/avni-infra#112), but any of them forfeits parity with today's production — so a finding here changes what subsequent runs measure against.
5. ETL contention on the same IO budget
avni-etlmaintains a flat analytical schema per organisation, converting every JSONB key to a column, plus passthrough tables and materialised views dropped and recreated at the end of every run. A Quartz job runs it every 90 minutes.It reads the public schema in direct competition with sync reads, writes the org schema, and rebuilds those views — all against the same fixed 3,000 IOPS. An ETL cycle coinciding with the start-of-day sync herd is a scheduled, recurring production event, not a hypothetical.
Scale: 62 GB across 10,367 relations in org schemas, against 70 GB and 143 relations in
public. ETL is not enabled for every organisation, so the per-enabled-org multiplier is higher than that aggregate suggests.6. Connection pool size
spring.datasource.type=org.apache.tomcat.jdbc.pool.DataSource(application.properties:14) and no pool size is configured, so it sits at the Tomcat JDBC default.Falsifiable prediction: concurrency beyond that default should produce borrow waits before anything else saturates.
(The pool is Tomcat JDBC, not HikariCP — HikariCP is on the classpath but unused, so Hikari metrics read zero and Hikari-shaped dashboards silently show nothing.)
7. Per-request logging
AuthenticationFilterlogs at INFO twice per request — on receipt, and on completion with timing — including the full query string.-Dlogging.level.…inavni_server_opts, so this one is cheap and needs no code change to test.Also in this repo, unrelated to measurement
avni-server/perf/gatling/— a second, older harness separate fromavni-perf. Maintaining two guarantees both drift.Related
syncDetailsfidelity work lives