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
One thought on “Debug logging SQL with jOOQ”