Wanted to get an idea of what the performance impact is of using JOOQ and 
if there were ways to improve it.

Currently we're seeing pretty slow performance when using JOOQ for doing 
even very simple tasks. See output below from the StopWatch:

2017-04-06 10:45:25:428 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Initialising             : Total: 0.003ms
2017-04-06 10:45:25:428 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Rendering query          : Total: 0.231ms, +0.228ms
2017-04-06 10:45:25:428 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Executing query          : SELECT `session`.`id`, 
`session`.`created_date` FROM `session` WHERE (`session`.`id` = ? AND 
`session`.`created_date` = ?)
2017-04-06 10:45:25:429 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] -> with bind values      : SELECT `session`.`id`, 
`session`.`created_date` FROM `session` WHERE (`session`.`id` = 'abcd' AND 
`session`.`created_date` = {TS '2017-04-06 10:45:25.417'})
2017-04-06 10:45:25:429 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Query rendered           : Total: 1.166ms, +0.935ms
2017-04-06 10:45:25:429 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Preparing statement      : Total: 1.391ms, +0.225ms
2017-04-06 10:45:25:429 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Statement prepared       : Total: 1.645ms, +0.253ms
2017-04-06 10:45:25:430 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Binding variables        : Total: 1.814ms, +0.168ms
2017-04-06 10:45:25:430 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Variables bound          : Total: 2.113ms, +0.299ms
2017-04-06 10:45:25:430 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Executing query          : Total: 2.331ms, +0.217ms
2017-04-06 10:45:25:431 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Query executed           : Total: 3.486ms, +1.154ms
2017-04-06 10:45:25:432 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Fetching results         : Total: 4.052ms, +0.566ms
2017-04-06 10:45:25:432 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Fetching result          : Total: 4.304ms, +0.252ms
2017-04-06 10:45:25:432 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Fetching record          : Total: 4.576ms, +0.271ms
2017-04-06 10:45:25:432 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Record fetched           : Total: 4.796ms, +0.22ms
2017-04-06 10:45:25:433 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Fetched result           : 
+------------------------------------+-----------------------+
2017-04-06 10:45:25:433 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ]                          : |id                     
             |created_date           |
2017-04-06 10:45:25:433 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ]                          : 
+------------------------------------+-----------------------+
2017-04-06 10:45:25:434 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ]                          : | abcd |2017-04-06 
10:45:25.417|
2017-04-06 10:45:25:434 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ]                          : 
+------------------------------------+-----------------------+
2017-04-06 10:45:25:434 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Result fetched           : Total: 6.146ms, +1.349ms
2017-04-06 10:45:25:434 TRACE [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Results fetched          : Total: 6.374ms, +0.228ms
2017-04-06 10:45:25:434 DEBUG [dw-28 - POST /service/nonuilogin] 
[JooqLogger] [SdDYuJEQ] Finishing                : Total: 6.523ms, +0.148ms

This is run on a quad-core MacBook Pro with 16GB against a MySQL database 
running on the same machine. The same query run using mysql workbench would 
take roughly (duration/fetch time): 0.00074 sec / 0.000036 sec.

Seems like using JOOQ to execute the query causes several magnitudes more 
time. This causes us to have db connectionpool starvation (timeout waiting 
for an open connection) and terrible latencies when running with any 
concurrent traffic (even as low as 20 concurrent requests). 

I'd like to think that we're doing something wrong here with the way we're 
using JOOQ (we use dropwizard/jooq for our service). All these things that 
are taking a lot of time seem like things that are done with CPU cycles and 
I would have expected would run many magnitudes faster. If anyone can 
provide any hints about how we would get these latencies back down to 
decent levels, I would very much appreciate it.

Thank you!
Udam

-- 
You received this message because you are subscribed to the Google Groups "jOOQ 
User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to [email protected].
For more options, visit https://groups.google.com/d/optout.

Reply via email to