SQL logging about hikaricp

[cowwoc]

@brettwooldridge For what it's worth, I've successfully used https://github.com/p6spy/p6spy multiple times, and it seems to be (slightly) better maintained than log4jdbc-log4j2. At least there are consistent, recent commits.

I installed it as follows:

1. Added the Maven dependency to my project

<dependency>
	<groupId>p6spy</groupId>
	<artifactId>p6spy</artifactId>
	<version>3.6.0</version>
</dependency>

2. Created spy.properties in src/main/resources with the following content:

driverlist=org.postgresql.Driver
appender=com.p6spy.engine.spy.appender.Slf4JLogger

3. Changed the JDBC URL in my application from jdbc:postgresql://hostname/databaseName to jdbc:p6spy:postgresql://hostname/databaseName

That's it. Easy peasy.

[brettwooldridge]

As documented on the project page:

Log Statement Text / Slow Query Logging

Like Statement caching, most major database vendors support statement logging through properties of their own driver. This includes Oracle, MySQL, Derby, MSSQL, and others. Some even support slow query logging. We consider this a "development-time" feature. For those few databases that do not support it, jdbcdslog-exp is a good option. Great stuff during development and pre-Production.

In summary, we are unlikely to implement this feature as it impacts performance even when logging is turned off.

[odwrotnie]

:(

[brettwooldridge]

Even checking a boolean flag for whether logging is enabled or disabled is too much overhead for HikariCP. Almost every driver supports logging of some sort, and ORMs inevitably do.

Alternatively, use BoneCP in development and HikariCP in production. And if you need logging at the SQL statement level in production, you don't need the performance of HikariCP because logging is a performance killer.

[vinov]

I am sure you would be able to solve this without performance impact - with a logging/non logging strategy pattern or something similar.

Sure there are other ways to log SQL, but we support more than one database vendor, and use single point logging configuration through logback, which would by difficult with custom driver logging.

[patric-r]

I would also love to see such a feature within HikariCP.
I can't imagine that checking a nearly-constant boolean flag can affect real-life performance of HikariCP when thinking of modern JIT-Compilers and CPUs which contain highly sophisticated branch predictors...

[patrik7]

+1; Eventhou mysql server does this as well. I would like to be able to be enabled logging just for testing and dev deployes. Changing my.cfg and restarting DB server is extremely cumbersome.

[twiho]

+1 for having this. How does it affect performance when turned off? I can't imagine that.

[billoneil]

I have been using HikariCP for close to two years and I have never needed this feature. SQL logging doesn't belong in the connection pool. I use JOOQ with HikariCP and JOOQ provides all the custom logging I need for dev / local. I am sure Hibernate / JPA / JDBI offer similar features.

HikariCP is a very high performance connection pool. All logging related to pooling connections is readily available. It is not a one stop shop tool for profiling your database and making your life easier. It does one thing very well and that is all it should do.

[brettwooldridge]

@billoneil I want to hug you, or buy you a beer.

[slyoldfox]

@brettwooldridge Do you have any experience combining jdbcdslog and hikaricp (or any other logging framework). Something that is generic and can be centralized (at the moment we have several datasources and a mix of mybatis and hibernate jpa). Because of that, I don't want to bother with driver specific logging or dao framework specific logging).

We instantiate HikariDataSource(HikariConfig).

Should I wrap the HikariDatasource in an jdbclog ConnectionPoolDataSourceProxy?

Any code examples/experiences you have if you have are welcome (or maybe documented on one of your awesome wiki pages).

[gcardoso22]

@slyoldfox Did you manage to solve that?

[slyoldfox]

@balizeiro no I haven't looked further into it how I would incorporate some framework into our framework. If i do, I'll share it. If @brettwooldridge has any smart experiences, I hope he shares them :) We mixed javamelody at one point, but it seemed that activates itself when it's in the classpath, which is a designed decision by the programmer, however I'd like something that can be switched on an off if feasible and of course with not too much overhead (and yes I do know that any kind of such monitoring will have performance impact).

[patrik7]

We also weren't able to find sufficient replacement for deprecated JDBC's logging. @brettwooldridge I understand your point and I love your determinism and pride you take in keeping Hikary efficient, but I would still urge you to reconcider.

I would argue that modern CPUs have high quality jump predictions built in, and last time I checked I wasn't able to measure time cost of an if clause. (I worked for high-frequency trading shop). Even if there was a time penalty, If you look at how long a DB query is going to take, an extra 20-30 ns to check a logger flag will be absolutely negligible.

[brettwooldridge]

@patrik7 What detail level of logging are you looking for?

[patrik7]

Thanks Brett, the SQL statements that are going out to DB would be great. Specifically: select, update, delete, etc.

I am not sure if transaction boundaries: open and commit make sense. That would only be usefull if we could somehow match them to the previously mentioned statements.

Let's keep it simple.

[brettwooldridge]

@patrik7 What about logging PreparedStatement parameters? PreparedStatement.addBatch()? Log at INFO?

[ams2990]

Is there some reason log4jdbc is inadequate here? When I needed to see the statements my driver was producing, I used that and it worked well.

[brettwooldridge]

@ams2990 Thanks for that project ref, I wasn't aware of it. I've added it to the main project page.

[patrik7]

@ams2990 I also wasn't aware of it, if we decide to close this ticket again I would definitelly give it a try.

@brettwooldridge The statement parameters are definitelly useful. I would log at DEBUG or TRACE, It will be heavy.

[brettwooldridge]

@patrik7 @ams2990 We will have to consider it, but it may be worth it to invest development effort in log4jdbc, rather than recreating the same functionality in HikariCP. It looks like they have a lot of open issues, and little activity since 2012 if their release log is to be believed.

[brettwooldridge]

@ams2990 @patrik7 Can either of you give me a list of JDBC drivers that do not inherently have logging on their own?

[slyoldfox]

Just for the sake of discussion (not really because I think this needs to be pushed in HikariCP). We have always worked with the following:

1. request.log for web applications
   This usually holds the uri, request duration, viewName (if spring model), .. and also the number of queries and total db-query time executed on that request. It is logged in a well parsable format, so you can grep/awk/export to excel/logstash it. During peek moments, we usually analyze the longest request. Or look at the pages with too much queries per request. Or look at the difference between db-query time and request query time. We used to have some code which logs this using a helper class where a ThreadLocal (yes we know about the PITAs of ThreadLocals) would keep two counters, one for the number of connections/queries executed and one for the total query time. I doubt if HikariCP can assist in this situation, because it's quite heavily tied to the request-logic.
   We also inject a UUID in the log file via MDC, which can be used to trace in other logfiles (e.g. the query.log below). https://bitbucket.org/beforeach/logging-module/src/32d6101592d6a3bd0a32d5dc410943977d4adea6/logging-module/src/main/java/com/foreach/across/modules/logging/request/RequestLoggerFilter.java?at=develop&fileviewer=file-view-default is the example of the RequestLoggerFilter in our logging-module. It's a java "module" based on the "across" framework. A framework we are creating to introduce "modules" on top of the spring framework - where each "module" uses its own Spring ApplicationContext. Much like drupal has modules. Read more about it on https://foreach.atlassian.net/wiki/display/AX/Across+Home if you are interested.
2. query.log
   This holds all executed queries. The UUID from the request is also injected via MDC in this log file. @brettwooldridge instead of logging with INFO or DEBUG or TRACE, we made the log levels configurable via a builder (see https://bitbucket.org/beforeach/logging-module/src/32d6101592d6a3bd0a32d5dc410943977d4adea6/logging-module/src/main/java/com/foreach/across/modules/logging/request/LoggerLevelThreshold.java?at=develop&fileviewer=file-view-default). The builder allows you to define thresholds which impact the log level. E.g. i can setup logback to level="DEBUG" for query.log. And set the threshold of INFO to "200". This means that queries running longer than 200 will be logged as "INFO". All the rest will be "DEBUG". If you add a threshold of "WARN" at 5000, all queries between 200-5000 will be logged as INFO, everything >5000 will be WARN. It also allow ERROR, and so on.
   This allows for easy grepping/filtering when you are doing some log file analyses. The same logic is being used in the RequestLoggerFilter above, so you can look how it is used there. No rocket science. But I would avoid just picking "DEBUG" or "INFO".

[brettwooldridge]

@slyoldfox I'm starting a page on JDBC Logging. Looking at some of what you guys are upto above, have you looked at log4jdbc-log4j2?

It seems to support logging at different levels (WARN or ERROR) based on query execution time. Not sure on the MDC. It allows a user-defined logging adapter, which may also afford some extensibility.

Just thought it was interesting.

[patrik7]

It is, I did not try going down to the driver level, but rather up to the eBean level which was very cumbersome. I will give it a try. Thanks!

[patrik7]

@brettwooldridge We have successfully used log4jdbc-log4j2 with mysql JDBC driver within Play 2.4 application. The setup was far from intuitive, but it does what it's supposed to.

Thanks for your help. I don't think we need to change HikariCP.

[brettwooldridge]

@cowwoc Thanks for the feedback! I updated the main project page with a link to your comment above.

[lasneyx]

I can confirm that what @cowwoc is working with MySQL and p6spy too:

The only tweak in MySQL is that you need to provide the jdbcUrl and driverClassName too.

XML spring based configuration:

<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
        <property name="poolName" value="springHikariCP" />
        <property name="jdbcUrl" value="jdbc:p6spy:mysql://hostname:port/etc"/>
        <property name="driverClassName" value="com.p6spy.engine.spy.P6SpyDriver"/>
        <!-- Remainder omitted -->
</bean>