среда, 18 апреля 2012 г.

Log4jdbc

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

Простым, удобным и при этом информативным инструментом для решения задач такого рода являются специальные JDBC logging библиотеки. Подобные библиотеки встраиваются в программу, используя Proxy Design Pattern, перед DataSource или Connection, что легко можно сделать в java-коде или декларативно (Spring).

Существует несколько независимых библиотек, реализующих такую функциональность, например, Log4jdbc (http://code.google.com/p/log4jdbc/). На страничке этого проекта можно найти достаточно подробную информацию о свойствах и возможностях библиотеки. Если кратко, то Log4jdbc:
  • open-source под лицензией Apache 2.0;
  • работает с JDK 1.4 и выше;
  • работает с системой логирования SLF4J 1.x, соответственно, поддерживает log4j, logback, JCL, java.util logging in JDK 1.4;
  • просто настраивается;
  • имеет широкие возможности по объёму и глубине логируемой информации.


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

1) Определить версию JDK и скачать соответствующую версию Log4jdbc - JDBC 3 для JDK 4/5 или JDBC 4 для JDK 6/7 (http://code.google.com/p/log4jdbc/downloads/list).
2) Определиться с системой логирования и скачать нужные библиотеки (например, slf4j-api.jar, slf4j-log4j12.jar, log4j.jar) (http://slf4j.org/download.html).
3) Добавить все новые библиотеки в CLASSPATH приложения.
4) Настроить логирование используемого в приложении логгера. Подробнее это действие описывается чуть ниже.
5) Скорректировать DATABASE URL (добавить jdbc:log4jdbc) и изменить класс JDBC-драйвера (на net.sf.log4jdbc.DriverSpy).

Пример в java-коде:
//реальный драйвер
Class.forName("oracle.jdbc.driver.OracleDriver")
Connection connection = DriverManager.getConnection("jdbc:oracle:thin:@host:1521:test01");

//драйвер Log4jdbc
Class.forName("net.sf.log4jdbc.DriverSpy")
Connection connection = DriverManager.getConnection("jdbc:log4jdbc:oracle:thin:@host:1521:test01");
 Пример в Spring:
<beans>
    <bean name="applicationDataSource" class="org.apache.commons.dbcp.BasicDataSource">

        <!-- реальный драйвер -->
        <property name="driverClassName" value="com.microsoft.sqlserver.jdbc.SQLServerDriver" />
        <property name="url" value="jdbc:sqlserver://localhost:1433;username=user;password=pas;databaseName=fake" />

        <!-- драйвер Log4jdbc-->
        <property name="driverClassName" value="net.sf.log4jdbc.DriverSpy" />
        <property name="url" value="jdbc:log4jdbc:sqlserver://localhost:1433;username=user;password=pas;databaseName=fake" />
       
    </bean>
</beans>
Интересный вопрос: как Log4jdbc определяет, какой драйвер надо реально использовать для коннекта к БД, после изменения driverClassName?
Оказывается, здесь возможны два варианта:
    a) можно положиться на Log4jdbc - он автоматически попробует найти и загрузить подходящий драйвер из имеющегося списка (MSQSL, MySQL, Oracle, Sybase, Informix и пр.);
    b) можно явно указать драйвер в настройке логгера либо через системное свойство, например:
-Dlog4jdbc.drivers=com.microsoft.sqlserver.jdbc.SQLServerDriver

Фактически, перечисленные шаги - целых 5! - нужны для того, чтобы впервые "подружиться" с Log4jdbc. Впоследствии, когда все библиотеки уже загружены и добавлены в CLASSPATH, а шаблон для настройки логгера готов и отлажен, переход с реального драйвера на Log4jdbc и обратно требует выполнения только 5-го шага.

----------------------------------------------------------------------------------------------------
Настройка логирования выполняется через предлагаемые Log4jdbc категории:

    * jdbc.sqlonly - логирование только SQL-запросов (удобно то, что можно посмотреть запросы и из PreparedStatement - и не со знаками "?", а с реальными значениями, что очень и очень сильно повышает читаемость логов);
    * jdbc.sqltiming - логирование SQL-запросов и их времени выполнения; то же, что и в предыдущем, плюс длительность выполнения запросов. По длительности можно выявить медленные запросы, которые тормозят работу приложения.
На первый взгляд, вторая категория отличается от первой только добавлением времени выполнения запросов. Поэтому, казалось бы, использовать следует только вторую из них. Однако коренное отличие всё же есть: jdbc.sqlonly логирует PRE-EXECUTION (т.е. перед выполнением запроса) + ошибки, а jdbc.sqltiming - POST-EXECUTION (т.е. фактически после выполнения). Соответственно, если при попытке выполнить запрос произойдёт ошибка, то категория jdbc.sqlonly хотя бы залогирует текст выполняемого запроса, что может быть полезно при последующем анализе причин ошибки.
   
    * jdbc.audit - логирование всех JDBC-операций за исключением ResultSet-ов. Фактически логируются все операции с Connection (getMetaData, isClosed, clearWarnings, get/setAutoCommit, createStatement, prepareStatement), Statement (setFetchSize, executeQuery, close), PreparedStatement (executeQuery, new, setString/setInt/setTimestamp/etc) и т.д., и т.п.;
    * jdbc.resultset - логирование, включающее в себя операции со всеми ResultSet-объектами (new, next, wasNull, getInt/getString/getBytes/etc);
    * jdbc.connection - логирование операций с JDBC-соединениями (по факту - открытие и закрытие соединений). Может оказаться очень полезным для анализа того, как приложение оперирует ресурсоёмкими соединениями, переиспользует ли их или каждый раз создаёт новое, есть ли проблемы с пулом и пр.

Несколько отдельно стоит следующая категория:
    * log4jdbc.debug - отладка Log4jdbc. Содержит данные инициализации самого Log4jdbc, какие есть параметры и что используется.

Можно использовать все или любые нужные категории, логировать их по отдельным файлам или все вместе - это уже зависит от настроек логгеров. Следует обратить внимание на то, что особенно категории jdbc.audit и jdbc.resultset склонны к выводу очень большого количества информации, что при низком уровне логирования запросто забивает логи.

Полезную информацию по настройке логирования на примере log4j можно найти здесь: http://code.google.com/p/log4jdbc/source/browse/trunk/doc/log4j.xml и http://code.google.com/p/log4jdbc/source/browse/trunk/doc/log4j.properties
Также немного полезной информации можно посмотреть тут: http://alex-kuznetsov.blogspot.com/2009/11/log4jdbc.html#!/2009/11/log4jdbc.html

----------------------------------------------------------------------------------------------------

Для своего рода автоматизированного анализа (пост-обработки SQL TIMING лога) можно использовать встроенный инструмент, например:
    java -Xmx1024m -classpath log4jdbc4-1.2.jar net.sf.log4jdbc.PostLogProfilerProcessor filename.log
Подсчитывает количество SQL-запросов в логе, их общую длительность, среднюю длительность одного запроса. Авторы уточняют, что это новая и экспериментальная фича; и действительно, предлагаемый функционал совсем небольшой, а анализ чаще всего требует решения бОльших задач.

----------------------------------------------------------------------------------------------------

Так же просто Log4jdbc разворачивается и на серверах. Например, для JBoss потребуется:
1) добавить в директорию jboss/server/default/lib/other/ библиотеки log4jdbc, slf4j и log4j (если их там ещё нет);
2) скорректировать данные соединения: строка соединения jdbc:log4jdbc:..., драйвер net.sf.log4jdbc.DriverSpy (в различных datasourse.xml или *.properties в зависимости от того, что используется для хранения DATABASE URL);
3) настроить jboss/server/default/conf/jboss-log4j.xml, например, так:

    <appender name="JDBC" class="org.apache.log4j.DailyRollingFileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${jboss.server.log.dir}/jdbc.log"/>
        <param name="Append" value="true"/>
        <param name="Threshold" value="debug"/>
        <param name="DatePattern" value="'.'yyyy-MM-dd"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p [%t] [%c{1}] %m%n"/>
       </layout>
    </appender>

    <category name="jdbc.sqltiming">
        <priority value="DEBUG"/>
        <appender-ref ref="JDBC"/>
    </category>

    <category name="jdbc.connection">
        <priority value="DEBUG"/>
        <appender-ref ref="JDBC"/>
    </category>

----------------------------------------------------------------------------------------------------

Очень здорово, что на странице http://code.google.com/p/log4jdbc/ в разделе Similar Tools перечислены другие подобные по функционалу библиотеки. Так что если именно Log4jdbc не понравился, а решить задачу требуется, то можно попробовать другой инструмент.

----------------------------------------------------------------------------------------------------

В качестве заключения.
Log4jdbc - JDBC logging библиотека, работает как прокси между приложением и базой данных.
Встраивается в систему буквально в несколько действий.
Использует SLF4J, поэтому в реальном приложении отлично работает с несколькими логгерами. Настройка вывода информации выполняется через применяемый логгер.
Позволяет получить подробную информацию о взаимодействии между приложением и БД: тексты всех запросов (в т.ч. и PreparedStatement с реальными значениями), длительность их выполнения, операции с соединениями и другими объектами.

Комментариев нет:

Отправить комментарий