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

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,29 @@ 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<String> labels = new ArrayList<>();
         for (int i = 0; i < columnCount; i++) {
             labels.add(rs.getMetaData().getColumnName(i + 1));
         }
+        ExecutionPathProfilingContext.endJdbcCall();
 
         List<ResultRow> 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();
+
+        boolean rowAvailable = profiledNext(rs);
+        while (rowAvailable) {
             if (DbName.DB2.equals(dbName) && !resultSetMetadataCollected) {
                 collectResultSetMetadata(context, session, resultSetUUID, rs);
             }
@@ -211,6 +218,8 @@ public static void handleResultSet(ActionContext context, SessionInfo session, S
                 labels = null; // Labels only included in the first block
                 results = new ArrayList<>();
             }
+
+            rowAvailable = profiledNext(rs);
         }
 
         if (!justSent) {
@@ -262,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();
+        }
+    }
 }

ojp-server/src/main/java/org/openjproxy/grpc/server/action/streaming/SessionConnectionHelper.java

@@ -18,6 +18,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.
@@ -104,8 +106,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 {
@@ -121,8 +127,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) {
@@ -152,10 +160,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: {}",
@@ -184,7 +194,9 @@ public static ConnectionSessionDTO sessionConnection(ActionContext context, Sess
                         }
 
                         // 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);
 
                         if (startSessionIfNone) {

ojp-server/src/main/java/org/openjproxy/grpc/server/action/transaction/ExecuteQueryAction.java

@@ -17,10 +17,13 @@
 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;
 
+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 +64,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 +96,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,22 +149,39 @@ private void executeQueryInternal(ActionContext actionContext, StatementRequest
                 log.debug("SQL enhancement took {}ms (no modifications)", enhancementDuration);
             }
         }
+        ExecutionPathProfilingContext.mark("sqlEnhancement");
 
         List<Parameter> params = ProtoConverter.fromProtoList(request.getParametersList());
+        ExecutionPathProfilingContext.mark("paramConversion");
 
         // Phase 7: Wrap response observer for cache storage (if caching enabled)
         StreamObserver<OpResult> finalObserver = QueryCacheHelper.wrapWithCaching(
                 responseObserver, cacheConfig, sql, params, dto.getSession().getConnHash());
 
         if (CollectionUtils.isNotEmpty(params)) {
+            ExecutionPathProfilingContext.beginJdbcCall();
             PreparedStatement ps = StatementFactory.createPreparedStatement(sessionManager, dto, sql, params, request);
-            String resultSetUUID = sessionManager.registerResultSet(dto.getSession(), ps.executeQuery());
+            ExecutionPathProfilingContext.endJdbcCall();
+            ExecutionPathProfilingContext.mark("statementCreation");
+            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);
-            String resultSetUUID = sessionManager.registerResultSet(dto.getSession(),
-                    stmt.executeQuery(sql));
+            ExecutionPathProfilingContext.endJdbcCall();
+            ExecutionPathProfilingContext.mark("statementCreation");
+            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");
         }
     }
 }

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,41 +114,57 @@ 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<Parameter> 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) {
                     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");
             }
 
             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 {

ojp-server/src/main/java/org/openjproxy/grpc/server/profiling/ExecutionPathProfiler.java

@@ -0,0 +1,107 @@
+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.
+ * <p>
+ * 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.
+ * </p>
+ * <p>
+ * Instances are not thread-safe; create one per thread via
+ * {@link ExecutionPathProfilingContext}.
+ * </p>
+ */
+public class ExecutionPathProfiler {
+
+    /** Ordered list of step timings accumulated during one execution. */
+    private final List<StepTiming> 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;
+    }
+
+    /**
+     * Advances the reference timestamp by {@code ns} nanoseconds, effectively
+     * excluding that duration from the current step's measurement window.
+     * <p>
+     * Use this to discount time spent inside external JDBC calls so that the
+     * subsequent {@link #mark(String)} records only OJP-internal overhead.
+     * </p>
+     *
+     * @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.
+     *
+     * @return list of step timings
+     */
+    public List<StepTiming> 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;
+        }
+    }
+}