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 = ctx
  .select(T_AUTHOR.LAST_NAME, count().as("c"))
  .from(T_BOOK)
  .join(T_AUTHOR)
  .on(T_BOOK.AUTHOR_ID.eq(T_AUTHOR.ID))
  .where(T_BOOK.TITLE.ne("1984"))
  .groupBy(T_AUTHOR.LAST_NAME)
  .having(count().eq(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|
                         : +---------+----+

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.

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)

Binding variable 1       : 1984 (class java.lang.String)
Binding variable 2       : 2 (class java.lang.Integer)
Attaching                : RecordImpl [ RecordImpl [values=[null, null]] ]
Fetching record          : RecordImpl [values=[Coelho, 2]]
Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+

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. 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