SQL Logging and Monitoring

From PatternTesting Wiki
Jump to: navigation, search

Version 1.3 brought the ConnectionMonitor which is based on the ProxyConnection to count the opened connections. Here you had to manually wrap the DB connection to help ConnectionMonitor to do his job.

With 1.4.1 a ProxyDriver was introduced to simplify the monitoring and to extend log output by SQL statements. All you have to do is the registration of the ProxyDriver for JDBC and to to use "jdbc:proxy:..." as JDBC URL.

Driver Registration

As an example we want to develop a litte bank application. Parts of this example you can find in samples-jfs2010 in the BankRepository class.

jdbc:hsqldb:mem

For testing we want to use a memory database like HSQL. The JDBC URL for it is jdbc:hsqldb:mem:TESTDB which is used by the DriverManager to get a connection:

   private static String JDBC_URL = "jdbc:hsqldb:mem:testdb";
   private static Connection getConnection() throws SQLException {
       return DriverManager.getConnection(JDBC_URL, "", "");
   }

But before you have to register this URL at the DriverManager. Usually this can be done by loading the driver class which do this registration itself:

   private static void loadDbDriver() throws ClassNotFoundException {
       Class.forName("org.hsqldb.jdbcDriver");
   }

That's all you have to do to get a connection to the database to store to or load data from it.

jdbc:proxy:hsqldb:mem

As mentioned in the intro PatternTesting provides an ProxyDriver which monitors the DB connections and allows you to log the executed SQL statements. To use this ProxyDriver you use now jdbc:proxy:hsqldb:mem:testdb as URL, i.e. you put a proxy: after the jdbc: prefix:

   private static String JDBC_URL = "jdbc:proxy:hsqldb:mem:testdb";

The ProxyDriver acts, as the name implies, as a proxy for the real DB driver to be able to monitor the opening and closing of DB connections. This means that both drivers (ProxyDriver and HSQL driver) must be loaded for the JDBC DriverManager:

   private static void loadDbDriver() throws ClassNotFoundException {
       Class.forName("patterntesting.runtime.monitor.db.ProxyDriver");
       Class.forName("org.hsqldb.jdbcDriver");
   }

You do not have to do it for HSQL because PatternTesting know the driver for it (also for some other databases). But it is recommended to do it because not all driver classes are known by PatternTesting.

ConnectionMonitor

If you use use 'jdbc:proxy:..." and the ProxyDriver to get a DB connection you can use the ConnectionMonitor to watch the connections. The ConnectionMonitor register itself as MBean at JMX so can use e.g. jconsole (which is part of the JDK) to look at the open connections.

jconsole with ConnectionMonitor MBean
If you open the filder 'patterntesting > runtime > monitor > db' in the management console ('jconsole') you can see the ConnectionMonitor with its different attributes:
Callers 
an array of the callers of the open connections (in this example only 1 connection is open)
ClosedConnections 
number of closed connections
LastCaller 
caller of the last opened connection
OpenConnections 
number of connections which are not yet closed and still open
SumOfConnections 
number of opened and closed connections

If the number of open connections grow with the time you probably have a problem and will run in a resource leak. The callers array help you to find the location in your code where you have forgot to close your connection.

Profiling with SqlStatistic MBean

jconsole with SqlStatistic MBean
As you can see in the 'jconsole' there is also a SqlStastistic MBean available. This MBean gives you some information about the SQL statements with the
  • maximal average of the kind of SQL statement (MaxAvg)
  • maximal hits of a SQL statement (MaxHits)
  • maximal time of a single SQL statement (MaxMax)
  • maximal time of a SQL statement in sum, i.e. which SQL statement need most of the time (MaxTotal)

Under Operations you can trigger three operations for that MBean:

reset 
resets the statistic
dumpStatistic 
writes the statistic of the SQL statements to a CSV file (watch the log for the name of it)
logStatistic 
logs the statistic of the SQL statements (again: watch the log)

You can also automate the dump of the SQL statistic if you register the SqlStatistic as shutdown hook:

   SqlStatistic.addAsShutdownHook();

If the Java VM will end the statistic will be automatically dumped into the temporary directory.

Logging

SQL Logging

To log the SQL statements set the log level for patterntesting.runtime.monitor.db to DEBUG:

log4j.rootLogger=INFO, STDOUT
log4j.logger.patterntesting.runtime.monitor.db=DEBUG
log4j.appender.STDOUT.layout.ConversionPattern=%-5p %-40.40c{3} %m%n

If this is your Log4J configuration (usually placed in 'log4j.properties'), you should see the executed SQL statements in your application log:

...
DEBUG nternal.StasiPreparedStatement "SELECT balance, name FROM accounts where number = 1" returned with true after 1 ms.
DEBUG nternal.StasiPreparedStatement "SELECT balance, name FROM accounts where number = 2" returned with true after 1 ms.
DEBUG nternal.StasiPreparedStatement "UPDATE accounts SET balance = 2125.00 WHERE number = 1" returned with 1 after 2 ms.
INFO  sample.jfs2010.BankRepository  account 1: 2125.00 $ was saved.
DEBUG nternal.StasiPreparedStatement "UPDATE accounts SET balance = 1276.00 WHERE number = 2" returned with 1 after 2 ms.
INFO  sample.jfs2010.BankRepository  account 2: 1276.00 $ was saved.
DEBUG nternal.StasiPreparedStatement "SELECT * FROM accounts WHERE name = 'oboehm'" returned with open JDBCResultSet after 1 ms.
INFO  sample.jfs2010.BankRepository  2 account(s) found for oboehm.
...

You can see the SQL statement which is executed independant from the DB and independant of the facilities of the JDBC driver. All you have to do is the registration of the ProxyDriver of PatternTesting.

SQL Logging with Stacktrace

The logging with stacktrace is available only in TRACE level. To activate it add the following line to your log4j.properties:

log4j.logger.patterntesting.runtime.monitor.db.SqlStatistic=TRACE

With this line not only the SQL statement is logged but also the method together with the stacktrace where it happened:

TRACE monitor.db.SqlStatistic "INSERT INTO accounts (balance, name) VALUES (0.00, 'nobody')" returned with 1 after 1 ms
	at patterntesting.sample.jfs2010.BankRepository.createAccount(BankRepository.java:186)
	at patterntesting.sample.jfs2010.BankRepository.createAccountFor(BankRepository.java:163)
	at patterntesting.sample.jfs2010.BankRepositoryTest.setUpRepository(BankRepositoryTest.java:53)