db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bergquist, Brett" <Br...@canoga.com>
Subject RE: Derby 10.5.3.0
Date Tue, 16 Nov 2010 16:10:26 GMT
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:kristian.waagan@oracle.com]
Sent: Tuesday, November 16, 2010 10:57 AM
To: derby-dev@db.apache.org
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:kristian.waagan@oracle.com]
> Sent: Tuesday, November 16, 2010 10:22 AM
> To: derby-dev@db.apache.org
> 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
>>
>
>




Mime
View raw message