From ae20ffa0da55b5e7d4932ac4d75b19e113db7ca6 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 14 May 2026 13:56:22 +0000 Subject: [PATCH 1/5] feat: instrument executeQuery/executeUpdate paths with ns step timings and open-loop benchmark test Agent-Logs-Url: https://github.com/Open-J-Proxy/ojp/sessions/d969ea6a-97b9-4001-9fa9-41d0394edf22 Co-authored-by: rrobetti <7221783+rrobetti@users.noreply.github.com> --- .../transaction/ExecuteQueryAction.java | 12 + .../transaction/ExecuteUpdateAction.java | 10 + .../profiling/ExecutionPathProfiler.java | 93 ++++ .../ExecutionPathProfilingContext.java | 73 +++ .../ExecutePathLatencyBenchmarkTest.java | 474 ++++++++++++++++++ 5 files changed, 662 insertions(+) create mode 100644 ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java create mode 100644 ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java create mode 100644 ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java index 627ef2e82..25b37c893 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java @@ -21,6 +21,8 @@ import java.sql.Statement; import java.util.List; +import org.openjproxy.grpc.server.profiling.ExecutionPathProfilingContext; + import static org.openjproxy.grpc.server.action.session.ResultSetHelper.handleResultSet; import static org.openjproxy.grpc.server.action.streaming.SessionConnectionHelper.sessionConnection; import static org.openjproxy.grpc.server.action.transaction.CommandExecutionHelper.executeWithResilience; @@ -61,6 +63,7 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest throws SQLException { ConnectionSessionDTO dto = sessionConnection(actionContext, request.getSession(), true); + ExecutionPathProfilingContext.mark("sessionConnection"); // Phase 6: Cache Lookup (before query execution) - with graceful degradation String sql = request.getSql(); @@ -92,6 +95,7 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest // Continue to database execution } } + ExecutionPathProfilingContext.mark("cacheCheck"); // Phase 2: SQL Enhancement with timing long enhancementStartTime = System.nanoTime(); @@ -144,8 +148,10 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest log.debug("SQL enhancement took {}ms (no modifications)", enhancementDuration); } } + ExecutionPathProfilingContext.mark("sqlEnhancement"); List params = ProtoConverter.fromProtoList(request.getParametersList()); + ExecutionPathProfilingContext.mark("paramConversion"); // Phase 7: Wrap response observer for cache storage (if caching enabled) StreamObserver finalObserver = QueryCacheHelper.wrapWithCaching( @@ -153,13 +159,19 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest if (CollectionUtils.isNotEmpty(params)) { PreparedStatement ps = StatementFactory.createPreparedStatement(sessionManager, dto, sql, params, request); + ExecutionPathProfilingContext.mark("statementCreation"); String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), ps.executeQuery()); + ExecutionPathProfilingContext.mark("sqlExecution"); handleResultSet(actionContext, dto.getSession(), resultSetUUID, finalObserver); + ExecutionPathProfilingContext.mark("resultSetHandling"); } else { Statement stmt = StatementFactory.createStatement(sessionManager, dto.getConnection(), request); + ExecutionPathProfilingContext.mark("statementCreation"); String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), stmt.executeQuery(sql)); + ExecutionPathProfilingContext.mark("sqlExecution"); handleResultSet(actionContext, dto.getSession(), resultSetUUID, finalObserver); + ExecutionPathProfilingContext.mark("resultSetHandling"); } } } diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java index f1129d56a..d36497ed6 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java @@ -31,6 +31,8 @@ import java.util.List; import java.util.Map; +import org.openjproxy.grpc.server.profiling.ExecutionPathProfilingContext; + import static org.openjproxy.grpc.server.action.streaming.SessionConnectionHelper.sessionConnection; import static org.openjproxy.grpc.server.action.transaction.CommandExecutionHelper.executeWithResilience; @@ -112,17 +114,20 @@ private OpResult executeUpdateInternal(ActionContext actionContext, StatementReq // etc.) boolean requiresSessionAffinity = SqlSessionAffinityDetector.requiresSessionAffinity(request.getSql()); boolean requiresGeneratedKeys = StatementRequestValidator.requiresGeneratedKeysTracking(request); + ExecutionPathProfilingContext.mark("affinityCheck"); dto = sessionConnection(actionContext, request.getSession(), StatementRequestValidator.isAddBatchOperation(request) || requiresGeneratedKeys || requiresSessionAffinity); + ExecutionPathProfilingContext.mark("sessionConnection"); List params = ProtoConverter.fromProtoList(request.getParametersList()); PreparedStatement ps = dto.getSession() != null && StringUtils.isNotBlank(dto.getSession().getSessionUUID()) && StringUtils.isNoneBlank(request.getStatementUUID()) ? sessionManager.getPreparedStatement(dto.getSession(), request.getStatementUUID()) : null; + ExecutionPathProfilingContext.mark("paramConversion"); if (CollectionUtils.isNotEmpty(params) || ps != null || requiresGeneratedKeys) { if (StringUtils.isNotEmpty(request.getStatementUUID()) && ps != null) { @@ -132,21 +137,26 @@ private OpResult executeUpdateInternal(ActionContext actionContext, StatementReq request); generatedKeysUuid = registerForGeneratedKeys(sessionManager, dto, request, ps); } + ExecutionPathProfilingContext.mark("statementCreation"); if (StatementRequestValidator.isAddBatchOperation(request)) { psUUID = addBatchAndGetStatementUUID(sessionManager, dto, ps, request); } else { updated = ps.executeUpdate(); } + ExecutionPathProfilingContext.mark("sqlExecution"); stmt = ps; } else { stmt = StatementFactory.createStatement(sessionManager, dto.getConnection(), request); + ExecutionPathProfilingContext.mark("statementCreation"); updated = stmt.executeUpdate(request.getSql()); + ExecutionPathProfilingContext.mark("sqlExecution"); } OpResult result = buildOpResult(request, dto.getSession(), psUUID, updated, generatedKeysUuid); // Phase 9: Cache Invalidation (after successful update) org.openjproxy.grpc.server.cache.QueryCacheHelper.invalidateCacheIfEnabled(actionContext, dto.getSession(), request.getSql()); + ExecutionPathProfilingContext.mark("buildResult"); return result; } finally { diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java new file mode 100644 index 000000000..7b17bbe36 --- /dev/null +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java @@ -0,0 +1,93 @@ +package org.openjproxy.grpc.server.profiling; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; + +/** + * Records nanosecond-granularity timings for each named step in an execution path. + *

+ * Each call to {@link #mark(String)} records the elapsed nanoseconds since the + * previous mark (or since {@link #start()} if this is the first mark). This + * produces a sequential list of per-step durations. + *

+ *

+ * Instances are not thread-safe; create one per thread via + * {@link ExecutionPathProfilingContext}. + *

+ */ +public class ExecutionPathProfiler { + + /** Ordered list of step timings accumulated during one execution. */ + private final List timings = new ArrayList<>(); + + /** Nanosecond timestamp of the last mark (or start). */ + private long lastMarkNs; + + /** + * Sets the starting reference timestamp. Must be called before the first + * {@link #mark(String)} call. + */ + public void start() { + this.lastMarkNs = System.nanoTime(); + } + + /** + * Records the nanoseconds elapsed since the last mark (or since {@link #start()}) + * under the given step name, then advances the reference timestamp. + * + * @param stepName human-readable label for this step + */ + public void mark(String stepName) { + long now = System.nanoTime(); + timings.add(new StepTiming(stepName, now - lastMarkNs)); + lastMarkNs = now; + } + + /** + * Returns an unmodifiable view of all recorded step timings in insertion order. + * + * @return list of step timings + */ + public List getTimings() { + return Collections.unmodifiableList(timings); + } + + /** + * Immutable value object representing the duration of one named step. + */ + public static final class StepTiming { + + private final String stepName; + private final long durationNs; + + /** + * Creates a new StepTiming. + * + * @param stepName the name of the step + * @param durationNs the duration in nanoseconds + */ + public StepTiming(String stepName, long durationNs) { + this.stepName = stepName; + this.durationNs = durationNs; + } + + /** + * Returns the step name. + * + * @return step name + */ + public String getStepName() { + return stepName; + } + + /** + * Returns the step duration in nanoseconds. + * + * @return duration in nanoseconds + */ + public long getDurationNs() { + return durationNs; + } + } +} diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java new file mode 100644 index 000000000..e6138acba --- /dev/null +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java @@ -0,0 +1,73 @@ +package org.openjproxy.grpc.server.profiling; + +/** + * Thread-local holder for an active {@link ExecutionPathProfiler}. + *

+ * Production code calls {@link #mark(String)} at each instrumentation point; the + * call is a no-op unless a profiler has been {@link #activate(ExecutionPathProfiler) + * activated} on the current thread by a test or diagnostic harness. This design + * avoids any allocation or synchronization overhead in the production hot path. + *

+ * + *

Typical test usage

+ * 
{@code
+ * ExecutionPathProfiler profiler = new ExecutionPathProfiler();
+ * ExecutionPathProfilingContext.activate(profiler);
+ * try {
+ *     action.execute(context, request, observer);
+ * } finally {
+ *     ExecutionPathProfilingContext.deactivate();
+ * }
+ * profiler.getTimings().forEach(t ->
+ *     log.info("{}: {} ns", t.getStepName(), t.getDurationNs()));
+ * }
+ */ +public final class ExecutionPathProfilingContext { + + private static final ThreadLocal ACTIVE = new ThreadLocal<>(); + + /** Utility class — no instances. */ + private ExecutionPathProfilingContext() { + } + + /** + * Activates the given profiler on the current thread and starts its timer. + * + * @param profiler the profiler to activate; must not be {@code null} + */ + public static void activate(ExecutionPathProfiler profiler) { + profiler.start(); + ACTIVE.set(profiler); + } + + /** + * Deactivates the current profiler and removes it from the thread-local. + * Safe to call even when no profiler is active. + */ + public static void deactivate() { + ACTIVE.remove(); + } + + /** + * Returns {@code true} if a profiler is currently active on this thread. + * + * @return whether profiling is active + */ + public static boolean isActive() { + return ACTIVE.get() != null; + } + + /** + * Records elapsed nanoseconds for the named step on the active profiler. + * This is a no-op when no profiler is active. + * + * @param step the step label; use short, lowercase identifiers (e.g. + * {@code "sessionConnection"}, {@code "sqlExecution"}) + */ + public static void mark(String step) { + ExecutionPathProfiler profiler = ACTIVE.get(); + if (profiler != null) { + profiler.mark(step); + } + } +} diff --git a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java new file mode 100644 index 000000000..754555fe4 --- /dev/null +++ b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java @@ -0,0 +1,474 @@ +package org.openjproxy.grpc.server.profiling; + +import com.openjproxy.grpc.DbName; +import com.openjproxy.grpc.OpResult; +import com.openjproxy.grpc.SessionInfo; +import com.openjproxy.grpc.StatementRequest; +import io.grpc.stub.StreamObserver; +import org.junit.jupiter.api.AfterAll; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.Test; +import org.openjproxy.grpc.server.AdmissionControlManager; +import org.openjproxy.grpc.server.CircuitBreakerRegistry; +import org.openjproxy.grpc.server.ClusterHealthTracker; +import org.openjproxy.grpc.server.MultinodeXaCoordinator; +import org.openjproxy.grpc.server.ServerConfiguration; +import org.openjproxy.grpc.server.SessionManagerImpl; +import org.openjproxy.grpc.server.action.ActionContext; +import org.openjproxy.grpc.server.action.transaction.ExecuteQueryAction; +import org.openjproxy.grpc.server.action.transaction.ExecuteUpdateAction; +import org.openjproxy.grpc.server.metrics.SqlStatementMetrics; +import org.openjproxy.grpc.server.sql.SqlEnhancerEngine; +import org.openjproxy.xa.pool.spi.XAConnectionPoolProvider; + +import javax.sql.DataSource; +import java.sql.Connection; +import java.sql.DriverManager; +import java.sql.Statement; +import java.util.ArrayList; +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; +import java.util.stream.Collectors; + +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.Mockito.mock; + +/** + * Open-loop concurrency benchmark for the {@code executeQuery} and + * {@code executeUpdate} server-side action paths. + * + *

Fires {@value #CONCURRENT_REQUESTS} simultaneous requests at each path + * using an H2 in-memory database, records nanosecond-level timings for every + * instrumented step, then prints median latencies as an ASCII bar chart to + * stdout.

+ * + *

This test is for assessment purposes only and is not intended to be + * merged to the main branch.

+ * + *

executeQuery steps instrumented:

+ *
    + *
  1. {@code sessionConnection} – connection look-up from the session map (pre-created sessions)
    2. + *
  2. {@code cacheCheck} – query-result cache check (cache disabled here)
    3. + *
  3. {@code sqlEnhancement} – Calcite SQL enhancer (disabled here)
    4. + *
  4. {@code paramConversion} – proto-parameter deserialisation
    5. + *
  5. {@code statementCreation} – {@code Statement} / {@code PreparedStatement} creation
    6. + *
  6. {@code sqlExecution} – actual {@code executeQuery()} JDBC call
    7. + *
  7. {@code resultSetHandling} – row iteration and gRPC streaming
    8. + *
+ * + *

executeUpdate steps instrumented:

+ *
    + *
  1. {@code affinityCheck} – session-affinity and generated-keys detection
    2. + *
  2. {@code sessionConnection} – connection look-up from the session map (pre-created sessions)
    3. + *
  3. {@code paramConversion} – proto-parameter deserialisation + prepared-statement look-up
    4. + *
  4. {@code statementCreation} – {@code Statement} / {@code PreparedStatement} creation
    5. + *
  5. {@code sqlExecution} – actual {@code executeUpdate()} JDBC call
    6. + *
  6. {@code buildResult} – result object construction + cache invalidation
    7. + *
+ */ +class ExecutePathLatencyBenchmarkTest { + + // Number of concurrent requests fired in the open-loop burst + private static final int CONCURRENT_REQUESTS = 100; + // Number of sequential warmup iterations (JIT warm-up) + private static final int WARMUP_REQUESTS = 20; + // Total pre-created sessions = warmup + concurrent + private static final int TOTAL_SESSIONS = WARMUP_REQUESTS + CONCURRENT_REQUESTS; + + private static final String DB_URL = "jdbc:h2:mem:profiling_bench;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE"; + private static final String CONN_HASH = "benchmark-h2"; + // Large multiplier to avoid row-ID collisions between the warmup and concurrent runs + private static final int UPDATE_ID_MULTIPLIER = 100_000; + private static final String SELECT_SQL = "SELECT id, val FROM bench"; + + private static ActionContext actionContext; + /** Pre-created sessions indexed [0 .. TOTAL_SESSIONS). */ + private static final List PRE_SESSIONS = new ArrayList<>(TOTAL_SESSIONS); + /** Direct H2 connections backing each pre-created session; closed in teardown. */ + private static final List PRE_CONNECTIONS = new ArrayList<>(TOTAL_SESSIONS); + + // ----------------------------------------------------------------------- + // Lifecycle + // ----------------------------------------------------------------------- + + @BeforeAll + static void setUpAll() throws Exception { + // Bootstrap table via a standalone connection + try (Connection bootstrap = DriverManager.getConnection(DB_URL, "sa", "")) { + try (Statement stmt = bootstrap.createStatement()) { + stmt.execute("CREATE TABLE IF NOT EXISTS bench (id INT, val VARCHAR(100))"); + stmt.execute("DELETE FROM bench"); + for (int i = 1; i <= 10; i++) { + stmt.execute("INSERT INTO bench (id, val) VALUES (" + i + ", 'row" + i + "')"); + } + } + } + + ServerConfiguration serverConfiguration = new ServerConfiguration(); + SessionManagerImpl sessionManager = new SessionManagerImpl(new ConcurrentHashMap<>()); + + // Pre-create one direct H2 connection per virtual client and register a session + for (int i = 0; i < TOTAL_SESSIONS; i++) { + String clientUUID = clientUUID(i); + sessionManager.registerClientUUID(CONN_HASH, clientUUID); + Connection conn = DriverManager.getConnection(DB_URL, "sa", ""); + PRE_CONNECTIONS.add(conn); + SessionInfo session = sessionManager.createSession(clientUUID, conn); + PRE_SESSIONS.add(session); + } + + // datasourceMap left empty: all sessions are pre-created, so no pool acquisition occurs. + Map datasourceMap = new ConcurrentHashMap<>(); + Map admissionManagers = new ConcurrentHashMap<>(); + // Disabled admission control so that slot queuing is excluded from the measured steps. + // Parameters: totalSlots=TOTAL_SESSIONS, slowSlotPct=0 (disabled), idleTimeoutMs=0, + // slowSlotTimeoutMs=0, fastSlotTimeoutMs=0, enabled=false + admissionManagers.put(CONN_HASH, + new AdmissionControlManager(TOTAL_SESSIONS, 0, 0, 0, 0, false)); + + Map dbNameMap = new ConcurrentHashMap<>(); + dbNameMap.put(CONN_HASH, DbName.H2); + + CircuitBreakerRegistry circuitBreakerRegistry = new CircuitBreakerRegistry( + serverConfiguration.getCircuitBreakerTimeout(), + serverConfiguration.getCircuitBreakerThreshold()); + + SqlStatementMetrics noopMetrics = new SqlStatementMetrics() { + @Override + public void recordSqlExecution(String sql, long executionTimeMs, boolean isSlow) { + // no-op for benchmark + } + + @Override + public void close() { + // no-op + } + }; + + actionContext = new ActionContext( + datasourceMap, + new ConcurrentHashMap<>(), + new ConcurrentHashMap<>(), + new ConcurrentHashMap<>(), + dbNameMap, + admissionManagers, + new ConcurrentHashMap<>(), + mock(XAConnectionPoolProvider.class), + new MultinodeXaCoordinator(), + new ClusterHealthTracker(), + sessionManager, + circuitBreakerRegistry, + serverConfiguration, + noopMetrics, + new SqlEnhancerEngine(false)); + } + + @AfterAll + static void tearDownAll() throws Exception { + for (Connection conn : PRE_CONNECTIONS) { + if (conn != null && !conn.isClosed()) { + conn.close(); + } + } + } + + // ----------------------------------------------------------------------- + // Benchmark tests + // ----------------------------------------------------------------------- + + @Test + void shouldBenchmarkExecuteQueryPath() throws Exception { + System.out.println("\n=== executeQuery benchmark ==="); + + // Sequential warmup using the first WARMUP_REQUESTS sessions + runExecuteQuerySequential(0, WARMUP_REQUESTS); + System.out.println("[warmup done: " + WARMUP_REQUESTS + " sequential requests]"); + + // Concurrent open-loop burst using the remaining CONCURRENT_REQUESTS sessions + List profilers = runExecuteQueryConcurrent(WARMUP_REQUESTS); + + assertTrue(profilers.stream().noneMatch(p -> p == null || p.getTimings().isEmpty()), + "All profilers should have recorded timings"); + printReport("executeQuery path", profilers); + } + + @Test + void shouldBenchmarkExecuteUpdatePath() throws Exception { + System.out.println("\n=== executeUpdate benchmark ==="); + + // Sequential warmup + runExecuteUpdateSequential(0, WARMUP_REQUESTS); + System.out.println("[warmup done: " + WARMUP_REQUESTS + " sequential requests]"); + + // Concurrent open-loop burst + List profilers = runExecuteUpdateConcurrent(WARMUP_REQUESTS); + + assertTrue(profilers.stream().noneMatch(p -> p == null || p.getTimings().isEmpty()), + "All profilers should have recorded timings"); + printReport("executeUpdate path", profilers); + } + + // ----------------------------------------------------------------------- + // executeQuery helpers + // ----------------------------------------------------------------------- + + private void runExecuteQuerySequential(int startIdx, int count) throws Exception { + for (int i = startIdx; i < startIdx + count; i++) { + StatementRequest request = StatementRequest.newBuilder() + .setSession(PRE_SESSIONS.get(i)) + .setSql(SELECT_SQL) + .build(); + ExecuteQueryAction.getInstance().execute(actionContext, request, new DroppingObserver()); + } + } + + /** + * Fires {@value #CONCURRENT_REQUESTS} executeQuery requests simultaneously from + * {@code startIdx} onward. Returns one profiler per request. + */ + private List runExecuteQueryConcurrent(int startIdx) throws Exception { + return runConcurrentBurst(startIdx, CONCURRENT_REQUESTS, idx -> { + StatementRequest request = StatementRequest.newBuilder() + .setSession(PRE_SESSIONS.get(idx)) + .setSql(SELECT_SQL) + .build(); + ExecuteQueryAction.getInstance().execute(actionContext, request, new DroppingObserver()); + }); + } + + // ----------------------------------------------------------------------- + // executeUpdate helpers + // ----------------------------------------------------------------------- + + private void runExecuteUpdateSequential(int startIdx, int count) throws Exception { + for (int i = startIdx; i < startIdx + count; i++) { + String sql = buildInsertSql(i); + StatementRequest request = StatementRequest.newBuilder() + .setSession(PRE_SESSIONS.get(i)) + .setSql(sql) + .build(); + ExecuteUpdateAction.getInstance().execute(actionContext, request, new DroppingObserver()); + } + } + + /** + * Fires {@value #CONCURRENT_REQUESTS} executeUpdate requests simultaneously from + * {@code startIdx} onward. Returns one profiler per request. + */ + private List runExecuteUpdateConcurrent(int startIdx) throws Exception { + return runConcurrentBurst(startIdx, CONCURRENT_REQUESTS, idx -> { + String sql = buildInsertSql(idx * UPDATE_ID_MULTIPLIER); + StatementRequest request = StatementRequest.newBuilder() + .setSession(PRE_SESSIONS.get(idx)) + .setSql(sql) + .build(); + ExecuteUpdateAction.getInstance().execute(actionContext, request, new DroppingObserver()); + }); + } + + private static String buildInsertSql(int id) { + return "INSERT INTO bench (id, val) VALUES (" + id + ", 'bench')"; + } + + // ----------------------------------------------------------------------- + // Generic open-loop burst driver + // ----------------------------------------------------------------------- + + /** + * Runs {@code count} tasks simultaneously (open-loop burst) starting at + * session index {@code startIdx}, activating a per-thread + * {@link ExecutionPathProfiler} before each invocation. + * + * @param startIdx first session index to use + * @param count number of concurrent tasks + * @param task action to execute; receives the absolute session index + * @return profilers from all {@code count} tasks in index order + */ + private List runConcurrentBurst(int startIdx, int count, BenchTask task) + throws Exception { + + List profilers = + new ArrayList<>(Collections.nCopies(count, null)); + List> errors = new ArrayList<>(count); + for (int i = 0; i < count; i++) { + errors.add(new AtomicReference<>()); + } + + CountDownLatch startGate = new CountDownLatch(1); + CountDownLatch doneLatch = new CountDownLatch(count); + ExecutorService executor = Executors.newFixedThreadPool(count); + + for (int i = 0; i < count; i++) { + final int taskIdx = startIdx + i; + final int resultIdx = i; + executor.submit(() -> { + try { + startGate.await(); + ExecutionPathProfiler profiler = new ExecutionPathProfiler(); + ExecutionPathProfilingContext.activate(profiler); + try { + task.run(taskIdx); + } finally { + ExecutionPathProfilingContext.deactivate(); + } + profilers.set(resultIdx, profiler); + } catch (InterruptedException ie) { + Thread.currentThread().interrupt(); + errors.get(resultIdx).set(ie); + } catch (Exception e) { + errors.get(resultIdx).set(e); + } finally { + doneLatch.countDown(); + } + }); + } + + // Open loop: release all threads simultaneously + startGate.countDown(); + boolean completed = doneLatch.await(60, TimeUnit.SECONDS); + executor.shutdown(); + + assertTrue(completed, "Benchmark burst did not finish within 60 s"); + for (int i = 0; i < count; i++) { + Exception err = errors.get(i).get(); + if (err != null) { + throw new AssertionError("Thread " + i + " failed: " + err.getMessage(), err); + } + } + return profilers; + } + + // ----------------------------------------------------------------------- + // Reporting: collect medians and print ASCII bar chart + // ----------------------------------------------------------------------- + + /** + * Aggregates per-step nanosecond timings from all profilers, computes the + * median across {@value #CONCURRENT_REQUESTS} samples for each step, and + * prints an ASCII bar chart. + */ + private void printReport(String title, List profilers) { + // Collect durations per step (preserve insertion order via LinkedHashMap) + Map> stepData = new LinkedHashMap<>(); + for (ExecutionPathProfiler profiler : profilers) { + for (ExecutionPathProfiler.StepTiming timing : profiler.getTimings()) { + stepData.computeIfAbsent(timing.getStepName(), k -> new ArrayList<>()) + .add(timing.getDurationNs()); + } + } + + // Compute medians + Map medians = new LinkedHashMap<>(); + for (Map.Entry> entry : stepData.entrySet()) { + List sorted = entry.getValue().stream().sorted().collect(Collectors.toList()); + int mid = sorted.size() / 2; + long median = sorted.size() % 2 == 0 + ? (sorted.get(mid - 1) + sorted.get(mid)) / 2 + : sorted.get(mid); + medians.put(entry.getKey(), median); + } + + long maxMedian = medians.values().stream().mapToLong(Long::longValue).max().orElse(1L); + + int barWidth = 40; + int labelWidth = medians.keySet().stream().mapToInt(String::length).max().orElse(10) + 2; + int totalWidth = barWidth + labelWidth + 26; + + System.out.println(); + System.out.println(center("Step Timing Report — " + title, totalWidth)); + System.out.println(center("median of " + CONCURRENT_REQUESTS + " concurrent requests (H2 in-memory)", totalWidth)); + System.out.println(repeat("-", totalWidth)); + + for (Map.Entry entry : medians.entrySet()) { + String step = entry.getKey(); + long medNs = entry.getValue(); + int bars = maxMedian == 0 ? 0 : (int) ((double) medNs / maxMedian * barWidth); + String bar = repeat("█", bars) + repeat("░", barWidth - bars); + System.out.printf(" %-" + labelWidth + "s |%s| %,9d ns (%,.3f µs)%n", + step, bar, medNs, medNs / 1_000.0); + } + System.out.println(repeat("-", totalWidth)); + + // Summary line + String heaviest = medians.entrySet().stream() + .max(Map.Entry.comparingByValue()) + .map(Map.Entry::getKey) + .orElse("?"); + long totalNs = medians.values().stream().mapToLong(Long::longValue).sum(); + System.out.printf(" Heaviest step: %-20s Total instrumented: %,d ns (%,.3f µs)%n", + heaviest, totalNs, totalNs / 1_000.0); + System.out.println(); + } + + // ----------------------------------------------------------------------- + // Utilities + // ----------------------------------------------------------------------- + + private static String clientUUID(int index) { + return "bench-client-" + index; + } + + private static String repeat(String s, int count) { + if (count <= 0) { + return ""; + } + StringBuilder sb = new StringBuilder(count * s.length()); + for (int i = 0; i < count; i++) { + sb.append(s); + } + return sb.toString(); + } + + private static String center(String text, int width) { + int pad = Math.max(0, (width - text.length()) / 2); + return repeat(" ", pad) + text; + } + + // ----------------------------------------------------------------------- + // Inner types + // ----------------------------------------------------------------------- + + /** + * Task interface used by the open-loop burst driver. + * Receives the session index and may throw checked exceptions. + */ + @FunctionalInterface + interface BenchTask { + /** + * Executes one benchmark iteration for the given session index. + * + * @param sessionIdx session index into {@link #PRE_SESSIONS} + * @throws Exception on any error + */ + void run(int sessionIdx) throws Exception; + } + + /** + * gRPC {@link StreamObserver} that silently discards all results, used to + * avoid test-framework noise in the benchmark loop. + */ + private static final class DroppingObserver implements StreamObserver { + @Override + public void onNext(OpResult value) { + // intentionally discarded + } + + @Override + public void onError(Throwable t) { + // errors handled via AtomicReference in the burst driver + } + + @Override + public void onCompleted() { + // intentionally discarded + } + } +} From 0bbae43f76824b067cca95cb07195eee1a9b80b2 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 14 May 2026 14:35:07 +0000 Subject: [PATCH 2/5] feat(profiling): add TOTAL row (sum of medians) to benchmark step timing report Agent-Logs-Url: https://github.com/Open-J-Proxy/ojp/sessions/fa4fda8a-b0c0-4f5d-8ccf-51f13e842448 Co-authored-by: rrobetti <7221783+rrobetti@users.noreply.github.com> --- .../ExecutePathLatencyBenchmarkTest.java | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java index 754555fe4..4ff90aa61 100644 --- a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java +++ b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java @@ -379,7 +379,10 @@ private void printReport(String title, List profilers) { long maxMedian = medians.values().stream().mapToLong(Long::longValue).max().orElse(1L); int barWidth = 40; - int labelWidth = medians.keySet().stream().mapToInt(String::length).max().orElse(10) + 2; + String totalRowLabel = "TOTAL (sum of medians)"; + int labelWidth = Math.max( + medians.keySet().stream().mapToInt(String::length).max().orElse(10), + totalRowLabel.length()) + 2; int totalWidth = barWidth + labelWidth + 26; System.out.println(); @@ -395,6 +398,13 @@ private void printReport(String title, List profilers) { System.out.printf(" %-" + labelWidth + "s |%s| %,9d ns (%,.3f µs)%n", step, bar, medNs, medNs / 1_000.0); } + + long totalNs = medians.values().stream().mapToLong(Long::longValue).sum(); + System.out.println(repeat("-", totalWidth)); + int totalBars = maxMedian == 0 ? 0 : (int) Math.min((double) totalNs / maxMedian * barWidth, barWidth); + String totalBar = repeat("█", totalBars) + repeat("░", barWidth - totalBars); + System.out.printf(" %-" + labelWidth + "s |%s| %,9d ns (%,.3f µs)%n", + totalRowLabel, totalBar, totalNs, totalNs / 1_000.0); System.out.println(repeat("-", totalWidth)); // Summary line @@ -402,9 +412,7 @@ private void printReport(String title, List profilers) { .max(Map.Entry.comparingByValue()) .map(Map.Entry::getKey) .orElse("?"); - long totalNs = medians.values().stream().mapToLong(Long::longValue).sum(); - System.out.printf(" Heaviest step: %-20s Total instrumented: %,d ns (%,.3f µs)%n", - heaviest, totalNs, totalNs / 1_000.0); + System.out.printf(" Heaviest step: %s%n", heaviest); System.out.println(); } From 2454178982e5ae905114b1ec81686966bff5888e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 15 May 2026 08:57:41 +0000 Subject: [PATCH 3/5] feat(profiling): exclude JDBC driver time from step measurements; show OJP-only overhead Agent-Logs-Url: https://github.com/Open-J-Proxy/ojp/sessions/ae46c7a0-3adb-4253-8466-cbd9526738bf Co-authored-by: rrobetti <7221783+rrobetti@users.noreply.github.com> --- .../action/session/ResultSetHelper.java | 17 +++++++-- .../streaming/SessionConnectionHelper.java | 16 +++++++-- .../transaction/ExecuteQueryAction.java | 16 +++++++-- .../transaction/ExecuteUpdateAction.java | 8 +++++ .../profiling/ExecutionPathProfiler.java | 14 ++++++++ .../ExecutionPathProfilingContext.java | 35 +++++++++++++++++++ .../ExecutePathLatencyBenchmarkTest.java | 2 +- 7 files changed, 100 insertions(+), 8 deletions(-) diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java index ea30c9305..bad81030f 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java @@ -13,6 +13,7 @@ import org.openjproxy.grpc.server.HydratedResultSetMetadata; import org.openjproxy.grpc.server.action.ActionContext; import org.openjproxy.grpc.server.lob.LobProcessor; +import org.openjproxy.grpc.server.profiling.ExecutionPathProfilingContext; import org.openjproxy.grpc.server.resultset.ResultSetWrapper; import org.openjproxy.grpc.server.utils.DateTimeUtils; @@ -80,23 +81,31 @@ public static void handleResultSet(ActionContext context, SessionInfo session, S var sessionManager = context.getSessionManager(); ResultSet rs = sessionManager.getResultSet(session, resultSetUUID); + ExecutionPathProfilingContext.beginJdbcCall(); int columnCount = rs.getMetaData().getColumnCount(); List labels = new ArrayList<>(); for (int i = 0; i < columnCount; i++) { labels.add(rs.getMetaData().getColumnName(i + 1)); } + ExecutionPathProfilingContext.endJdbcCall(); List results = new ArrayList<>(); int row = 0; boolean justSent = false; - DbName dbName = DatabaseUtils.resolveDbName(rs.getStatement().getConnection().getMetaData().getURL()); // Only used if result set contains LOBs in SQL Server and DB2 (if LOB's // present), so cursor is not read in advance, // every row has to be requested by the jdbc client. String resultSetMode = ""; boolean resultSetMetadataCollected = false; - while (rs.next()) { + ExecutionPathProfilingContext.beginJdbcCall(); + DbName dbName = DatabaseUtils.resolveDbName(rs.getStatement().getConnection().getMetaData().getURL()); + ExecutionPathProfilingContext.endJdbcCall(); + + ExecutionPathProfilingContext.beginJdbcCall(); + boolean rowAvailable = rs.next(); + ExecutionPathProfilingContext.endJdbcCall(); + while (rowAvailable) { if (DbName.DB2.equals(dbName) && !resultSetMetadataCollected) { collectResultSetMetadata(context, session, resultSetUUID, rs); } @@ -211,6 +220,10 @@ public static void handleResultSet(ActionContext context, SessionInfo session, S labels = null; // Labels only included in the first block results = new ArrayList<>(); } + + ExecutionPathProfilingContext.beginJdbcCall(); + rowAvailable = rs.next(); + ExecutionPathProfilingContext.endJdbcCall(); } if (!justSent) { diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/streaming/SessionConnectionHelper.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/streaming/SessionConnectionHelper.java index c43c535e1..881116c0e 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/streaming/SessionConnectionHelper.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/streaming/SessionConnectionHelper.java @@ -16,6 +16,8 @@ import java.sql.Connection; import java.sql.SQLException; +import org.openjproxy.grpc.server.profiling.ExecutionPathProfilingContext; + /** * Utility class for managing database connections within gRPC streaming * sessions. @@ -102,8 +104,12 @@ public static ConnectionSessionDTO sessionConnection(ActionContext context, Sess if (conn == null) { throw new SQLException("Connection not found for this sessionInfo"); } - dtoBuilder.dbName(DatabaseUtils.resolveDbName(conn.getMetaData().getURL())); - if (conn.isClosed()) { + ExecutionPathProfilingContext.beginJdbcCall(); + String dbUrl = conn.getMetaData().getURL(); + boolean connClosed = conn.isClosed(); + ExecutionPathProfilingContext.endJdbcCall(); + dtoBuilder.dbName(DatabaseUtils.resolveDbName(dbUrl)); + if (connClosed) { throw new SQLException("Connection is closed"); } } else { @@ -119,8 +125,10 @@ public static ConnectionSessionDTO sessionConnection(ActionContext context, Sess // Unpooled XA mode: create XAConnection on demand try { log.debug("Creating unpooled XAConnection for hash: {}", connHash); + ExecutionPathProfilingContext.beginJdbcCall(); XAConnection xaConnection = xaDataSource.getXAConnection(); conn = xaConnection.getConnection(); + ExecutionPathProfilingContext.endJdbcCall(); // Store the XAConnection in session for XA operations if (startSessionIfNone) { @@ -149,10 +157,12 @@ public static ConnectionSessionDTO sessionConnection(ActionContext context, Sess // Unpooled mode: create direct connection without pooling try { log.debug("Creating unpooled (passthrough) connection for hash: {}", connHash); + ExecutionPathProfilingContext.beginJdbcCall(); conn = java.sql.DriverManager.getConnection( unpooledDetails.getUrl(), unpooledDetails.getUsername(), unpooledDetails.getPassword()); + ExecutionPathProfilingContext.endJdbcCall(); log.debug("Successfully created unpooled connection for hash: {}", connHash); } catch (SQLException e) { log.error("Failed to create unpooled connection for hash: {}. Error: {}", @@ -171,7 +181,9 @@ public static ConnectionSessionDTO sessionConnection(ActionContext context, Sess try { // Use enhanced connection acquisition with timeout protection + ExecutionPathProfilingContext.beginJdbcCall(); conn = ConnectionAcquisitionManager.acquireConnection(dataSource, connHash); + ExecutionPathProfilingContext.endJdbcCall(); log.debug("Successfully acquired connection from pool for hash: {}", connHash); } catch (SQLException e) { log.error("Failed to acquire connection from pool for hash: {}. Error: {}", diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java index 25b37c893..1933be2a6 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java @@ -17,6 +17,7 @@ import javax.sql.DataSource; import java.sql.Connection; import java.sql.PreparedStatement; +import java.sql.ResultSet; import java.sql.SQLException; import java.sql.Statement; import java.util.List; @@ -158,17 +159,26 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest responseObserver, cacheConfig, sql, params, dto.getSession().getConnHash()); if (CollectionUtils.isNotEmpty(params)) { + ExecutionPathProfilingContext.beginJdbcCall(); PreparedStatement ps = StatementFactory.createPreparedStatement(sessionManager, dto, sql, params, request); + ExecutionPathProfilingContext.endJdbcCall(); ExecutionPathProfilingContext.mark("statementCreation"); - String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), ps.executeQuery()); + ExecutionPathProfilingContext.beginJdbcCall(); + ResultSet rs = ps.executeQuery(); + ExecutionPathProfilingContext.endJdbcCall(); + String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), rs); ExecutionPathProfilingContext.mark("sqlExecution"); handleResultSet(actionContext, dto.getSession(), resultSetUUID, finalObserver); ExecutionPathProfilingContext.mark("resultSetHandling"); } else { + ExecutionPathProfilingContext.beginJdbcCall(); Statement stmt = StatementFactory.createStatement(sessionManager, dto.getConnection(), request); + ExecutionPathProfilingContext.endJdbcCall(); ExecutionPathProfilingContext.mark("statementCreation"); - String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), - stmt.executeQuery(sql)); + ExecutionPathProfilingContext.beginJdbcCall(); + ResultSet rs = stmt.executeQuery(sql); + ExecutionPathProfilingContext.endJdbcCall(); + String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), rs); ExecutionPathProfilingContext.mark("sqlExecution"); handleResultSet(actionContext, dto.getSession(), resultSetUUID, finalObserver); ExecutionPathProfilingContext.mark("resultSetHandling"); diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java index d36497ed6..2bb79b174 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteUpdateAction.java @@ -133,22 +133,30 @@ private OpResult executeUpdateInternal(ActionContext actionContext, StatementReq if (StringUtils.isNotEmpty(request.getStatementUUID()) && ps != null) { bindLobsAndParameters(sessionManager, dto, ps, params); } else { + ExecutionPathProfilingContext.beginJdbcCall(); ps = StatementFactory.createPreparedStatement(sessionManager, dto, request.getSql(), params, request); + ExecutionPathProfilingContext.endJdbcCall(); generatedKeysUuid = registerForGeneratedKeys(sessionManager, dto, request, ps); } ExecutionPathProfilingContext.mark("statementCreation"); if (StatementRequestValidator.isAddBatchOperation(request)) { psUUID = addBatchAndGetStatementUUID(sessionManager, dto, ps, request); } else { + ExecutionPathProfilingContext.beginJdbcCall(); updated = ps.executeUpdate(); + ExecutionPathProfilingContext.endJdbcCall(); } ExecutionPathProfilingContext.mark("sqlExecution"); stmt = ps; } else { + ExecutionPathProfilingContext.beginJdbcCall(); stmt = StatementFactory.createStatement(sessionManager, dto.getConnection(), request); + ExecutionPathProfilingContext.endJdbcCall(); ExecutionPathProfilingContext.mark("statementCreation"); + ExecutionPathProfilingContext.beginJdbcCall(); updated = stmt.executeUpdate(request.getSql()); + ExecutionPathProfilingContext.endJdbcCall(); ExecutionPathProfilingContext.mark("sqlExecution"); } diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java index 7b17bbe36..d2c66c050 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java @@ -44,6 +44,20 @@ public void mark(String stepName) { lastMarkNs = now; } + /** + * Advances the reference timestamp by {@code ns} nanoseconds, effectively + * excluding that duration from the current step's measurement window. + *

+ * Use this to discount time spent inside external JDBC calls so that the + * subsequent {@link #mark(String)} records only OJP-internal overhead. + *

+ * + * @param ns nanoseconds to exclude from the current step's elapsed time + */ + public void excludeNs(long ns) { + this.lastMarkNs += ns; + } + /** * Returns an unmodifiable view of all recorded step timings in insertion order. * diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java index e6138acba..65a1d3571 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java @@ -26,6 +26,9 @@ public final class ExecutionPathProfilingContext { private static final ThreadLocal ACTIVE = new ThreadLocal<>(); + /** Start timestamp (ns) recorded by {@link #beginJdbcCall()}. */ + private static final ThreadLocal JDBC_CALL_START = new ThreadLocal<>(); + /** Utility class — no instances. */ private ExecutionPathProfilingContext() { } @@ -46,6 +49,7 @@ public static void activate(ExecutionPathProfiler profiler) { */ public static void deactivate() { ACTIVE.remove(); + JDBC_CALL_START.remove(); } /** @@ -70,4 +74,35 @@ public static void mark(String step) { profiler.mark(step); } } + + /** + * Marks the start of a JDBC driver call whose duration should be excluded + * from the current step's OJP measurement. + *

+ * Must be paired with a subsequent {@link #endJdbcCall()}. This is a no-op + * when no profiler is active. + *

+ */ + public static void beginJdbcCall() { + if (ACTIVE.get() != null) { + JDBC_CALL_START.set(System.nanoTime()); + } + } + + /** + * Marks the end of a JDBC driver call and subtracts its duration from the + * current step's measurement window so that only OJP-internal time is counted. + *

+ * Safe to call even when {@link #beginJdbcCall()} was not called first (no-op + * in that case). + *

+ */ + public static void endJdbcCall() { + ExecutionPathProfiler profiler = ACTIVE.get(); + Long start = JDBC_CALL_START.get(); + if (profiler != null && start != null) { + profiler.excludeNs(System.nanoTime() - start); + JDBC_CALL_START.remove(); + } + } } diff --git a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java index 4ff90aa61..5d840b63b 100644 --- a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java +++ b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java @@ -387,7 +387,7 @@ private void printReport(String title, List profilers) { System.out.println(); System.out.println(center("Step Timing Report — " + title, totalWidth)); - System.out.println(center("median of " + CONCURRENT_REQUESTS + " concurrent requests (H2 in-memory)", totalWidth)); + System.out.println(center("median of " + CONCURRENT_REQUESTS + " concurrent requests (H2 in-memory) — OJP overhead only, JDBC time excluded", totalWidth)); System.out.println(repeat("-", totalWidth)); for (Map.Entry entry : medians.entrySet()) { From 50e7da6c6f5794f6706d09795b7871878e31768c Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 15 May 2026 09:02:16 +0000 Subject: [PATCH 4/5] refactor(profiling): extract profiledNext() helper; document non-nesting in beginJdbcCall Agent-Logs-Url: https://github.com/Open-J-Proxy/ojp/sessions/ae46c7a0-3adb-4253-8466-cbd9526738bf Co-authored-by: rrobetti <7221783+rrobetti@users.noreply.github.com> --- .../action/session/ResultSetHelper.java | 27 ++++++++++++++----- .../ExecutionPathProfilingContext.java | 4 ++- 2 files changed, 24 insertions(+), 7 deletions(-) diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java index bad81030f..db8de39cf 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/action/session/ResultSetHelper.java @@ -102,9 +102,7 @@ public static void handleResultSet(ActionContext context, SessionInfo session, S DbName dbName = DatabaseUtils.resolveDbName(rs.getStatement().getConnection().getMetaData().getURL()); ExecutionPathProfilingContext.endJdbcCall(); - ExecutionPathProfilingContext.beginJdbcCall(); - boolean rowAvailable = rs.next(); - ExecutionPathProfilingContext.endJdbcCall(); + boolean rowAvailable = profiledNext(rs); while (rowAvailable) { if (DbName.DB2.equals(dbName) && !resultSetMetadataCollected) { collectResultSetMetadata(context, session, resultSetUUID, rs); @@ -221,9 +219,7 @@ public static void handleResultSet(ActionContext context, SessionInfo session, S results = new ArrayList<>(); } - ExecutionPathProfilingContext.beginJdbcCall(); - rowAvailable = rs.next(); - ExecutionPathProfilingContext.endJdbcCall(); + rowAvailable = profiledNext(rs); } if (!justSent) { @@ -275,4 +271,23 @@ private static void collectResultSetMetadata(ActionContext context, SessionInfo context.getSessionManager().registerAttr(session, RESULT_SET_METADATA_ATTR_PREFIX + resultSetUUID, new HydratedResultSetMetadata(rs.getMetaData())); } + + /** + * Advances the result set cursor and excludes the JDBC call time from the + * current profiling step. This is a no-op in production (when no profiler is + * active). + * + * @param rs the result set to advance + * @return {@code true} if the new current row is valid, {@code false} if there + * are no more rows + * @throws SQLException if a database access error occurs + */ + private static boolean profiledNext(ResultSet rs) throws SQLException { + ExecutionPathProfilingContext.beginJdbcCall(); + try { + return rs.next(); + } finally { + ExecutionPathProfilingContext.endJdbcCall(); + } + } } diff --git a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java index 65a1d3571..a62dbff6a 100644 --- a/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java +++ b/ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfilingContext.java @@ -79,7 +79,9 @@ public static void mark(String step) { * Marks the start of a JDBC driver call whose duration should be excluded * from the current step's OJP measurement. *

- * Must be paired with a subsequent {@link #endJdbcCall()}. This is a no-op + * Must be paired with a subsequent {@link #endJdbcCall()}. Nesting is not + * supported: a second {@code beginJdbcCall()} before a matching + * {@code endJdbcCall()} will overwrite the first timestamp. This is a no-op * when no profiler is active. *

*/ From 595edb887846ec708cce7266bce4e624b356f2b1 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 15 May 2026 21:38:18 +0000 Subject: [PATCH 5/5] chore: merge main (e59f4eb2) into profiling branch; document sync commit; verify new SessionConnectionHelper paths retain JDBC exclusion Agent-Logs-Url: https://github.com/Open-J-Proxy/ojp/sessions/b7032520-e5f1-4616-9ed0-df63436dd35e Co-authored-by: rrobetti <7221783+rrobetti@users.noreply.github.com> --- .../grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java index 5d840b63b..bfbb43e12 100644 --- a/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java +++ b/ojp-server/src/test/java/org/openjproxy/grpc/server/profiling/ExecutePathLatencyBenchmarkTest.java @@ -53,6 +53,9 @@ *

This test is for assessment purposes only and is not intended to be * merged to the main branch.

* + *

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

+ * *

executeQuery steps instrumented:

*
    *
  1. {@code sessionConnection} – connection look-up from the session map (pre-created sessions)