Thanks again. The network server trace was after I could not connect with any
client and I did not look closely at it ;) Before that point, there was a
thread that looked like:
"NetworkServerThread_2" prio=6 tid=0x030fc800 nid=0x121c runnable
[0x0357f000..0x0357fa94]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x22efa880> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at org.apache.derby.impl.drda.ClientThread$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.derby.impl.drda.ClientThread.run(Unknown Source)
That would be the server's connection handling thread, right? So you are
correct, it seemed to be gone when the server was completely locked up.
Unfortunately I was running within my IDE (Netbeans) and I guess it does not
have it appending to the derby.log because whatever error message that might
have been there is gone :( I will fix that!
Yes, running under Windows as my test/development box. Java 1.6.0_03 is being
used as that is what is being run in production at this moment. I don't want
to change too much at once to ensure I know what I change has an effect,
positive or negative.
Not using time slicing, no SSL, no security on this test/development box. All
good suggestions.
I took a look at the DRDA stuff and will enable tracing on the next test run.
Currently running a test and am up to about 60K transactions successful with no
problem at this point using the non-XA client driver. If this runs for about
200K worth of transactions, I will put the other driver back in place and see
if the problem re-appears to try to isolate it to the driver. Previously it
has failed between 80K and 120K transactions each time, so this will be a good
test.
Again, thank you for help in pointing me to where to try to debug this. Much
appreciated.
Brett
-----Original Message-----
From: Kristian Waagan [mailto:[email protected]]
Sent: Tuesday, November 16, 2010 10:57 AM
To: [email protected]
Subject: Re: Derby 10.5.3.0
On 16.11.10 16:27, Bergquist, Brett wrote:
> Okay, thanks for the feedback. Just a little more info. I was using the XA
> client driver. I am now trying try reproduce with just the standard local
> client driver to see if this makes a difference. I don't actually need the
> distributed transaction support at this time.
Running with the non-XA driver is a good idea, as the XA driver is a bit
different from the other(s).
> Also, here is the jstack trace of the network control server process just in
> case it might trigger some insight. I don't see anything standing out
> however. Note that shortly there after, no connection to the database would
> succeed. I tried connecting with Squirrel SQL client and that also hung.
As far as I can see from the stack trace below, there is no thread
accepting new connections. Why has it died?
Further questions/observations:
o the Java version is fairly old.
o are you using time slicing, session capping (maxThreads), SSL or a
non-default Derby security mechanism?
o is seems you are running on Windows.
o have you checked that nothing is printed to the console?
(where you start the server by running NetworkServerControl)
Note that I'm just throwing stuff at you here :)
The best way to get this debugged and fixed is to provide a runnable
repro, but based on what I've learned so far that may include quite a
bit of work...
--
Kristian
> 2010-11-16 09:11:27
> Full thread dump Java HotSpot(TM) Client VM (1.6.0_03-b05 mixed mode,
> sharing):
>
> "DRDAConnThread_13" prio=6 tid=0x02e8f000 nid=0x66e4 runnable
> [0x0395f000..0x0395fa94]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "DRDAConnThread_12" prio=6 tid=0x02e8e800 nid=0x11f0 runnable
> [0x0390f000..0x0390fb14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "DRDAConnThread_10" prio=6 tid=0x03136c00 nid=0x2098 runnable
> [0x0386f000..0x0386fc14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "DRDAConnThread_8" prio=6 tid=0x02b29000 nid=0x3094 runnable
> [0x037cf000..0x037cfd14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "DRDAConnThread_6" prio=6 tid=0x03119400 nid=0x2a7c runnable
> [0x0372f000..0x0372fa14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "DRDAConnThread_4" prio=6 tid=0x02a41800 nid=0x83f4 runnable
> [0x0368f000..0x0368fb14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "derby.rawStoreDaemon" daemon prio=6 tid=0x030aa000 nid=0x2c44 in
> Object.wait() [0x0363f000..0x0363fb94]
> java.lang.Thread.State: TIMED_WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22f00c60> (a
> org.apache.derby.impl.services.daemon.BasicDaemon)
> at org.apache.derby.impl.services.daemon.BasicDaemon.rest(Unknown
> Source)
> - locked<0x22f00c60> (a
> org.apache.derby.impl.services.daemon.BasicDaemon)
> at org.apache.derby.impl.services.daemon.BasicDaemon.run(Unknown
> Source)
> at java.lang.Thread.run(Thread.java:619)
>
> "DRDAConnThread_3" prio=6 tid=0x02f5e400 nid=0x2fa8 runnable
> [0x035ef000..0x035efc14]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at org.apache.derby.impl.drda.DDMReader.fill(Unknown Source)
> at
> org.apache.derby.impl.drda.DDMReader.ensureALayerDataInBuffer(Unknown Source)
> at org.apache.derby.impl.drda.DDMReader.readDssHeader(Unknown Source)
> at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown
> Source)
> at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
>
> "Timer-0" daemon prio=6 tid=0x0303b400 nid=0x6774 in Object.wait()
> [0x0353f000..0x0353fd14]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22ee2388> (a java.util.TaskQueue)
> at java.lang.Object.wait(Object.java:485)
> at java.util.TimerThread.mainLoop(Timer.java:483)
> - locked<0x22ee2388> (a java.util.TaskQueue)
> at java.util.TimerThread.run(Timer.java:462)
>
> "derby.antiGC" daemon prio=2 tid=0x02e51c00 nid=0x5da4 in Object.wait()
> [0x034df000..0x034dfd94]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22ec01e0> (a
> org.apache.derby.impl.services.monitor.AntiGC)
> at java.lang.Object.wait(Object.java:485)
> at org.apache.derby.impl.services.monitor.AntiGC.run(Unknown Source)
> - locked<0x22ec01e0> (a
> org.apache.derby.impl.services.monitor.AntiGC)
> at java.lang.Thread.run(Thread.java:619)
>
> "Low Memory Detector" daemon prio=6 tid=0x02a6d000 nid=0x8b9c runnable
> [0x00000000..0x00000000]
> java.lang.Thread.State: RUNNABLE
>
> "CompilerThread0" daemon prio=10 tid=0x02a68400 nid=0x3258 waiting on
> condition [0x00000000..0x02d1f798]
> java.lang.Thread.State: RUNNABLE
>
> "Attach Listener" daemon prio=10 tid=0x02a67000 nid=0x46cc waiting on
> condition [0x00000000..0x00000000]
> java.lang.Thread.State: RUNNABLE
>
> "Signal Dispatcher" daemon prio=10 tid=0x02a66400 nid=0x4714 runnable
> [0x00000000..0x00000000]
> java.lang.Thread.State: RUNNABLE
>
> "Finalizer" daemon prio=8 tid=0x02a5e800 nid=0x1f24 in Object.wait()
> [0x02c2f000..0x02c2fc94]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22e60720> (a java.lang.ref.ReferenceQueue$Lock)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
> - locked<0x22e60720> (a java.lang.ref.ReferenceQueue$Lock)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
>
> "Reference Handler" daemon prio=10 tid=0x02a5d400 nid=0x5fbc in Object.wait()
> [0x02bdf000..0x02bdfd14]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22e607b0> (a java.lang.ref.Reference$Lock)
> at java.lang.Object.wait(Object.java:485)
> at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
> - locked<0x22e607b0> (a java.lang.ref.Reference$Lock)
>
> "main" prio=6 tid=0x002a6800 nid=0x8e90 in Object.wait()
> [0x0090f000..0x0090fe54]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on<0x22ea2e08> (a java.lang.Object)
> at java.lang.Object.wait(Object.java:485)
> at
> org.apache.derby.impl.drda.NetworkServerControlImpl.blockingStart(Unknown
> Source)
> - locked<0x22ea2e08> (a java.lang.Object)
> at
> org.apache.derby.impl.drda.NetworkServerControlImpl.executeWork(Unknown
> Source)
> at org.apache.derby.drda.NetworkServerControl.main(Unknown Source)
>
> "VM Thread" prio=10 tid=0x02a5c400 nid=0x83c4 runnable
>
> "VM Periodic Task Thread" prio=10 tid=0x02a77000 nid=0x5a64 waiting on
> condition
>
> JNI global references: 688
>
>
>
>
> -----Original Message-----
> From: Kristian Waagan [mailto:[email protected]]
> Sent: Tuesday, November 16, 2010 10:22 AM
> To: [email protected]
> Subject: Re: Derby 10.5.3.0
>
> On 16.11.10 14:47, Bergquist, Brett wrote:
>> I am using Derby as a database as part of a Glassfish installation. I
>> am processing JMS messages with each one causing access to the Derby
>> database via Eclipselink. After about 80K to 100K messages processed,
>> I have a hung system.
>>
>> I run jstack on the Derby network server and there is no deadlock.
>> Also I run jstack on the Glassfish and there is no deadlock. In the
>> thread stack for Glassfish I see a thread with the following stack trace:
>>
> Hi Brett,
>
> Nothing concrete for this particular problem, but some ideas that might
> bring something more to the table:
> a) Can you replace derbyClient.jar in Glassfish with a newer version
> and reproduce?
> This should be as simple as shutting down Glassfish and replacing
> the file (you don't have to upgrade the server).
> b) If you have a large number of connections this won't do any good,
> but where is the DRDAConnThread thread in the network server when Derby
> has hung?
> c) Run the server with the debug build (there are some extra asserts
> in there for the session data piggyback mechanism), and for good
> measure, set derby.stream.error.logSeverityLevel=0.
> --- Note that DRDA protocol traces are likely to contain user data.
> Consider this before making them public.
> d) Spend some time learning how to enable DRDA tracing on the client
> (see [1]).
> e) Enable DRDA tracing on the server (see [1]).
>
> At first sight this looks like a protocol error, perhaps where both the
> server and the client are waiting for more data.
> Note that the DRDA traces aren't necessarily that easy to understand
> unless you're familiar with the protocol, so if you obtain them you may
> want to log a Jira issue [2] and attach them there.
>
>
> Hope this helps,
> --
> Kristian
>
> [1] http://wiki.apache.org/db-derby/ProtocolDebuggingTips
> [2] https://issues.apache.org/jira/browse/DERBY
>
>> "p: thread-pool-1; w: 3" daemon prio=6 tid=0x5de34800 nid=0xb94
>> runnable [0x60abe000..0x60abfd94]
>>
>> java.lang.Thread.State: RUNNABLE
>>
>> at java.net.SocketInputStream.socketRead0(Native Method)
>>
>> at java.net.SocketInputStream.read(SocketInputStream.java:129)
>>
>> at org.apache.derby.client.net.Reply.fill(Unknown Source)
>>
>> at
>> org.apache.derby.client.net.Reply.ensureALayerDataInBuffer(Unknown Source)
>>
>> at org.apache.derby.client.net.Reply.readDssHeader(Unknown Source)
>>
>> at
>> org.apache.derby.client.net.Reply.startSameIdChainParse(Unknown Source)
>>
>> at
>> org.apache.derby.client.net.NetConnectionReply.readExchangeServerAttributes(Unknown
>> Source)
>>
>> at
>> org.apache.derby.client.net.NetConnection.readServerAttributesAndKeyExchange(Unknown
>> Source)
>>
>> at
>> org.apache.derby.client.net.NetConnection.readAllConnectCommandsChained(Unknown
>> Source)
>>
>> at
>> org.apache.derby.client.net.NetConnection.readDeferredReset(Unknown
>> Source)
>>
>> at
>> org.apache.derby.client.net.NetAgent.readDeferredResetConnection(Unknown
>> Source)
>>
>> at org.apache.derby.client.net.NetAgent.beginReadChain(Unknown
>> Source)
>>
>> at org.apache.derby.client.am.Agent.flow(Unknown Source)
>>
>> at org.apache.derby.client.am.Statement.flowExecute(Unknown
>> Source)
>>
>> at org.apache.derby.client.am.Statement.executeQueryX(Unknown
>> Source)
>>
>> at org.apache.derby.client.am.Statement.executeQuery(Unknown
>> Source)
>>
>> - locked<0x1d90dba0> (a
>> org.apache.derby.client.net.NetConnection40)
>>
>> at
>> org.apache.derby.client.am.Connection.getTransactionIsolation(Unknown
>> Source)
>>
>> at
>> org.apache.derby.client.am.LogicalConnection.getTransactionIsolation(Unknown
>> Source)
>>
>> at
>> com.sun.gjc.spi.ManagedConnectionFactory.resetIsolation(ManagedConnectionFactory.java:463)
>>
>> at
>> com.sun.gjc.spi.ManagedConnection.resetConnectionProperties(ManagedConnection.java:354)
>>
>> at
>> com.sun.gjc.spi.ManagedConnection.getConnection(ManagedConnection.java:328)
>>
>> at
>> com.sun.enterprise.resource.ConnectorAllocator.fillInResourceObjects(ConnectorAllocator.java:155)
>>
>> at
>> com.sun.enterprise.resource.AbstractResourcePool.getResource(AbstractResourcePool.java:514)
>>
>> at
>> com.sun.enterprise.resource.PoolManagerImpl.getResourceFromPool(PoolManagerImpl.java:248)
>>
>> at
>> com.sun.enterprise.resource.PoolManagerImpl.getResource(PoolManagerImpl.java:176)
>>
>> at
>> com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:337)
>>
>> at
>> com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:189)
>>
>> at
>> com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:165)
>>
>> at
>> com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:158)
>>
>> This thread is making no progress at all. This is the one hanging my
>> system. The derby log shows:
>>
>> 2010-11-15 23:57:46.593 GMT : Apache Derby Network Server - 10.5.3.0 -
>> (802917) started and ready to accept connections on port 1527
>>
>> ----------------------------------------------------------------
>>
>> 2010-11-16 00:00:20.078 GMT:
>>
>> Booting Derby version The Apache Software Foundation - Apache Derby -
>> 10.5.3.0 - (802917): instance a816c00e-012c-51f9-12b2-0000376d74d3
>>
>> on database directory C:\Documents and Settings\Brett
>> Bergquist\.netbeans-derby\csemdb
>>
>> Database Class Loader started - derby.database.classpath='CSEM.csemderby'
>>
>> (END)
>>
>> The rest of Glassfish is up and running as well as other parts of my
>> application. This one thread, however, is causing my JMS processing
>> to be hung.
>>
>> This is the second time in two days of testing that this has
>> occurred. The previous lockup has exactly the same thread stack
>> traceback in a few other threads, all from different database queries,
>> all stuck at the same point. Restarting the derby network server,
>> caused the condition to clear up as far as the application server is
>> concerned, so I am pretty confident it is related to derby.
>>
>> Any help on where to look to find this problem will be greatly
>> appreciated.
>>
>> Brett
>>
>
>
