Логгер производительности и обратный вызов

Скачать драйвер JDBC

Начиная с версии 13.4 драйвер Microsoft JDBC для SQL Server предоставляет платформу метрик производительности для отслеживания времени критически важных операций драйверов. Эту платформу можно использовать для наблюдения за поведением подключения и выполнения инструкций, помогая выявлять узкие места задержки в взаимодействии приложения с SQL Server.

Метрики доступны с помощью двух механизмов, которые можно использовать независимо или совместно:

  • Программный обратный вызов: зарегистрируйте PerformanceLogCallback для получения метрик в коде вашего приложения.
  • Ведение журнала Java — подписывайтесь на специальные java.util.logging логгеры, чтобы фиксировать метрики в журнале.

Отслеживаемые действия

Драйвер отслеживает действия на двух уровнях: подключение и инструкция.

Действия уровня подключения

Activity Описание
CONNECTION Общее время для установления подключения, включая все подзадачи.
PRELOGIN Время предварительного входа TDS с сервером.
LOGIN Время выполнения рукопожатия для входа и аутентификации TDS.
TOKEN_ACQUISITION Время, необходимое для получения федеративных токенов аутентификации при использовании Microsoft Entra.

Действия на уровне инструкций

Activity Описание
STATEMENT_REQUEST_BUILD Время на стороне клиента для создания запроса TDS (привязка параметров, обработка SQL, построение пакетов). Только синхронизация по времени; не выполняется отслеживание исключений.
STATEMENT_FIRST_SERVER_RESPONSE Время от отправки запроса на получение первого ответа сервера. Только синхронизация по времени; не выполняется отслеживание исключений.
STATEMENT_PREPARE Время для sp_prepare, когда prepareMethod=prepare.
STATEMENT_PREPEXEC Время для объединенной подготовки и выполнения с помощью sp_prepexec.
STATEMENT_EXECUTE Время запуска инструкции (sp_executesql, sp_execute, прямой SQL или пакетный режим).

Включение метрик производительности

Вариант 1. Регистрация обратного вызова

Зарегистрируйте PerformanceLogCallback, чтобы программно получать данные о производительности.

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);
    }
});

Используйте наносекундную точность времени и контекст инструкций

Начиная с версии 13.6 для функции обратного вызова можно включить измерение времени с точностью до наносекунд, переопределив useNanoseconds(). Обратный вызов также может вызывать getCurrentUserSql() и getCurrentStatementType(), чтобы сопоставить событие уровня инструкции с SQL-текстом, отправленным приложением, и типом выполненной инструкции. getCurrentStatementType() возвращает STATEMENT, PREPARED_STATEMENT, или CALLABLE_STATEMENT. Используйте getCurrentApplicationName() для идентификации соединения или пула, который породил событие, исходя из его applicationName свойства соединения. Если applicationName не установлен, метод возвращает имя приложения драйвера по умолчанию.

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);
    }
});

Тайминг наносекунд — это опция по согласию. Обратные вызовы, которые не переопределяют useNanoseconds(), по-прежнему получают значения длительности в миллисекундах. Если для зарегистрированного обратного вызова включена эта возможность, вывод отдельного регистратора производительности также использует наносекунды и обозначает длительности с помощью ns; в противном случае используются миллисекунды и ms. Вызов System.nanoTime() может быть связан с бо́льшими накладными расходами, чем System.currentTimeMillis(), на некоторых платформах.

Контекст обратного вызова доступен только при соответствующем вызове publish(). getCurrentApplicationName() доступна для событий уровня соединения и уровня инструкции и возвращает null за пределами publish(). Он также может возвращать null, если свойства соединения ещё не были обработаны, например если сбой соединения происходит до того, как будет определено имя приложения. Методы контекста SQL возвращают null для событий уровня соединения, метрик подопераций инструкции, не имеющих контекста SQL, и вызовов, выполненных вне publish().

Caution

SQL-текст может содержать чувствительные данные в виде литерал или комментариев. Очищайте его и применяйте требования вашей организации к обработке данных перед тем, как записывать их в журналы или телеметрию.

Вариант 2. Настройка ведения журнала Java

Настройте java.util.logging средства ведения журнала метрик производительности на FINE уровне.

logging.properties В файле:

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

Или программно:

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

Метод подготовки и его влияние на активность операторов

Действия, отслеживаемые для PreparedStatement, зависят от prepareMethod свойства подключения. Дополнительные сведения см. в prepareMethodразделе "Настройка свойств подключения".

Настройка prepareMethod Первое выполнение Второе выполнение Третье+ выполнение
prepexec (по умолчанию) STATEMENT_EXECUTE (sp_executesql) STATEMENT_PREPEXEC (sp_prepexec) STATEMENT_EXECUTE (sp_execute)
prepare STATEMENT_PREPARE + STATEMENT_EXECUTE STATEMENT_EXECUTE STATEMENT_EXECUTE
none STATEMENT_EXECUTE (прямой SQL) STATEMENT_EXECUTE (прямой SQL) STATEMENT_EXECUTE (прямой SQL)

Замечание

Если задано значение по умолчанию prepexec , драйвер отложит подготовку при условии одноразового использования. Во втором выполнении используется sp_prepexec (совмещенная подготовка и выполнение). Начиная с третьего выполнения, кэшированный дескриптор повторно используется через sp_execute. Чтобы принудительно применить sp_prepexec при первом вызове, установите для свойства подключения enablePrepareOnFirstPreparedStatementCall значение true.

Пример выходных данных журнала

Следующие результаты PreparedStatement показывают действия, отслеживаемые в ходе трех последовательных запусков с настройкой по умолчанию prepexec.

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

Связанные материалы

  • Last updated on