Add nanosecond granularity option to PerformanceLogCallback

[machavan]

Add nanosecond granularity option to PerformanceLogCallback

Summary

Adds an opt-in nanosecond duration mode to the PerformanceLogCallback interface, allowing applications to receive high-resolution timing data without any breaking changes to the existing API.

Motivation

Millisecond resolution is insufficient for profiling fast operations (e.g., cached statement execution, connection pool checkout). Applications that need sub-millisecond visibility can now opt into nanosecond granularity by overriding a single default method.

Design

• No API signature changes — the publish() methods and registerPerformanceLogCallback() remain identical.
• Opt-in via default method — PerformanceLogCallback gains a default boolean useNanoseconds() that returns false. Applications override it to return true to receive nanosecond values in the existing duration parameter.
• Correct time source — when useNanoseconds() is true, the driver uses System.nanoTime() for both start and end; otherwise it uses System.currentTimeMillis().
• Zero impact on existing users — the default behavior is unchanged (milliseconds).

Changes

File	Change
PerformanceLogCallback.java	Added default boolean useNanoseconds() with Javadoc
PerformanceLog.java	Scope reads useNanoseconds() at construction, selects nanoTime() or currentTimeMillis() accordingly; logger output includes correct unit label ("ms" or "ns")
PerformanceLogCallbackTest.java	Added testPublishWithNanosecondGranularity test

Usage

SQLServerDriver.registerPerformanceLogCallback(new PerformanceLogCallback() {
    @Override
    public boolean useNanoseconds() {
        return true; // opt-in to nanosecond durations
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId, long duration, Exception ex) {
        // duration is now in nanoseconds
        System.out.printf("%s conn=%d duration=%dns%n", activity, connectionId, duration);
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId, int statementId, long duration, Exception ex) {
        System.out.printf("%s conn=%d stmt=%d duration=%dns%n", activity, connectionId, statementId, duration);
    }
});

Testing

• All 11 existing PerformanceLogCallbackTest tests pass.
• New test validates nanosecond values are within expected range (> 1000ns for a 1ms+ operation).

Backward Compatibility

Fully backward compatible. Existing callbacks that do not override useNanoseconds() continue to receive millisecond durations with no code changes required.

Performance Considerations

When useNanoseconds() returns true, an additional overhead is expected compared to millisecond mode. This is because System.nanoTime() have higher invocation cost than System.currentTimeMillis() on some platforms. This overhead only applies when a callback is registered and logging is enabled — there is no impact when both are disabled.

Sample Output

May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1 Prelogin, duration: 16078800ns
May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1 Login, duration: 736384700ns
May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1 Connection, duration: 746256200ns
May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1, StatementID:1 Request build time, duration: 1098600ns
May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1, StatementID:1 First server response, duration: 1334200ns
May 13, 2026 3:21:25 PM com.microsoft.sqlserver.jdbc.PerformanceLog$Scope close
FINE: ConnectionID:1, StatementID:1 Statement execute, duration: 48569800ns

[codecov]

Codecov Report

❌ Patch coverage is 84.61538% with 2 lines in your changes missing coverage. Please review.
✅ Project coverage is 60.82%. Comparing base (4af91fe) to head (56a9b71).

Files with missing lines	Patch %	Lines
...a/com/microsoft/sqlserver/jdbc/PerformanceLog.java	83.33%	2 Missing ⚠️

Additional details and impacted files

@@             Coverage Diff              @@
##               main    #2944      +/-   ##
============================================
- Coverage     60.83%   60.82%   -0.02%     
+ Complexity     4980     4972       -8     
============================================
  Files           151      152       +1     
  Lines         35223    35231       +8     
  Branches       5900     5904       +4     
============================================
  Hits          21429    21429              
  Misses        10932    10932              
- Partials       2862     2870       +8     

☔ 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.

[Copilot]

Pull request overview

Adds an opt-in nanosecond timing mode for performance metrics callbacks so applications can receive higher-resolution durations without changing the existing publish(...) method signatures.

Changes:

• Added PerformanceLogCallback.useNanoseconds() default method (defaults to milliseconds).
• Updated PerformanceLog.Scope to use System.nanoTime() when nanosecond mode is enabled and to label logs with ms/ns.
• Expanded PerformanceLogCallbackTest and documentation to cover nanosecond granularity usage.

Reviewed changes

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

File	Description
src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLogCallback.java	Adds useNanoseconds() and updates Javadoc to describe unit switching for duration.
src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLog.java	Switches duration timing source (nanoTime vs currentTimeMillis) and adjusts log unit suffix.
src/test/java/com/microsoft/sqlserver/jdbc/PerformanceLogCallbackTest.java	Adds nanosecond-mode testing and extends overhead/performance tests to cover both modes.
.github/instructions/performance-metrics.instructions.md	Documents how to opt into nanosecond granularity and what changes in timing/log output.

Comments suppressed due to low confidence (1)

src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLogCallback.java:43

• useNanoseconds() Javadoc also uses {@link #publish} without a signature, which is ambiguous due to the overloaded publish methods and can break Javadoc generation when failOnError=true. Use signature-qualified links (or reference both overloads) to avoid Javadoc errors.

     * Indicates whether the callback wants duration values in nanoseconds.
     * Override this method to return {@code true} to receive nanosecond granularity
     * in the {@code duration} parameter of {@link #publish}.
     * The default is {@code false} (milliseconds).
     *

[Copilot]

Pull request overview

Copilot reviewed 4 out of 4 changed files in this pull request and generated 2 comments.

Comments suppressed due to low confidence (2)

src/main/java/com/microsoft/sqlserver/jdbc/PerformanceLog.java:110

• close() uses the static callback field directly; this can publish to a different callback than the one used to decide the time source in the constructor (or to a callback that was registered after the scope started). To keep units consistent and avoid races, publish using a callback reference captured when the scope was created (or skip publishing if no callback was registered at that time).

            if (callback != null) {
                try {
                    if (statementId == 0) {
                        callback.publish(activity, connectionId, duration, exception);
                    } else {
                        callback.publish(activity, connectionId, statementId, duration, exception);
                    }

src/test/java/com/microsoft/sqlserver/jdbc/PerformanceLogCallbackTest.java:755

• testPublishDefaultDelegatesToMsOverload claims to validate millisecond behavior, but it only asserts that publish() was called and never checks that the values are actually in milliseconds (or at least not nanoseconds). Either add an assertion that would fail under nanosecond mode, or rename/reword the test so it matches what is actually being validated.

    /**
     * Test to validate backward compatibility: when registered without useNanoseconds
     * (default), the duration field contains millisecond values.
     */
    @Test
    void testPublishDefaultDelegatesToMsOverload() throws Exception {
        List<Long> connectionMs = new ArrayList<>();
        List<Long> statementMs = new ArrayList<>();

        PerformanceLogCallback callbackInstance = new PerformanceLogCallback() {
            @Override
            public void publish(PerformanceActivity activity, int connectionId, long duration,
                    Exception exception) {
                connectionMs.add(duration);
            }

            @Override
            public void publish(PerformanceActivity activity, int connectionId, int statementId,
                    long duration, Exception exception) {
                statementMs.add(duration);
            }
        };

        // Register without useNanoseconds (default = milliseconds)
        SQLServerDriver.registerPerformanceLogCallback(callbackInstance);

        try (Connection con = getConnection()) {
            try (Statement stmt = con.createStatement();
                 ResultSet rs = stmt.executeQuery("SELECT 1")) {
            }
        }

        // Durations should be in milliseconds
        assertTrue(connectionMs.size() > 0,
                "publish should have been called for connection-level activities");
        assertTrue(statementMs.size() > 0,
                "publish should have been called for statement-level activities");