Hi,
Which dbconnection pool manager are you using and why have you the number
of connections set to such a low number? If you are expecting/testing 100's
of concurrent requests per second such a small pool could become exhausted
unless each request can be handled in a millisecond or 2. Even if not
exhausted you are likely to see a high level of contention and so delays at
the pool level. You seem to indicate contention and then exhaustion as you
say that it starts off quick, then slows down (contention) and then times
out (exhaustion/timeout). Unless you have any other restrictions do a test
run with the pool set to 50 and see what happens.
If you have the time to read up on yet another Java library you may find
java metrics useful
http://metrics.dropwizard.io/3.2.2/
This allows you to reduce the logging level and instead insert code that
records stats with detail being reported via histograms. It can make
understanding things like DB connections and query processing over time far
easier to understand.
Another nice tool you may want to look at is http://www.profilesql.com/ as
this provides a free in-line profiler for MySQL. By deploying this you will
be able to confirm how connections are being made/dropped and the time it
takes the database to process the request passed to it - the values you see
here should be far nearer to the values you see within mysql workbench, but
it's worth checking. In past projects I have found this very helpful as it
has allowed me to discover configuration issues with the db connection
pool, such as lack of reuse (lots of opens/closes) or lots of clean up
between reuse (re-issuing of default information).
I hope my comments are helpful.
Roger
On Thursday, April 6, 2017 at 10:29:53 PM UTC+1, [email protected] wrote:
>
> Hi Lukas,
>
> First, awesome product! you do an amazing job answering questions and
> helping. We definitely expect there will be some minor overhead as you
> mentioned.
>
> We're looking in to performance degradation as we increase the load in our
> service. Load testing is far from scientific, just using a threadpool to
> send traffic to one fairly simple API concurrently. We're running with 5 db
> connections in the pool (min=max=5). DB connection pool will wait 1000ms
> for a connection before timing out. The APIs are basically doing some reads
> or writes to a database. Some parts of the write APIs execute multiple
> writes with in a single transaction.
>
> What we're seeing is that under low loads the API performance is ok. The
> higher the number of concurrent requests, the api latency gets
> exponentially high. It also seems to get worse even with in a single run.
> E.g. if we do 300 concurrent requests, then some will still finish quickly.
> Then you see a long tail of requests out of the 300 that finish later and
> later (even to the point of minutes where the earlier ones may have
> finished in a 10s of milliseconds). I understand theres a lot of reasons
> where things could be slowing down. After 150ish concurrent connections, we
> see timeouts trying to get a free db connection from the pool.
>
> We've done some work to make sure the transactions use the same
> configuration/connection. I was expecting the the querying from DB to be
> super fast to the point where no API would be waiting 1000 milliseconds for
> an open connection in the pool. While we keep digging on this, I turned on
> the trace logging on the stop watch and the execute logging to see how long
> the queries were taking. Then I ran it with a single API call (so no
> concurrent calls). The numbers I was seeing with the execute logging turned
> on is what I pasted. I was alarmed to see the times I was seeing. Though I
> admit I didn't run them 1000s of times, the numbers after the very first
> API after a restart seem to remain pretty stable.
>
> The reason I started looking in to this was because I wanted to figure out
> why connections in the connection pool would be tied up for long periods of
> time. I'll keep digging on that further.
>
> Is there a way to find out how well things are performing in JOOQ without
> turning on the execute logging? What level of slow down can we attribute to
> the logging?
>
> One thing we noticed recently was we were keeping a cache of "Record"
> objects for some entities that rarely change. When we hand them out of the
> cache, we make a copy of it. We noticed that its using reflection for
> copying and is very slow. I wonder if there's a similar way we may be using
> JOOQ that causes excessive slow downs.
>
> Thanks again!
>
> Udam
>
>
>
> On Thursday, April 6, 2017 at 1:55:40 PM UTC-7, Lukas Eder wrote:
>>
>> 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.
