Introducing Performance Logger metrics - Statement/PreparedStatement#2885
Introducing Performance Logger metrics - Statement/PreparedStatement#2885muskan124947 merged 14 commits intomainfrom
Conversation
|
/azp run |
|
Azure Pipelines successfully started running 3 pipeline(s). |
Codecov Report❌ Patch coverage is 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. 🚀 New features to boost your workflow:
|
There was a problem hiding this comment.
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
PerformanceActivityvalues 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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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 specificdoExecute*methods. IfexecuteCommand(newStmtCmd)throws and the exception is rethrown (no retry), thecreationToFirstPacketScoperemains open, which can leak the scope and prevent subsequent executions from starting a new request-build measurement (becausestartCreationToFirstPacketTracking()is a no-op when the field is non-null). Consider closing/resetting the scope in thecatch/finallypath 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.
There was a problem hiding this comment.
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.
|
Azure Pipelines successfully started running 3 pipeline(s). |
…nFirstPreparedStatementCall=true
|
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). |
|
Hi @JDBC-0 Register a PerformanceLogCallback to receive metrics in-process — no log files involved: 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 |
|
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). |
|
@JDBC-0 , |
|
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.: 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) |

Summary
This PR extends the existing Performance Logger work by adding statement-level metrics for
StatementandPreparedStatementexecution 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 withconnectionId+statementId) and/orcom.microsoft.sqlserver.jdbc.PerformanceMetrics.Statementlogger.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_preparetime whenprepareMethod=prepare. Tracks exceptions.STATEMENT_PREPEXEC: combined prepare+execute time viasp_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 → EXECUTEPreparedStatement: REQUEST_BUILD → FIRST_SERVER_RESPONSE → (PREPEXEC or EXECUTE) + PREPARE (whenprepareMethod=prepare)Testing
testPublishIsCalledAndLogFileCreatedperformance.logfile is createdtestStatementExecutionPerformanceLoggingtestPerformanceOverheadtestHighVolumeStatementPerformancetestBatchStatementPerformanceLoggingPreparedStatement.executeBatch()with parameterized inserts triggers the callbacktestAllStatementActivitiesprepareMethodvariants: Statement (direct SQL),prepexec,prepare,none,scopeTempTablesToConnectiontestPrepExecActivityTrackedOnlyOnSecondExecutionsp_executesql), 2nd→PREPEXEC (sp_prepexec), 3rd→EXECUTE (sp_execute)testPrepExecActivityTrackedOnFirstExecutionWhenEagerPrepareEnabledenablePrepareOnFirstPreparedStatementCall=trueflow: 1st→PREPEXEC, 2nd→EXECUTE, 3rd→EXECUTESample Log Output