Skip to content

Introducing Performance Logger metrics - Statement/PreparedStatement#2885

Merged
muskan124947 merged 14 commits intomainfrom
users/muskgupta/metrics_statement
Feb 19, 2026
Merged

Introducing Performance Logger metrics - Statement/PreparedStatement#2885
muskan124947 merged 14 commits intomainfrom
users/muskgupta/metrics_statement

Conversation

@muskan124947
Copy link
Copy Markdown
Contributor

@muskan124947 muskan124947 commented Jan 27, 2026

Summary

This PR extends the existing Performance Logger work by adding statement-level metrics for Statement and PreparedStatement execution paths. (Callback/logging design and connection metrics were added in a previous PR.)
Introducing Performance Logger and callback handling mechanism#2706

Statement activities tracked

Metrics are emitted via PerformanceLogCallback (statement overload with connectionId + statementId) and/or com.microsoft.sqlserver.jdbc.PerformanceMetrics.Statement logger.

  • STATEMENT_REQUEST_BUILD (timing-only): client-side request build time (SQL processing, parameter binding, TDS packet construction). No exception tracking.
  • STATEMENT_FIRST_SERVER_RESPONSE (timing-only): time from request send to first server response (startResponse()). No exception tracking.
  • STATEMENT_PREPARE: sp_prepare time when prepareMethod=prepare. Tracks exceptions.
  • STATEMENT_PREPEXEC: combined prepare+execute time via sp_prepexec (default reuse path). Tracks exceptions.
  • STATEMENT_EXECUTE: execution time for Statement + PreparedStatement variants (sp_executesql, sp_execute, direct SQL, batch). Tracks exceptions.

Execution mapping (high level)

  • Statement: REQUEST_BUILD → FIRST_SERVER_RESPONSE → EXECUTE
  • PreparedStatement: REQUEST_BUILD → FIRST_SERVER_RESPONSE → (PREPEXEC or EXECUTE) + PREPARE (when prepareMethod=prepare)

Testing

Test Validates
testPublishIsCalledAndLogFileCreated Callback is invoked for connection-level activities; performance.log file is created
testStatementExecutionPerformanceLogging Statement and PreparedStatement execution triggers the callback
testPerformanceOverhead Measures overhead of enabling callback+logging vs disabled (configurable iterations)
testHighVolumeStatementPerformance High-volume single-connection test (10k+ iterations) to validate no performance regression
testBatchStatementPerformanceLogging PreparedStatement.executeBatch() with parameterized inserts triggers the callback
testAllStatementActivities End-to-end coverage of all 5 prepareMethod variants: Statement (direct SQL), prepexec, prepare, none, scopeTempTablesToConnection
testPrepExecActivityTrackedOnlyOnSecondExecution Verifies default flow: 1st→EXECUTE (sp_executesql), 2nd→PREPEXEC (sp_prepexec), 3rd→EXECUTE (sp_execute)
testPrepExecActivityTrackedOnFirstExecutionWhenEagerPrepareEnabled Verifies enablePrepareOnFirstPreparedStatementCall=true flow: 1st→PREPEXEC, 2nd→EXECUTE, 3rd→EXECUTE

Sample Log Output

ConnectionID:1, StatementID:1 Request build time, duration: 8ms
ConnectionID:1, StatementID:1 First server response, duration: 17ms
ConnectionID:1, StatementID:1 Statement execute, duration: 75ms      ← 1st call: sp_executesql
ConnectionID:1, StatementID:1 Request build time, duration: 9ms
ConnectionID:1, StatementID:1 First server response, duration: 0ms
ConnectionID:1, StatementID:1 Statement prepexec, duration: 0ms      ← 2nd call: sp_prepexec
ConnectionID:1, StatementID:1 Request build time, duration: 0ms
ConnectionID:1, StatementID:1 First server response, duration: 0ms
ConnectionID:1, StatementID:1 Statement execute, duration: 0ms       ← 3rd call: sp_execute

@muskan124947 muskan124947 self-assigned this Jan 27, 2026
@github-project-automation github-project-automation Bot moved this to In progress in MSSQL JDBC Jan 27, 2026
@muskan124947 muskan124947 changed the title [WIP] Perf Logger metrics - Statemnet/PreparedStatement [WIP] Perf Logger metrics - Statement/PreparedStatement Jan 27, 2026
@muskan124947
Copy link
Copy Markdown
Contributor Author

/azp run

@azure-pipelines
Copy link
Copy Markdown

Azure Pipelines successfully started running 3 pipeline(s).

@muskan124947 muskan124947 added this to the 13.3.2 milestone Jan 28, 2026
@codecov
Copy link
Copy Markdown

codecov Bot commented Jan 28, 2026

Codecov Report

❌ Patch coverage is 79.50820% with 50 lines in your changes missing coverage. Please review.
✅ Project coverage is 60.68%. Comparing base (26c55e1) to head (efc53e4).
⚠️ Report is 2 commits behind head on main.

Files with missing lines Patch % Lines
...oft/sqlserver/jdbc/SQLServerPreparedStatement.java 74.56% 29 Missing and 15 partials ⚠️
...m/microsoft/sqlserver/jdbc/SQLServerStatement.java 90.16% 3 Missing and 3 partials ⚠️
Additional details and impacted files
@@             Coverage Diff              @@
##               main    #2885      +/-   ##
============================================
+ Coverage     60.55%   60.68%   +0.13%     
- Complexity     4887     4904      +17     
============================================
  Files           151      151              
  Lines         34827    34936     +109     
  Branches       5834     5837       +3     
============================================
+ Hits          21088    21201     +113     
- Misses        10907    10908       +1     
+ Partials       2832     2827       -5     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Adds statement-level performance metrics (Statement/PreparedStatement) to the JDBC driver’s performance logging/callback pipeline.

Changes:

  • Introduces statement/connection identifiers for correlating statement metrics.
  • Adds new PerformanceActivity values and instrumentation around statement execution/preparation paths.
  • Adds documentation describing the new statement performance metrics and where they’re emitted.

Reviewed changes

Copilot reviewed 6 out of 6 changed files in this pull request and generated 13 comments.

Show a summary per file
File Description
src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Adds statement ID + performance scopes around statement execution paths.
src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Adds tracking for prepared statement execution/prepare paths and distinguishes prepexec vs execute.
src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java Exposes connection ID for statement-metric correlation.
src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLog.java Adds a dedicated statement metrics logger.
src/main/java/com/microsoft/sqlserver/jdbc/PerformanceActivity.java Extends the enum with statement-related performance activities and inline documentation.
docs/statement-performance-metrics.md Documents the statement performance metrics and coverage across execution paths.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceActivity.java Outdated
Comment thread docs/statement-performance-metrics.md Outdated
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated 5 comments.


💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLog.java
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java Outdated
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated 7 comments.

Comments suppressed due to low confidence (1)

src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java:283

  • startCreationToFirstPacketTracking() is started for every execution attempt, but the scope is only closed on the retry sleep path or inside specific doExecute* methods. If executeCommand(newStmtCmd) throws and the exception is rethrown (no retry), the creationToFirstPacketScope remains open, which can leak the scope and prevent subsequent executions from starting a new request-build measurement (because startCreationToFirstPacketTracking() is a no-op when the field is non-null). Consider closing/resetting the scope in the catch/finally path before rethrowing.
            
            // Start request build time tracking for this execution attempt.
            startCreationToFirstPacketTracking();
            
            try {
                // (Re)execute this Statement with the new command
                executeCommand(newStmtCmd);
            } catch (SQLServerException e) {

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLog.java
Comment thread docs/performance-metrics.md Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceActivity.java
Comment thread docs/performance-metrics.md Outdated
@muskan124947 muskan124947 requested a review from Copilot February 3, 2026 16:07
@muskan124947 muskan124947 added the Under Review Used for pull requests under review label Feb 3, 2026
@muskan124947 muskan124947 changed the title [WIP] Perf Logger metrics - Statement/PreparedStatement Introducing Performance Logger metrics - Statement/PreparedStatement Feb 3, 2026
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceActivity.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/PerformanceActivity.java Outdated
Comment thread docs/performance-metrics.md
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 7 out of 7 changed files in this pull request and generated 9 comments.


💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
Comment thread docs/performance-metrics.md Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
Comment thread src/test/java/com/microsoft/sqlserver/jdbc/PerformanceLogCallbackTest.java Outdated
Comment thread src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java Outdated
@azure-pipelines
Copy link
Copy Markdown

Azure Pipelines successfully started running 3 pipeline(s).

Copy link
Copy Markdown
Contributor

@divang divang left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need a way to identify different statement types: Statement, PreparedStatement, and CallableStatement , so that users can analyze and compare the performance differences among them?

image

Comment thread docs/performance-metrics.md
@muskan124947 muskan124947 merged commit cf51d04 into main Feb 19, 2026
19 checks passed
@github-project-automation github-project-automation Bot moved this from In progress to Closed/Merged PRs in MSSQL JDBC Feb 19, 2026
@muskan124947 muskan124947 removed the Under Review Used for pull requests under review label Mar 5, 2026
@JDBC-0
Copy link
Copy Markdown

JDBC-0 commented Apr 17, 2026

OK, the log output works for log level FINE. But is there another way/API to get thse values? Because we don't want to set our log level to FINE and browse endloss log files. Instead we want to "listen" to these metrics, inspect them and check if specific value thresholds are hit to create our own log events (to specific metric systems).
Is there such an API, Interface, Listerm Handler?

@muskan124947
Copy link
Copy Markdown
Contributor Author

Hi @JDBC-0
FINE-level logging is not required. The driver already provides a programmatic callback API for exactly this use case.

Register a PerformanceLogCallback to receive metrics in-process — no log files involved:
(This is just a sample example)

SQLServerDriver.registerPerformanceLogCallback(new PerformanceLogCallback() {
    @Override
    public void publish(PerformanceActivity activity, int connectionId,
                        long durationMs, Exception exception) {
        // Connection-level metrics (CONNECTION, PRELOGIN, LOGIN, TOKEN_ACQUISITION)
        if (durationMs > 500) {
            myMetrics.record("jdbc.connection." + activity, durationMs);
        }
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId,
                        int statementId, long durationMs, Exception exception) {
        // Statement-level metrics (REQUEST_BUILD, FIRST_SERVER_RESPONSE, EXECUTE, etc.)
        if (durationMs > 200) {
            myAlertSystem.warn("Slow op: conn=" + connectionId
                + " stmt=" + statementId + " " + activity + " " + durationMs + "ms");
        }
    }
});

The callback fires independently of the log level — it's triggered whenever a performance scope closes, as long as a callback is registered. You get the activity type, connection/statement IDs, duration in ms, and any exception — everything you need to apply threshold checks and forward to your own metrics/alerting system.

To unregister later: SQLServerDriver.unregisterPerformanceLogCallback().

For more info, you can refer to: Performance logger and callback

@JDBC-0
Copy link
Copy Markdown

JDBC-0 commented Apr 20, 2026

That's great to have an API, but this PerformanceActivity just has numeric statementId so the result

JDBC performance (ConId: 9, StmtId: 128) 'First server response': 8507 ms

is unreadable/unusable because the statement name is missing. How can I know what "statement 128" is?

It would be great to have the statement as a "readable" name (with parameter values, if possible).

@muskan124947
Copy link
Copy Markdown
Contributor Author

@JDBC-0 ,
The callback is invoked synchronously on the same application thread that executed the statement — not on a background thread. So the application already has full context about which SQL triggered the callback at the point it's received, and can make out what it executed to receive these callback metrics.

@JDBC-0
Copy link
Copy Markdown

JDBC-0 commented Apr 20, 2026

Hm, what IDs are thes: ConnectionId, statementId? On the application context I don't have any access when I call a JDBC statement .... only statements with a resultsset might have such metainformation somewhere hidden in the JDBC driver API. So how can you get/inspect a "statementId" that is set in the PerformanceAcrtivity? The whole idea of this is to have a single point of configuration to get this info, e.g.:

    static {

    	//#31980: register MS SQL JDBC driver "PerformanceLogCallback" to listen to performance metrics:
        try {
            SQLServerDriver.registerPerformanceLogCallback(new PerformanceLogCallback() {
                @Override
                public void publish(PerformanceActivity activity, int connectionId, long durationMs, Exception exception) {
                    if (durationMs > 60_000L) { //longer than 1 minute?
                        logPerf(activity, connectionId, -1, durationMs, exception);
                    }
                }

                @Override
                public void publish(PerformanceActivity activity, int connectionId, int statementId, long durationMs, Exception exception) {
                    if (durationMs > 60_000L) { //longer than 1 minute?
                        logPerf(activity, connectionId, statementId, durationMs, exception);
                    }
                }

                private void logPerf(PerformanceActivity activity, int connId, int stmtId, long ms, Exception ex) {
                    final String msg = String.format("JDBC performance (ConId: %d, StmtId: %d) '%s': %d ms", connId, stmtId, activity, ms);
                    LOGGER.log(Level.WARNING, msg, ex);
                }
            });
        } catch (Throwable t) {
            LOGGER.config("Could not register MS-SQL Performance Callback: " + t.getMessage());
        }

    }//end of static

And this has no context to the generig threads of the applications that concurrently call misc JDBC methods. The only workaround I can think of is to samehow "get" this driver internal statementId when the statement is created, build an internal HashMap to store these and when the PerformanceLogCallback triggers, I could read this global HashMap to get information from it ... which would be possible within the driver itself, too.

I tried write such a global hashmap but I can't get the internal ID (statementId) from com.microsoft.sqlserver.jdbc.SQLServerStatement - there is no public method to read it! (getStatementID() is not public)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Closed/Merged PRs

Development

Successfully merging this pull request may close these issues.

5 participants