Debug logging SQL with jOOQ

This nice little feature is not much advertised in the jOOQ manual, but probably it’s something that most of us developers want and love when we have it. When you put log4j or slf4j on the classpath along with jOOQ, then jOOQ will use those frameworks for logging according to your configuration. While jOOQ is pretty quiet on ERROR/WARN/INFO level logging, it becomes quite a chatty tool on DEBUG/TRACE level.

DEBUG level logging example

Check out some sample DEBUG level output when executing this query:

Result<Record> result = create
  .select(TAuthor.LAST_NAME, create.count().as("c"))
  .from(T_BOOK)
  .join(T_AUTHOR)
  .on(TBook.AUTHOR_ID.equal(TAuthor.ID))
  .where(TBook.TITLE.notEqual("1984"))
  .groupBy(TAuthor.LAST_NAME)
  .having(create.count().equal(2))
  .fetch();

And the output is:

Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 3.911ms

The query text is printed to the log output with inlined parameters (i.e. bind variables are replaced for logging). Then a text table representation of the result’s first 5 rows is printed before the query execution time.

TRACE level logging example

On trace level, you can see even more of jOOQ’s internals, although usually this is only needed when debugging jOOQ:

Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Preparing statement      : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> cast(? as varchar) 
  group by "t_author"."last_name" 
  having count(*) = cast(? as int)

Statement prepared       : Total: 1.451ms, +0.435ms
Binding variable 1       : 1984 (class java.lang.String)
Binding variable 2       : 2 (class java.lang.Integer)
Variables bound          : Total: 1.808ms, +0.356ms
Attaching                : RecordImpl [ RecordImpl [values=[null, null]] ]
Fetching record          : RecordImpl [values=[Coelho, 2]]
Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 6.29ms, +4.481ms

In addition to the previously shown DEBUG-level output, you’ll also find the true SQL statement that is executed, including bind variables and some additional type-casts introduced by jOOQ. Time measuring is divided into 3 steps: statement preparing, variable binding, and statement execution. Also, all bind variables are documented, and every fetched record is documented. That’s a lot of logging. Be sure to turn it off when not needed!

Logging configuration

In future versions of jOOQ, logging will become more configurable