feat(profiling): instrument executeQuery/executeUpdate paths with nanosecond step timings + 100-thread open-loop benchmark

[Copilot]

Assessment-only instrumentation to identify latency bottlenecks across the executeQuery and executeUpdate server action paths. Not intended for merge to main.

Main branch sync: this branch is current with main as of commit e59f4eb2 (Merge PR #520 – throttle incoming requests, 2026-05-15).

New infrastructure

• ExecutionPathProfiler — per-thread recorder; mark(stepName) snapshots elapsed ns since the previous mark; excludeNs(long ns) subtracts external JDBC time from the current step window
• ExecutionPathProfilingContext — ThreadLocal holder; mark(), beginJdbcCall(), and endJdbcCall() are all guaranteed no-ops in production (zero allocation, zero branching cost when not activated)

Instrumented steps

Path	Steps
executeQuery	sessionConnection → cacheCheck → sqlEnhancement → paramConversion → statementCreation → sqlExecution → resultSetHandling
executeUpdate	affinityCheck → sessionConnection → paramConversion → statementCreation → sqlExecution → buildResult

JDBC time exclusion

Each step measures OJP-internal overhead only. Time spent inside JDBC driver calls is subtracted via beginJdbcCall() / endJdbcCall() pairs placed at every JDBC boundary:

Class	Calls excluded
SessionConnectionHelper	getMetaData().getURL(), isClosed(), HikariCP/DriverManager pool acquisition
ExecuteQueryAction	prepareStatement/createStatement, executeQuery
ExecuteUpdateAction	prepareStatement/createStatement, executeUpdate
ResultSetHelper	getColumnCount, column label reads, URL resolution, every rs.next()

Note: the new acquireSessionPermit() call introduced in SessionConnectionHelper by PR #520 is intentionally not excluded — it is OJP admission-control wait time, not a JDBC driver call, and should be counted as OJP overhead within the sessionConnection step.

Benchmark test (ExecutePathLatencyBenchmarkTest)

Pre-creates 120 direct H2 sessions (no pool pressure), warms JIT with 20 sequential requests, then releases 100 threads simultaneously via CountDownLatch (open loop). Collects per-step ns timings, computes medians, prints an ASCII bar chart with a TOTAL (sum of medians) row at the bottom.

Latest results (H2 in-memory, 100 concurrent threads, OJP overhead only — JDBC time excluded)

  Step Timing Report — executeQuery path
  median of 100 concurrent requests (H2 in-memory) — OJP overhead only, JDBC time excluded
  ------------------------------------------------------------------------------------------
  sessionConnection        |████████████████░░░░░░░░░░░░░░░░░░░░░░░░|   52,674 ns  ( 52.7 µs)
  cacheCheck               |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,482 ns  (  1.5 µs)
  sqlEnhancement           |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      816 ns  (  0.8 µs)
  paramConversion          |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,147 ns  (  1.1 µs)
  statementCreation        |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,778 ns  (  1.8 µs)
  sqlExecution             |████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░|   40,361 ns  ( 40.4 µs)
  resultSetHandling        |████████████████████████████████████████|  128,794 ns  (128.8 µs)
  ------------------------------------------------------------------------------------------
  TOTAL (sum of medians)                                                227,052 ns  (227.1 µs)

  Step Timing Report — executeUpdate path
  median of 100 concurrent requests (H2 in-memory) — OJP overhead only, JDBC time excluded
  ------------------------------------------------------------------------------------------
  affinityCheck            |████████████████████████████████████████|   50,887 ns  ( 50.9 µs)
  sessionConnection        |███░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    5,023 ns  (  5.0 µs)
  paramConversion          |██░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    3,245 ns  (  3.2 µs)
  statementCreation        |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      781 ns  (  0.8 µs)
  sqlExecution             |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      601 ns  (  0.6 µs)
  buildResult              |████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    5,263 ns  (  5.3 µs)
  ------------------------------------------------------------------------------------------
  TOTAL (sum of medians)                                                 65,800 ns  ( 65.8 µs)

Key findings (OJP overhead only):

• executeQuery total: 227 µs — resultSetHandling dominates (~129 µs, pure proto ResultRow construction for 10 result rows). sessionConnection (~53 µs) is the second-largest cost (session map lookup). sqlExecution (~40 µs) captures only the OJP post-query work (registerResultSet + UUID generation).
• executeUpdate total: 66 µs — affinityCheck (~51 µs, regex parse) is the single largest cost. All other steps are sub-6 µs after JDBC is excluded.

[rrobetti]

@copilot print out the total (sum of all means) at the end.

[Copilot]

@copilot print out the total (sum of all means) at the end.

Done in 0bbae43. A TOTAL (sum of medians) row is now printed as the last entry in the bar chart, separated by its own divider line, for both the executeQuery and executeUpdate reports. Sample output:

  sessionConnection        |█████████░░░...| 71,348 ns  (71.348 µs)
  ...
  resultSetHandling        |████████████░░...| 278,704 ns  (278.704 µs)
------------------------------------------------------------------------------------------
  TOTAL (sum of medians)   |████████████████████...| 665,882 ns  (665.882 µs)
------------------------------------------------------------------------------------------
  Heaviest step: sqlExecution

[rrobetti]

@copilot discount the time spent once control is given to the jdbc driver, for example when executeQuery is called in the H2 JDBC driver, that time is not OJP time, same for when getting a connection from HikariCP or creating the statement or reading next row in a result set, all those times need to be subtracted from the measurements.

[Copilot]

@copilot discount the time spent once control is given to the jdbc driver, for example when executeQuery is called in the H2 JDBC driver, that time is not OJP time, same for when getting a connection ...

Done in commits 2454178 and 50e7da6.

Added beginJdbcCall() / endJdbcCall() to ExecutionPathProfilingContext and excludeNs() to ExecutionPathProfiler. Each JDBC boundary is now wrapped so only OJP-internal time is counted per step:

Location	Calls excluded
SessionConnectionHelper	getMetaData().getURL(), isClosed(), pool/driver acquisition
ExecuteQueryAction	prepareStatement/createStatement, executeQuery
ExecuteUpdateAction	prepareStatement/createStatement, executeUpdate
ResultSetHelper	getColumnCount, label reads, URL resolution, rs.next() (via profiledNext())

All are no-ops in production (guarded by ACTIVE.get() != null). Sample output with JDBC excluded:

  Step Timing Report — executeQuery path
  median of 100 concurrent requests — OJP overhead only, JDBC time excluded
  sessionConnection   |█████████░| 63,558 ns  (63.6 µs)   ← OJP session lookup
  statementCreation   |░░░░░░░░░░|  2,449 ns  ( 2.4 µs)   ← OJP wrapper only
  sqlExecution        |███████░░░| 49,272 ns  (49.3 µs)   ← registerResultSet + UUID
  resultSetHandling   |██████████|193,878 ns  (193.9 µs)  ← proto ResultRow building
  ─────────────────────────────────────────────────────────
  TOTAL               |██████████|313,736 ns  (313.7 µs)

vs. the previous totals that included JDBC time (~666 µs query, ~364 µs update). The ~353 µs and ~274 µs differences are the actual H2 JDBC costs that are now discounted.

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

• checkstyle.org
  • Triggering command: /opt/hostedtoolcache/CodeQL/2.25.1/x64/codeql/tools/linux64/java/bin/java /opt/hostedtoolcache/CodeQL/2.25.1/x64/codeql/tools/linux64/java/bin/java -jar /opt/hostedtoolcache/CodeQL/2.25.1/x64/codeql/xml/tools/xml-extractor.jar --fileList=/tmp/codeql-scratch-0fe3065af824c7c2/dbs/java/working/files-to-index2894002843515206904.list --sourceArchiveDir=/tmp/codeql-scratch-0fe3065af824c7c2/dbs/java/src --outputDir=/tmp/codeql-scratch-0fe3065af824c7c2/dbs/java/trap/java (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

• Configure Actions setup steps to set up my environment, which run before the firewall is enabled
• Add the appropriate URLs or hosts to the custom allowlist in this repository's Copilot coding agent settings (admins only)

[rrobetti]

@copilot merge main branch into this branch, add measurement steps if required. Document which main branch commit this branch is up to date with for future reference.

[sonarqubecloud]

Quality Gate passed

Issues
2 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

[Copilot]

@copilot merge main branch into this branch, add measurement steps if required. Document which main branch commit this branch is up to date with for future reference.

Done in commit 595edb8.

Main merged cleanly (no conflicts). The auto-merge correctly preserved all JDBC exclusion wrappers in SessionConnectionHelper. Two notes on the new code from main:

• The new acquireSessionPermit() call (admission semaphore wait) is intentionally not wrapped in beginJdbcCall/endJdbcCall — it is OJP admission-control time, not JDBC driver time, so it should be counted in the sessionConnection measurement.
• StartTransactionAction now routes through SessionConnectionHelper.sessionConnection(), so the JDBC exclusion is inherited automatically — no new measurement steps needed.

The benchmark test javadoc documents the sync point: main commit e59f4eb2 (Merge PR #520 – throttle incoming requests, 2026-05-15).

[rrobetti]

@copilot run the test again and plot the new results here.

[Copilot]

@copilot run the test again and plot the new results here.

Results from a fresh run (H2 in-memory, 100 concurrent threads, OJP overhead only — JDBC time excluded):

  Step Timing Report — executeQuery path
  median of 100 concurrent requests (H2 in-memory) — OJP overhead only, JDBC time excluded
  ------------------------------------------------------------------------------------------
  sessionConnection        |████████████████░░░░░░░░░░░░░░░░░░░░░░░░|   52,674 ns  ( 52.7 µs)
  cacheCheck               |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,482 ns  (  1.5 µs)
  sqlEnhancement           |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      816 ns  (  0.8 µs)
  paramConversion          |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,147 ns  (  1.1 µs)
  statementCreation        |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    1,778 ns  (  1.8 µs)
  sqlExecution             |████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░|   40,361 ns  ( 40.4 µs)
  resultSetHandling        |████████████████████████████████████████|  128,794 ns  (128.8 µs)
  ------------------------------------------------------------------------------------------
  TOTAL (sum of medians)                                                227,052 ns  (227.1 µs)

  Step Timing Report — executeUpdate path
  median of 100 concurrent requests (H2 in-memory) — OJP overhead only, JDBC time excluded
  ------------------------------------------------------------------------------------------
  affinityCheck            |████████████████████████████████████████|   50,887 ns  ( 50.9 µs)
  sessionConnection        |███░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    5,023 ns  (  5.0 µs)
  paramConversion          |██░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    3,245 ns  (  3.2 µs)
  statementCreation        |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      781 ns  (  0.8 µs)
  sqlExecution             |░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|      601 ns  (  0.6 µs)
  buildResult              |████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░|    5,263 ns  (  5.3 µs)
  ------------------------------------------------------------------------------------------
  TOTAL (sum of medians)                                                65,800 ns  ( 65.8 µs)

Key takeaways:

• executeQuery total OJP overhead: 227 µs — resultSetHandling (~129 µs, proto ResultRow building) and sessionConnection (~53 µs, session map lookup) dominate. sqlExecution (~40 µs) is pure OJP post-query work (registerResultSet + UUID).
• executeUpdate total OJP overhead: 66 µs — affinityCheck (~51 µs, regex parse) is the single largest cost. All other steps are sub-6 µs.