Acquiring JDBC Database Connections Take a Long Time when Shared Server Is Enabled (Doc ID 2072598.1)

Last updated on AUGUST 03, 2016

Applies to:

JDBC - Version 10.2.0 and later
Information in this document applies to any platform.

Symptoms

When trying to obtain a JDBC connection from the database, there can be a significant delay. Delays in the region of 10-30 seconds can be seen, but it is possible that it could take longer.

By taking thread dumps a second apart, these delays can be correlated to the following stack which is repeated multiple times for each dump:

net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:152)
java.net.SocketInputStream.read(SocketInputStream.java:122)
oracle.net.ns.Packet.receive(Packet.java:300)
oracle.net.ns.DataPacket.receive(DataPacket.java:106)
oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315)
oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
oracle.jdbc.driver.T4CTTIOtxse.doOTXSE(T4CTTIOtxse.java:163)
oracle.jdbc.driver.T4CXAResource.doStart(T4CXAResource.java:186)
oracle.jdbc.xa.client.OracleXAResource.start(OracleXAResource.java:228)
weblogic.jdbc.common.internal.ConnectionEnv.testInternal(ConnectionEnv.java:1143)

By tracing the JDBC connection with the following settings:

.level=SEVERE
oracle.net.ns.level=FINEST
oracle.jdbc.diagnostics.DemultiplexingLogHandler.pattern = sqlnet_%s.log
oracle.jdbc.diagnostics.DemultiplexingLogHandler.count = 3
oracle.jdbc.diagnostics.DemultiplexingLogHandler.limit = 50000000
oracle.jdbc.diagnostics.DemultiplexingLogHandler.formatter = java.util.logging.XMLFormatter
oracle.net.ns.handlers = oracle.jdbc.diagnostics.DemultiplexingLogHandler

it is found that there are multiple instances of 'SELECT 1 FROM DUAL', which take a long time to receive a response from the server.

e.g.

<record>
 <date>2015-06-12T05:16:48</date>
 <millis>1434082608607</millis>
 <sequence>29508376</sequence>
 <logger>oracle.net.ns</logger>
 <level>TRACE_20</level>
 <class>oracle.net.ns.DataPacket</class>
 <method>send</method>
 <thread>35</thread>
 <message>C7EFAF9 Debug: Packet size=189
00 BD 00 00 06 00 00 00     |........|
00 00 03 67 00 01 01 00     |...g....|
00 02 BE A1 01 06 01 0F     |........|
01 01 80 01 01 01 3C 01     |......&lt;.|
01 01 01 01 0D 01 01 07     |........|
05 D7 5B 11 E7 0A 57 53     |..[...WS|
2D 54 52 55 4E 4B 2D 53     |-TRUNK-S|
59 53 54 45 4D 00 00 00     |YSTEM...|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 6A 64 62 63 5F 74 74     |.jdbc_tt|
63 5F 69 6D 70 6C 6A 64     |c_impljd|
62 63 5F 31 35              |bc_15   |
</message>
 <param>D9F321</param>
</record>
<record>
 <date>2015-06-12T05:16:51</date>
 <millis>1434082611986</millis>
 <sequence>29508379</sequence>
 <logger>oracle.net.ns</logger>
 <level>TRACE_20</level>
 <class>oracle.net.ns.Packet</class>
 <method>receive</method>
 <thread>35</thread>
 <message>648EF7D7 Debug: type=6, length=198, flags=0
00 C6 00 00 06 00 00 00     |........|
00 00 08 00 01 A8 00 00     |........|
00 00 00 00 00 00 A1 BE     |........|
00 00 00 00 00 00 06 00     |........|
00 00 00 00 00 00 0F 00     |........|
00 00 00 00 00 00 05 D7     |........|
5B 11 E7 0A 57 53 2D 54     |[...WS-T|
52 55 4E 4B 2D 53 59 53     |RUNK-SYS|
54 45 4D 00 00 00 00 00     |TEM.....|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
00 00 00 00 00 00 77 00     |......w.|
00 00 00 00 00 00 17 02     |........|
01 05 05 33 38 38 35 38     |...38858|
09 01 07 02 01 40           |.....@  |
</message>
 <param>D9F321</param>
</record>
<record>
 <date>2015-06-12T05:16:51</date>
 <millis>1434082611987</millis>
 <sequence>29508384</sequence>
 <logger>oracle.net.ns</logger>
 <level>TRACE_20</level>
 <class>oracle.net.ns.DataPacket</class>
 <method>send</method>
 <thread>35</thread>
 <message>C7EFAF9 Debug: Packet size=87
00 57 00 00 06 00 00 00     |.W......|
00 00 03 5E 00 02 80 21     |...^...!|
00 01 01 12 01 01 0D 00     |........|
00 04 FF FF FF FF 01 0A     |........|
04 7F FF FF FF 00 00 00     |........|
00 00 00 00 00 00 00 00     |........|
01 00 00 00 00 00 53 45     |......SE|
4C 45 43 54 20 31 20 46     |LECT.1.F|
52 4F 4D 20 44 55 41 4C     |ROM.DUAL|
01 01 00 00 00 00 00 00     |........|
01 01 00 00 00 00 00        |....... |
</message>
 <param>D9F321</param>
</record>
<record>
 <date>2015-06-12T05:16:51</date>
 <millis>1434082611988</millis>
 <sequence>29508391</sequence>
 <logger>oracle.net.ns</logger>
 <level>TRACE_20</level>
 <class>oracle.net.ns.Packet</class>
 <method>receive</method>
 <thread>35</thread>
 <message>648EF7D7 Debug: type=6, length=197, flags=0
00 C5 00 00 06 00 00 00     |........|
00 00 10 17 17 E7 5D DB     |......].|
B9 AB 3C 0D 22 7D 53 BD     |..&lt;."}S.|
A7 38 EA 01 78 73 05 0D     |.8..xs..|
0B 09 1E 01 02 01 01 51     |.......Q|
02 00 00 81 7F 01 02 00     |........|
00 00 00 00 00 00 01 01     |........|
01 01 01 31 00 00 00 00     |...1....|
01 07 07 78 73 06 0C 06     |...xs...|
11 34 00 02 1F E8 01 02     |.4......|
01 02 00 06 22 01 01 00     |...."...|
01 0A 00 00 00 07 02 C1     |........|
02 08 01 06 04 01 AE E9     |........|
80 00 01 0B 01 05 00 00     |........|
00 00 00 17 02 01 05 05     |........|
33 38 38 35 38 04 01 03     |38858...|
02 01 41 01 01 02 05 7B     |..A....{|
00 00 01 0B 00 03 00 00     |........|
01 08 00 00 03 01 93 70     |.......p|
01 05 00 03 02 0B 8D 01     |........|
02 00 00 00 00 01 01 00     |........|
00 00 00 19 4F 52 41 2D     |....ORA-|
30 31 34 30 33 3A 20 6E     |01403:.n|
6F 20 64 61 74 61 20 66     |o.data.f|
6F 75 6E 64 0A              |ound.   |
</message>
</record>
<record>

The above trace shows a 3 second delay from when the operation began, to when the server responded.

However, when the database side of the connection is traced, there does not appear to be any delay in responding.

NOTE: The 'SELECT 1 FROM DUAL' query is just an example. The delay may occur for any query. Do NOT rule out this problem if this query is not present in the trace files.

 

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms