Hi Udam, Thank you very much for your message.
First off - be careful with what you measure. Measuring a single query execution in any tool is not going to give you any significant results. You'd have to at least benchmark e.g. 100 or better 10000 consecutive executions. Secondly, you seem to have turned on TRACE logging in jOOQ. This by itself causes significant overhead and is probably not what you want to do in production. I'm more than happy to help you improve your performance with jOOQ (there's always some overhead compared to JDBC, but it's far below even a factor, if done correctly) - but do you have any actual productive issues, or did you just notice these numbers in your TRACE log? Cheers, Lukas 2017-04-06 20:14 GMT+02:00 <[email protected]>: > 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. > -- 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.
