db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bergquist, Brett" <BBergqu...@canoga.com>
Subject RE: Really need some help here please. I think I am having a problem with some sort of caching in Derby
Date Wed, 28 Mar 2012 14:39:21 GMT


-----Original Message-----
From: Mike Matrigali [mailto:mikem_app@sbcglobal.net]
Sent: Tuesday, March 27, 2012 8:33 PM
To: derby-dev@db.apache.org
Subject: Re: Really need some help here please. I think I am having a problem with some sort
of caching in Derby

Bergquist, Brett wrote:
> Derby is giving me fits but I just found a reproducible pattern.   The
> problem that I am having is that queries that are totally index based
> without any changing of the query plan are becoming slow.   Normally the
> query takes about 6 milliseconds and it quickly degrades to 20 seconds
> or more.
>
>
>
> Here is some  background.  The system is quite busy with about 40%
> system utilization for Derby.  Heap used space is around 2Gb out of
> 4Gb available.  Java is Oracle Java 1.6 and using the UseParallelGC
> parameters for garbage collection.
>
>
>
> There are thousands of statements being executed and most of these are
> new statements so few prepared statements are probably being used.
Is it possible to change this, are all the statements really different, or could they be rewritten
to be parameterized.  Even if individual connections don't do:
prepare
execute prepared with params
and instead just do
execute statement with params

derby has a cache of statements and you could possibly eliminate a lot of the class garbage.

[bb] Unfortunately the queries are generated from Java Persistence Architecture (JPA) using
EclipseLink.  So changing what that is generating at this time is not practical.

I did find one problem yesterday related to the statement chache in that the statement cache
is very small by default (100 statements) and that the property to change this is in none
of the documentation (manuals).  Zero.  I found this by going through the code.  There is
a reference to disabling the statement cache in the Wiki but nothing else other than this
bug:

https://issues.apache.org/jira/browse/DERBY-4280

So with many unique statements, this cache is really thrashing.  Overnight, I increased this
cache to 10000 statements and my test setup was able to run continuously with negligible increased
memory consumption.

Also, looking at the cache, I think it could be improved here.  One thought comes to mind
is to cache things that are "expensive".  So take a simple query that uses one table returning
a row that is using an indexed lookup.  This seems to compile very quickly.  As an example,
the application server can use a JDBC Realm for authentication.  Each time the user is authenticated,
the authentication time is logged.  Using a web server that authenticates and is hit very
often, a statement such as "update j2ee_users set last_login_tme = current_time() where username
= 'xxx'" is done very often.  The application server generates the code, so rewriting this
to use a prepared statement is not practical.   Yet this statement can quickly trash the statement
cache because the current_time() is going to be unique on each call.   This statement compiles
very quickly but floods the cache flushing out other statements that may be more expensive
to cache.

So my thinking might be to weight the replacement of an entry in the cache by the cost of
the statement.  So don't replace a statement that compiles and optimizes with a high cost
with a statement that compiles and optimizes with very little cost.  Maybe add in an age factor
on this such that if a cached statement has not been hit for a long time it is replace.  
So the replacement would take into the cost and age of a statement before replacing it.

Just thinking now, a quick and dirty might be to never cache a statement this is only going
to use one table as this should be pretty quick to compile as the optimizer needs to chose
a table scan or index scan based on the constraints and not much more.  So the example above
of the "update j2ee_users" would not be cached and not flood the cache.

I also played with the "derby.language.statementCacheSize" and set it to 0 just to force a
test case.  When I did this, a set of queries such as:

CALL SYSCS_UTIL.SYSCS_CHECKPOINT_DATABASE();
CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(1);
SELECT * ....
VALUES SYSCS_UTIL.SYSCS_GET_RUNTIMESTATISTICS();
CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(0);

fails.  Rather the " VALUES SYSCS_UTIL.SYSCS_GET_RUNTIMESTATISTICS();" fails.  Probably this
is looking at the cache to get the statistics and now there is no cached statement so no statistics.
 So the idea above of not caching certain things would probably need some work.  I bet a good
test case for this would be to set a statement cache size to 1 and execute the above sequence
and probably this will fail right away as the "VALUES ..." would replace the "SELECT ..."
in the cache and then not find the statistics for "SELECT ..."


> Using jvisualvm, I can see new classes being created and loaded every
> second.
>
>
>
> JvisualVM is showing a GC Activity of about 1.5% so the system is not
> being hammered by the garbage collector.   Also the "old" memory is
> glowing really slowly.
>
>
>
> So what I found is that if I hit the "Perform GC" button on JvisualVM
> to perform an explicit garbage collection, the same query that was
> taking
> 20 seconds or more instantaneously comes down to taking about 6
> milliseconds.  Its processing time then starts to creep up back
> towards
> 20 seconds or more.
Is it possible that the jvm's ability to present memory to derby's requests just slows down
as more garbage is put in the pool?  Garbage has always been a performance problem for derby,
so a lot of code it has is written to not create garbage if possible.  So the caches of pages
reuse the arrays for the pages, a scan of a million rows uses a small number of container
rows that are reused.  I guess the real question is if the jvm can start taking on the order
of seconds to return a memory request, and then if that happens I could come up with many
places in derby code where we might be holding latches that might stall every one and maybe
those stalls might be busy waits like:
lock manager critical section
buffer manager critical section
log system

[bb]
As a further test, I disabled all activity to the database so that there was no other statements
being executed at all.  CPU utilization drops to near zero.   The heap being used was about
2.5Gb out of 4G.  Note that the JVM was started with -Xmx4096 -Xms4096 so the heap is initialized
at startup and never grows.  Run the query and it took a long time.   Run the test all over
again and this time causing significant utilization and then shut everything down, force a
garbage collection, and then run the query and it performed in a couple of seconds.

Now this just might be a coincidence with the query being in the statement cache and maybe
I hit is just right on each test where the statement was not in the cache when the query took
a long time and the statement was in the cache when I did the garbage collection and the query
returned.

>
>
>
> Note that the system utilization does not decrease immediately after
> performing the forced garbage collection.  It is still just as busy at
> about 40% cpu utilization.
without understanding how many threads are active and their makeup, like i have said 40% is
sort of meaningless.  derby's ability to use up a cpu is pretty much 1 per active thread in
the system.
>

[bb] The test system is an Oracle M3000 with 8 cores and 32Gb of memory.  So it was not CPU
bound, I/O bound (especially when I shut everything down accessing the database), or memory
bound.

>
>
> Just on a whim, right now, I put "CALL
> SYSCS_UTIL.SYSCS_CHECKPOINT_DATABASE();" just in front of my query
> (through SquirrelSQL) and executed both at the same time so that I could
> eliminate the page cache as being a performance helper.   Still the same
> pattern.      After the system runs for a few minutes at this really
> busy, many thousands of statements, trying the query takes tens of
> seconds.   Force a garbage collection and the query immediately takes
> milliseconds and then starts to degrade.
>
note checkpoint just writes dirty pages from cache to disk but does not change the makeup
of the cache.  I guess it might make it quicker to get a new page in the cache if you have
filled the cache.

[bb] So the Derby tuning guide should mention this.  Page 21 of this guide says to use " Create
a benchmark test suite against which to run the sample queries. The first
thing the test suite should do is checkpoint data (force Derby to flush data to disk)."

It then goes on to say:

Use performance timings to identify poorly performing queries. Try to distinguish
between cached and uncached data. Focus on measuring operations on uncached
data (data not already in memory). For example, the first time you run a query,
Derby returns uncached data. If you run the same query immediately afterward,
Derby is probably returning cached data. The performance of these two otherwise
identical statements varies significantly and skews results.

So as a user, this really seemed to imply that the "SYSCS_UTIL.SYSCS_CHECKPOINT_DATABASE();"
would help to do this.  Probably it would be better to supply a system procedure to flush
the page cache or at least say to set the page cache size to something small (the documentation
says that 40 pages is the minimum but I would need to look at the code).

>
>
> Another point, I also found that even when the parallel garbage
> collection performs a major collection on its own (I watch this happen
> with jvisualvm), that the query immediately becomes responsive right
> after this.
>
>
>
> So I am wondering if there is some sort of cache in Derby that is
> getting really big and slow to find something in that gets cleanup
> when an major garbage collection happens.
>
>
>
> Any thoughts on this?
>
>
>
> Any pointers to code to check or something to try in the code will be
> most welcome.  I am comfortable with building Derby from source....
I don't think derby uses any fancy java stuff in it's cache's that would interact with garbage
collection like you are looking for, but stuff may have changed since I have looked at it.
 The interesting caches I would look at would be:
page buffer cache
query plan cache
open file cache

[bb] I went through the code looking for WeakReference or WeakHashMap or SoftReference which
would be things that could be forced by the GC to be freed.  I only found a few and these
don't seem to be relevant as far as I can tell.   There was only one that had a WeakHashMap
that its keyset was being iterated and I did not see where the entries were being cleared.
 I believe it was in connection class and may be related to XA processing (which we are doing
a lot of).  I will look closer.

Sounds like you have it down to
pretty reproducible in your environment.  Some suggestions:
1) determine if the "slow" query execution is using the same query plan
    as the "fast" one.   Maybe you have already done this as part of your
    previous problem.

[bb] With the query that I was testing, I now believe it is because of the statement cache
problem.  The query joins 7 tables, the plan that the optimizer finds is the best plan, but
it does take a long time to compile.  So probably the optimizer is doing something like 7
combinations.   Through SquirrelSQL, when the statement is not in the cache, it takes about
12 seconds to compile and execute.  If I force the join order with "joinOrder=fixed", it takes
about 0.169 seconds to execute, so I am pretty sure the time is in the optimizer.

Once point in there when looking at the code is that the optimizers seems to be unbounded
in time.  I see code checking for a maximum time but this is set to the maximum double size
to start and only take effect if the optimizer determines the time to create the plan is going
to be greater than just executing the query.   Maybe there should be a configurable parameter
that specifies a maximum optimizer time so that it gives up say after 2 seconds and just executes
what it has.  I need to look at this more.

2) does your app use blobs or clobs.  I do know that in some situations
    we need to keep locks on these when they are returned to users and those locks are cleared
on gc if the application does not explicitly release them.  your wait time of 20 seconds sounds
a lot like the time for a lock timeout.  does your application get lock timeouts and maybe
automatically retry?  Maybe as a test you could set

[bb] No blobs or cblobs.  Locks can be held for a while and that is an artifact of the design
which may have some problems.  The code is talking to a the database and to a physical network
device over a communications link that is pretty oversubscribed.  The system keeps a "model"
copy of what is configured in the device and so each interaction first updates the database
(the model) and then the device.  If a failure occurs in communicating with the device or
a failure occurs in actually updating the device configuration, the database transaction is
rolled back.   So the general flow is:

1. query and update database
2. query and update device
3. commit or rollback changes to the database

So locks can be held for a period of time.  The protocol to talk to the device is SNMP with
time outs of something like 5 seconds and 3 retries (plus the original) for a single SNMP
message to the device and there may be hundreds that are transferred between the code and
the device.   For the most part, optimistic locking (JPA) is done but I found a few places
in the system where the database operations were flushed to Derby which can cause row and
table locks to be acquired.

2) once you eliminate query plan then that kind of difference obviously
    means your thread is waiting on something.  Now you need to figure
    out what.  The full on answer might be to run a performance analyser
    on the system and compare when it runs fast and slow.   If you can
    really force the 20 second wait, maybe you can do the poor mans version of this and just
cause the system to dump all the stacks of all the threads every second or so and see if you
can catch the wait.  The trick here is to be able to identify the thread you are interested
in, which is much harder in network server vs embedded mode.  What I would be inter
>
>
>
> Brett
>
>
>

[bb] Thanks for your thoughts Mike.  I think the statement cache is probably one of the biggest
problems that I am seeing now that I understand it better.  Also looking into the optimizer
gives me a hint as to why some statements take a long time to optimize.   Unfortunately some
of the queries are being done behind the scenes are difficult to change.   Also testing this
beast (my application) is difficult just from a logistical problem of simulating (correctly)
tens of thousands of network devices.  So in some of our testing, we  have not really hit
these problems and they are being found in production.







Mime
View raw message