db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Sachin Chitale <sachit...@yahoo.com>
Subject Derby process taking up more than 20% of cpu for more than 5hrs with only one user connected.
Date Fri, 20 Apr 2007 14:26:36 GMT
Hi,

To give you a background of what I was testing:

We have process that uses database as our guranteed message store. To give a 
stress test to Derby, this program was run to store about 70k+ messages. Then 
a subscriber was started to fetch the messages. But it seems that the database 
has stopped responding to the requests.

Initially I was able to get message count using:
ij>  select count(*) from M_20070129MESSAGES;
1
-----------
54598

After ~15 minutes.
1 row selected
ij> select count(*) from M_20070129MESSAGES;
ERROR 40XL1: A lock could not be obtained within the time requested
ij> select count(*) from M_20070129MESSAGES;
ERROR 40XL1: A lock could not be obtained within the time requested

ij> select count(*) from M_20070129MESSAGES;
ERROR 40XL1: A lock could not be obtained within the time requested
ij> select * from M_20070129MESSAGES where MESSAGEID='000000000000000000001746'
;
MESSAGEID               |MES&
-----------------------------
ERROR 40XL1: A lock could not be obtained within the time requested

When I did prstat on the running derby process it gave the following result:
-------------------------------------------
   PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
 27823 schitale  76 1.0  -   -   -   -   21  -   73 127 767   0 java/28
 27823 schitale 0.5 0.0  -   -   -   -   62  -    2  38  40   0 java/2
 27823 schitale 0.5 0.0  -   -   -   -   62  -    2  36  38   0 java/4
 27823 schitale 0.5 0.0  -   -   -   -   62  -    2  37  39   0 java/3
 27823 schitale 0.5 0.0  -   -   -   -   62  -    2  36  38   0 java/5
 27823 schitale 0.2 0.0  -   -   -   -   62  -    0   0   0   0 java/11
 27823 schitale 0.2 0.0  -   -   -   -   62  -    0   0   0   0 java/12
 27823 schitale 0.1 0.0  -   -   -   -   62  -    1   0   5   0 java/6
 27823 schitale 0.1 0.0  -   -   -   -   62  -    1   0   8   0 java/27
 27823 schitale 0.0 0.0  -   -   -   -   63  -    4   0  12   0 java/8
 27823 schitale 0.0 0.0  -   -   -   -   63  -    5   0  12   0 java/7
 27823 schitale 0.0 0.0  -   -   -   -   63  -    0   0   0   0 java/1
 27823 schitale 0.0 0.0  -   -   -   -   63  -    0   0   0   0 java/10
 27823 schitale 0.0 0.0  -   -   -   -   63  -    0   0   0   0 java/15
 27823 schitale 0.0 0.0  -   -   -   -  100  -    0   0   0   0 java/14
  NLWP USERNAME  SIZE   RSS MEMORY      TIME  CPU
    20 schitale 6610M 5433M    34%   1:59.03  23%
Total: 1 processes, 20 lwps, load averages: 1.12, 1.12, 1.21

Thread no 28 was taking us most of the CPU time, and 23% was the total CPU 
cycle share was taken up by derby process.

To find out which java thread was taking time I did a jstack of the process 
which revealed the following:

jstack 27823
--------------------------------------------------------------------------
Thread t@28: (state = IN_JAVA)
 - java.util.Hashtable.get(java.lang.Object) @bci=45, line=339 (Compiled 
frame; information may be imprecise)
 - org.apache.derby.impl.store.raw.data.FileContainer.getUserPage
(org.apache.derby.impl.store.raw.data.BaseContainerHandle, long, boolean, 
boolean) @bci=48 (
Compiled frame)
 - org.apache.derby.impl.store.access.btree.BTreeScan.reposition
(org.apache.derby.impl.store.access.btree.BTreeRowPosition, boolean) @bci=114 
(Compiled frame
)
 - org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows
(org.apache.derby.impl.store.access.btree.BTreeRowPosition, 
org.apache.derby.iapi.types
.DataValueDescriptor[][], org.apache.derby.iapi.types.RowLocation[], 
org.apache.derby.iapi.store.access.BackingStoreHashtable, long, int[]) @bci=31 
(Compiled
 frame)
 - org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext
(org.apache.derby.iapi.types.DataValueDescriptor[]) @bci=29 (Compiled frame)
 - org.apache.derby.iapi.store.access.DiskHashtable.get(java.lang.Object) 
@bci=4 (Interpreted frame)
 - org.apache.derby.iapi.store.access.BackingStoreHashtable.get
(java.lang.Object) @bci=27 (Interpreted frame)
 - org.apache.derby.impl.sql.execute.HashScanResultSet.getNextRowCore() 
@bci=64 (Interpreted frame)
 - 
org.apache.derby.impl.sql.execute.NestedLoopLeftOuterJoinResultSet.getNextRowCo
re() @bci=98 (Compiled frame)
 - org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore() 
@bci=30 (Compiled frame)
 - org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore() 
@bci=30 (Compiled frame)
 - org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore() 
@bci=30 (Compiled frame)
 - org.apache.derby.impl.sql.execute.AnyResultSet.getNextRowCore() @bci=25 
(Interpreted frame)
 - org.apache.derby.exe.ac2c864112x0112x0e5dx37f1x00000ec63ae01.g0() @bci=330 
(Interpreted frame)
 - org.apache.derby.exe.ac2c864112x0112x0e5dx37f1x00000ec63ae01.e1() @bci=1 
(Interpreted frame)
 - org.apache.derby.impl.services.reflect.DirectCall.invoke(java.lang.Object) 
@bci=72 (Compiled frame)
 - org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore() 
@bci=71 (Compiled frame)
 - org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore
(org.apache.derby.iapi.sql.execute.NoPutResultSet) @bci=1 (Compiled frame)
 - org.apache.derby.impl.sql.execute.DeleteResultSet.open() @bci=5 
(Interpreted frame)
 - org.apache.derby.impl.sql.GenericPreparedStatement.execute
(org.apache.derby.iapi.sql.Activation, boolean, long) @bci=341 (Compiled frame)
 - org.apache.derby.impl.jdbc.EmbedStatement.executeStatement
(org.apache.derby.iapi.sql.Activation, boolean, boolean) @bci=183 (Compiled 
frame)
 - org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement
(org.apache.derby.iapi.sql.Activation, boolean, boolean) @bci=16 (Compiled 
frame)
 - org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute() @bci=9 
(Compiled frame)
 - org.apache.derby.impl.drda.DRDAStatement.execute() @bci=4 (Interpreted 
frame)
 - org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTT() @bci=668 
(Compiled frame)
 - org.apache.derby.impl.drda.DRDAConnThread.processCommands() @bci=1153 
(Compiled frame)
 - org.apache.derby.impl.drda.DRDAConnThread.run() @bci=111 (Compiled frame)
-----------------------------------------------------------------------

Then I ran a script which recorded these two outputs at ~30 sec interval. Most 
of the time the Derby process was executing the following method:

org.apache.derby.impl.store.raw.data.FileContainer.getUserPage(...)

The derby process is now running for more than 5hrs but the command:
kill -3 <derby-pid>
doest show any deadlock.

I would like to send the log of the jstat and prstat output (~164kb), to Derby 
developers if interested.

Regards,
Sachin



Mime
View raw message