Performance logger and callback

Download JDBC driver

Starting with version 13.4, the Microsoft JDBC Driver for SQL Server provides a performance metrics framework for tracking the timing of critical driver operations. You can use this framework to observe and analyze connection and statement execution behavior, helping identify latency bottlenecks in your application's interactions with SQL Server.

Metrics are available through two mechanisms that can be used independently or together:

• Programmatic callback - Register a PerformanceLogCallback to receive metrics in your application code.
• Java logging - Subscribe to dedicated java.util.logging loggers to capture metrics in log output.

Tracked activities

The driver tracks activities at two levels: connection and statement.

Connection-level activities

Statement-level activities

Enable performance metrics

Option 1: Register a callback

Register a PerformanceLogCallback to receive performance data programmatically:

SQLServerDriver.registerPerformanceLogCallback(new PerformanceLogCallback() {
    @Override
    public void publish(PerformanceActivity activity, int connectionId,
            long durationMs, Exception exception) {
        // Connection-level metrics
        System.out.printf("Activity: %s, Connection: %d, Duration: %d ms%n",
                activity, connectionId, durationMs);
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId,
            int statementId, long durationMs, Exception exception) {
        // Statement-level metrics
        System.out.printf("Activity: %s, Connection: %d, Statement: %d, Duration: %d ms%n",
                activity, connectionId, statementId, durationMs);
    }
});

Use nanosecond timing and statement context

Starting with version 13.6, a callback can opt in to nanosecond timing by overriding useNanoseconds(). The callback can also call getCurrentUserSql() and getCurrentStatementType() to correlate a statement-level event with the SQL text submitted by the application and the type of statement that executed. getCurrentStatementType() returns STATEMENT, PREPARED_STATEMENT, or CALLABLE_STATEMENT. Use getCurrentApplicationName() to identify the connection or pool that produced an event from its applicationName connection property. If applicationName isn't set, the method returns the driver's default application name.

SQLServerDriver.registerPerformanceLogCallback(new PerformanceLogCallback() {
    @Override
    public boolean useNanoseconds() {
        return true;
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId,
            long durationNs, Exception exception) {
        // Connection-level metrics don't have SQL statement context.
        System.out.printf("Application: %s, Activity: %s, Connection: %d, Duration: %d ns%n",
            getCurrentApplicationName(), activity, connectionId, durationNs);
    }

    @Override
    public void publish(PerformanceActivity activity, int connectionId,
            int statementId, long durationNs, Exception exception) {
        String applicationName = getCurrentApplicationName();
        String userSql = getCurrentUserSql();
        StatementType statementType = getCurrentStatementType();

        System.out.printf("Application: %s, Type: %s, Activity: %s, SQL: %s, Duration: %d ns%n",
            applicationName, statementType, activity, userSql, durationNs);
    }
});

Nanosecond timing is opt-in. Callbacks that don't override useNanoseconds() continue to receive durations in milliseconds. When a registered callback opts in, the dedicated performance logger output also uses nanoseconds and labels durations with ns; otherwise, it uses milliseconds and ms. Calling System.nanoTime() can have more overhead than System.currentTimeMillis() on some platforms.

Callback context is available only during the corresponding publish() invocation. getCurrentApplicationName() is available for connection-level and statement-level events and returns null outside publish(). It can also return null when connection properties haven't been parsed, such as when a connection fails before the application name is resolved. The SQL context methods return null for connection-level events, statement subactivity metrics that don't have SQL context, and calls made outside publish().

Option 2: Configure Java logging

Configure java.util.logging for the performance metrics loggers at FINE level.

In a logging.properties file:

com.microsoft.sqlserver.jdbc.PerformanceMetrics.Connection.level = FINE
com.microsoft.sqlserver.jdbc.PerformanceMetrics.Statement.level = FINE
handlers = java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = FINE

Or programmatically:

Logger.getLogger("com.microsoft.sqlserver.jdbc.PerformanceMetrics.Connection")
      .setLevel(Level.FINE);
Logger.getLogger("com.microsoft.sqlserver.jdbc.PerformanceMetrics.Statement")
      .setLevel(Level.FINE);

Prepare method effect on statement activities

The activities tracked for PreparedStatement depend on the prepareMethod connection property. For more information about prepareMethod, see Setting the connection properties.

Sample log output

The following output shows the activities tracked across three consecutive executions of a PreparedStatement with the default prepexec setting:

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

Related content

• Improving performance and reliability (JDBC)
• Set the connection properties