ODP.NET

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Interested in getting your voice heard by members of the Developer Marketing team at Oracle? Check out this post for AppDev or this post for AI focus group information.

ODP.Net Managed Driver Connection Timeout

Dmitry SukhovJun 9 2016 — edited Jun 8 2017

Hi, I have noticed, that for applications which use ODP.Net Managed Driver (version 4.121.2.0 from Nuget packge 12.1.24160419) periodically and quite often experience an Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Request timed out exception.

Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Request timed out

bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)

bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)

bei OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword)

bei Oracle.ManagedDataAccess.Client.OracleConnection.Open()

bei ConsoleApplication4.Program.TestConnections[T](Int32 count, String connectionString)

Whereas all other applications which use unmanaged ODP.net driver (version 4.112.4.0) with the same connection string don't receive such exception.

I have tried to increase connection timeout up to 30sec. It helps partly, but not complete.

Could somebody tell me, what can be reason and how to fix this issue. What is difference between Managed and unmanaged drivers in scope of connection timeout?

Here is dump:

2016-06-07 19:35:01.726098 TID:1   (CFG) (SQLNET)   SQLNET.AUTHENTICATION_SERVICES : (NTS)
2016-06-07 19:35:01.741723 TID:1   (CFG) (SQLNET)   NAMES.DIRECTORY_PATH : (TNSNAMES, EZCONNECT)
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      Machine Name : HAJFLI03
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      User Name : rzservice
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      OS Version : Microsoft Windows NT 6.1.7601 Service Pack 1
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      64-bit OS : True
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      64-bit Process : False
2016-06-07 19:35:01.741723 TID:1   (CFG) (ENV)      .NET Runtime Version : 4.0.30319.34209
2016-06-07 19:35:01.741723 TID:1   (CFG) (VER)      Oracle Data Provider for .NET, Managed Driver Version : 4.121.2.0
2016-06-07 19:35:01.741723 TID:1   (CFG) (VER)      Oracle Data Provider for .NET, Managed Driver Informational Version : 4.121.2.20150926 ODAC RELEASE 4
2016-06-07 19:35:01.741723 TID:1   (CFG) (.NET)     PerformanceCounters : 4095
2016-06-07 19:35:01.741723 TID:1   (CFG) (.NET)     TraceFileLocation : e:\FiplanHAJ\Crystal\Messenger.Net\trace\
2016-06-07 19:35:01.741723 TID:1   (CFG) (.NET)     TraceLevel : 7
2016-06-07 19:35:01.741723 TID:1   (CFG) (.NET)     NAMES.DIRECTORY_PATH : (TNSNAMES, EZCONNECT)
2016-06-07 19:35:01.741723 TID:1   (CFG) (.NET)     SQLNET.AUTHENTICATION_SERVICES : (NTS)
2016-06-07 19:35:01.757348 TID:1   (CFG) (TNSNAMES) FLIRTHAJ : (DESCRIPTION =(ADDRESS_LIST =(ADDRESS = (PROTOCOL = TCP)(HOST = hajfli02)(PORT = 1521)))(CONNECT_DATA =(SERVICE_NAME = FLIRTHAJ)))
2016-06-07 19:35:01.757348 TID:1   (CFG) (TNSNAMES) FLIRTHAJ : (DESCRIPTION =(ADDRESS_LIST =(ADDRESS = (PROTOCOL = TCP)(HOST = hajfli02)(PORT = 1521)))(CONNECT_DATA =(SERVICE_NAME = FLIRTHAJ)))
2016-06-07 19:35:01.772973 TID:1   (CFG) (SQLNET)   FilePath : e:\oracle\product\11.2.0\client_1\network\admin\sqlnet.ora
2016-06-07 19:35:01.772973 TID:1   (CFG) (TNSNAMES) FilePath : e:\oracle\product\11.2.0\client_1\network\admin\tnsnames.ora
2016-06-07 19:35:01.772973 TID:1   (PUB) (ENT) OracleConnection.ctor()
2016-06-07 19:35:01.772973 TID:1   (PUB) (EXT) OracleConnection.ctor()
2016-06-07 19:35:01.788598 TID:1   (PUB) (ENT) OracleConnection.Close() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=F) (txnid=n/a) 
2016-06-07 19:35:01.788598 TID:1   (PUB) (EXT) OracleConnection.Close() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=F) (txnid=n/a) 
2016-06-07 19:35:01.788598 TID:1   (PUB) (ENT) OracleConnection.Close() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=F) (txnid=n/a) 
2016-06-07 19:35:01.788598 TID:1   (PUB) (EXT) OracleConnection.Close() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=F) (txnid=n/a) 
2016-06-07 19:35:01.929223 TID:1   (PRI) (ENT) (CP) ConnectionString.GetCS()
2016-06-07 19:35:01.944848 TID:1   (PRI) (ENT) (CP) ConnectionString.ctor()
2016-06-07 19:35:01.944848 TID:1   (PRI) (ENT) (CP) ConnectionString.Parse()
2016-06-07 19:35:01.944848 TID:1   (PRI) (ENT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.SetProperty()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.Parse()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.ctor()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) ConnectionString.GetCS()
2016-06-07 19:35:01.960473 TID:1   (PUB) (ENT) OracleConnection.Open() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=T) (txnid=n/a) 
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) OracleConnectionDispenser`3..cctor()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) OracleConnectionDispenser`3..cctor()
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) OracleConnectionDispenser`3.Get()
2016-06-07 19:35:01.960473 TID:1   (PRI) (ENT) (CP) PoolManager`3.ctor()
2016-06-07 19:35:01.960473 TID:1   (PRI) (EXT) (CP) PoolManager`3.ctor()
2016-06-07 19:35:01.976098 TID:1   (PRI) (ENT) (CP) PoolManager`3.Initialize() (constr=USER ID=Crystal_Messenger_AL_HAJ;CONNECTION TIMEOUT=30;DATA SOURCE=flirthaj)
2016-06-07 19:35:01.976098 TID:1   (PRI) (ENT) (CP) ConnectionString.Secure()
2016-06-07 19:35:01.976098 TID:1   (PRI) (EXT) (CP) ConnectionString.Secure()
2016-06-07 19:35:01.976098 TID:1   (PRI) (EXT) (CP) PoolManager`3.Initialize() (pmid=32972388) (constr=USER ID=Crystal_Messenger_AL_HAJ;CONNECTION TIMEOUT=30;DATA SOURCE=flirthaj)
2016-06-07 19:35:01.976098 TID:1   (PRI) (BUF) (OBP.CTOR) (poolid:28316044) (OracleConnectionDispenser`3.GetPM)
2016-06-07 19:35:01.991723 TID:1   (PRI) (ENT) (CP) OraclePoolManager.Get()
2016-06-07 19:35:01.991723 TID:1   (PRI) (ENT) (CP) PoolManager`3.Get() (txnid=n/a) (bForceMatch=F)
2016-06-07 19:35:02.007348 TID:1   (PRI) (ENT) (CP) PoolManager`3.CreateNewPR() (txnid=n/a) 
2016-06-07 19:35:02.554223 TID:1   (PRI) (ENT) TimeStamp.GetLocalTZOffset()
2016-06-07 19:35:02.554223 TID:1   (PRI) (EXT) TimeStamp.GetLocalTZOffset()
2016-06-07 19:35:02.554223 TID:1   (PRI) (ENT) (CP) ConnectionString.GetStringFromSecureString()
2016-06-07 19:35:02.554223 TID:1   (PRI) (EXT) (CP) ConnectionString.GetStringFromSecureString()
2016-06-07 19:35:02.569848 TID:4   (PRI) (ENT) (CP) PoolManager`3.CreateNewPRThreadFunc()
2016-06-07 19:35:02.585473 TID:4   (PRI) (SVC) (ENT) OracleConnectionImpl.Connect() (oper=open) (aff=n/a) (inst=) (affmatch=n/a) (sessid=-1:-1) (F;F;F;;N) (pmid=32972388) 
2016-06-07 19:35:02.585473 TID:4   (PRI) (ENT) (CP) ConnectionString.GetStringFromSecureString()
2016-06-07 19:35:02.585473 TID:4   (PRI) (EXT) (CP) ConnectionString.GetStringFromSecureString()
2016-06-07 19:35:02.585473 TID:4   (PRI) (BUF) (COBP.CTOR) (poolid:1) (parentpoolid:28316044) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.632348 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:1)
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 00 F2 00 00 01 00 00 00   |........|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 01 3A 01 2C 0C 01 FF FF   |.:.,....|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) FF FF 4F 98 00 00 00 01   |..O.....|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 00 B8 00 3A 00 00 00 00   |...:....|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 01 01 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 00 00 28 44 45 53 43 52   |..(DESCR|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 49 50 54 49 4F 4E 3D 28   |IPTION=(|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 41 44 44 52 45 53 53 5F   |ADDRESS_|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 4C 49 53 54 3D 28 41 44   |LIST=(AD|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 44 52 45 53 53 3D 28 50   |DRESS=(P|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 52 4F 54 4F 43 4F 4C 3D   |ROTOCOL=|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 54 43 50 29 28 48 4F 53   |TCP)(HOS|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 54 3D 68 61 6A 66 6C 69   |T=hajfli|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 30 32 29 28 50 4F 52 54   |02)(PORT|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 3D 31 35 32 31 29 29 29   |=1521)))|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 28 43 4F 4E 4E 45 43 54   |(CONNECT|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 5F 44 41 54 41 3D 28 53   |_DATA=(S|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 45 52 56 49 43 45 5F 4E   |ERVICE_N|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 41 4D 45 3D 46 4C 49 52   |AME=FLIR|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 54 48 41 4A 29 28 43 49   |THAJ)(CI|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 44 3D 28 50 52 4F 47 52   |D=(PROGR|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 41 4D 3D 4D 65 73 73 65   |AM=Messe|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 6E 67 65 72 43 6F 6E 73   |ngerCons|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 6F 6C 65 2E 65 78 65 29   |ole.exe)|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 28 48 4F 53 54 3D 48 41   |(HOST=HA|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 4A 46 4C 49 30 33 29 28   |JFLI03)(|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 55 53 45 52 3D 72 7A 73   |USER=rzs|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 65 72 76 69 63 65 29 29   |ervice))|
2016-06-07 19:35:02.663598 TID:4   (NET) (SND) 29 29                     |))      |
2016-06-07 19:35:02.679223 TID:4   (NET) (REC) 00 08 00 00 0B 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 00 F2 00 00 01 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 01 3A 01 2C 0C 01 FF FF   |.:.,....|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) FF FF 4F 98 00 00 00 01   |..O.....|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 00 B8 00 3A 00 00 00 00   |...:....|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 01 01 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 00 00 28 44 45 53 43 52   |..(DESCR|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 49 50 54 49 4F 4E 3D 28   |IPTION=(|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 41 44 44 52 45 53 53 5F   |ADDRESS_|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 4C 49 53 54 3D 28 41 44   |LIST=(AD|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 44 52 45 53 53 3D 28 50   |DRESS=(P|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 52 4F 54 4F 43 4F 4C 3D   |ROTOCOL=|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 54 43 50 29 28 48 4F 53   |TCP)(HOS|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 54 3D 68 61 6A 66 6C 69   |T=hajfli|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 30 32 29 28 50 4F 52 54   |02)(PORT|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 3D 31 35 32 31 29 29 29   |=1521)))|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 28 43 4F 4E 4E 45 43 54   |(CONNECT|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 5F 44 41 54 41 3D 28 53   |_DATA=(S|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 45 52 56 49 43 45 5F 4E   |ERVICE_N|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 41 4D 45 3D 46 4C 49 52   |AME=FLIR|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 54 48 41 4A 29 28 43 49   |THAJ)(CI|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 44 3D 28 50 52 4F 47 52   |D=(PROGR|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 41 4D 3D 4D 65 73 73 65   |AM=Messe|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 6E 67 65 72 43 6F 6E 73   |ngerCons|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 6F 6C 65 2E 65 78 65 29   |ole.exe)|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 28 48 4F 53 54 3D 48 41   |(HOST=HA|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 4A 46 4C 49 30 33 29 28   |JFLI03)(|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 55 53 45 52 3D 72 7A 73   |USER=rzs|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 65 72 76 69 63 65 29 29   |ervice))|
2016-06-07 19:35:02.679223 TID:4   (NET) (SND) 29 29                     |))      |
2016-06-07 19:35:02.679223 TID:4   (NET) (REC) 00 20 00 00 02 00 00 00   |. ......|
2016-06-07 19:35:02.679223 TID:4   (NET) (REC) 01 3A 08 01 20 00 FF FF   |.:.. ...|
2016-06-07 19:35:02.679223 TID:4   (NET) (REC) 01 00 00 00 00 20 21 01   |..... !.|
2016-06-07 19:35:02.679223 TID:4   (NET) (REC) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.679223 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:2)
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 AD 00 00 06 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 00 DE AD BE EF 00 A3   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 0B 20 02 00 00 04 00 00   |. ......|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 04 00 03 00 00 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 04 00 05 0B 20 02 00 00   |.... ...|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 08 00 01 00 00 10 1C 66   |.......f|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) EC 28 EA 00 12 00 01 DE   |.(......|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) AD BE EF 00 03 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 04 00 04 00 01 00 02 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 03 00 01 00 05 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 00 04 00 05 0B 20 02   |...... .|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 00 02 00 03 E0 E1 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 02 00 06 FC FF 00 01 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 02 01 00 03 00 00 4E 54   |......NT|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 53 00 02 00 03 00 00 00   |S.......|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 00 04 00 05 0B 20 02   |...... .|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 00 0C 00 01 00 01 08   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 0A 06 03 02 0B 0C 0F 10   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 11 00 01 00 02 01 00 03   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 02 00 00 00 00 00 04   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 05 0B 20 02 00 00 03   |... ....|
2016-06-07 19:35:02.694848 TID:4   (NET) (SND) 00 01 00 03 01            |.....   |
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 A3 00 00 06 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 DE AD BE EF 00 99   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 00 00 00 04 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 04 00 03 00 00 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 04 00 05 0B 20 04 00 00   |.... ...|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 02 00 06 00 1F 00 0E 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 01 DE AD BE EF 00 03 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 02 00 04 00 01 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 01 00 07 00 00 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 04 00 05 0B 20 04 00 00   |.... ...|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 02 00 06 FA FF 00 01 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 02 01 00 03 00 00 4E 54   |......NT|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 53 00 04 00 05 02 00 00   |S.......|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 04 00 04 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 09 00 04 00 04 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 02 00 02 00 02 00 00 00   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 04 00 05 0B 20 04   |...... .|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 00 01 00 02 00 00 03   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 02 00 00 00 00 00 04   |........|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 05 0B 20 04 00 00 01   |... ....|
2016-06-07 19:35:02.694848 TID:4   (NET) (REC) 00 02 00                  |...     |
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 98 00 00 06 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 DE AD BE EF 00 8E   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 0B 20 02 00 00 01 00 00   |. ......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 01 00 07 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 05 02 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 04 00 00 00 09 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 04 00 00 00 02 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 14 00 01 02 00 00 00 04   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 02 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 01 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 01 35 00 00 00 00   |...5....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 35 00 01 4E 54 4C 4D 53   |5..NTLMS|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 53 50 00 01 00 00 00 07   |SP......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) B2 18 A2 05 00 05 00 30   |.......0|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 08 00 08 00 28   |.......(|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 06 01 B1 1D 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 0F 48 41 4A 46 4C   |...HAJFL|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 49 30 33 49 54 48 41 4A   |I03ITHAJ|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 01 CF 00 00 06 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 DE AD BE EF 01 C5   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 01 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 01 00 02 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 04 00 01 A4 01 00 00 01   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) A4 00 01 4E 54 4C 4D 53   |...NTLMS|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 53 50 00 03 00 00 00 18   |SP......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 18 00 84 00 00 00 08   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 01 08 01 9C 00 00 00 0A   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 0A 00 58 00 00 00 12   |...X....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 12 00 62 00 00 00 10   |...b....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 10 00 74 00 00 00 00   |...t....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 A4 01 00 00 05   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 82 98 A2 06 01 B1 1D 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 0F 28 97 46 76 88   |...(.Fv.|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 25 FE BA 8B 94 5A 1B EE   |%....Z..|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) C6 D8 30 49 00 54 00 48   |..0I.T.H|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 41 00 4A 00 72 00 7A   |.A.J.r.z|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 73 00 65 00 72 00 76   |.s.e.r.v|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 69 00 63 00 65 00 48   |.i.c.e.H|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 41 00 4A 00 46 00 4C   |.A.J.F.L|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 49 00 30 00 33 00 00   |.I.0.3..|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 C0   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 1B 96 CE 19 29 0F F8 A0   |....)...|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) EC 8A AE FD 91 54 F9 01   |.....T..|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 01 00 00 00 00 00 00 02   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 0A 44 EC E2 C0 D1 01 E9   |.D......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) FC FB 74 E2 86 78 F0 00   |..t..x..|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 02 00 0A 00 49   |.......I|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 54 00 48 00 41 00 4A   |.T.H.A.J|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 01 00 10 00 48 00 41   |.....H.A|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 4A 00 46 00 4C 00 49   |.J.F.L.I|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 30 00 32 00 04 00 10   |.0.2....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 69 00 74 00 68 00 61   |.i.t.h.a|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 6A 00 2E 00 64 00 65   |.j...d.e|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 03 00 22 00 48 00 41   |...".H.A|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 4A 00 46 00 4C 00 49   |.J.F.L.I|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 30 00 32 00 2E 00 69   |.0.2...i|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 74 00 68 00 61 00 6A   |.t.h.a.j|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 2E 00 64 00 65 00 05   |...d.e..|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 10 00 69 00 74 00 68   |...i.t.h|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 61 00 6A 00 2E 00 64   |.a.j...d|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 65 00 07 00 08 00 02   |.e......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 0A 44 EC E2 C0 D1 01 06   |.D......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 04 00 02 00 00 00 08   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 30 00 30 00 00 00 00   |.0.0....|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 30 00 00 14 01 16 E9 09   |0.......|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) D8 F2 F9 00 0F 43 B8 23   |.....C.#|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 7C E8 F0 A3 42 23 C8 5F   ||...B#._|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) B1 8E 11 E1 61 BA 7B 4D   |....a.{M|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) A6 A2 CC 0A 00 10 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 09   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00 00   |........|
2016-06-07 19:35:02.726098 TID:4   (NET) (SND) 00 00 00 00 00 00 00      |....... |
2016-06-07 19:35:02.726098 TID:4   (NET)      NS Handshake completed successfully
2016-06-07 19:35:02.726098 TID:4   (NET)      Negotiated SDU size = 8192
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:3)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:3) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:3) (count:1) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:4)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:4) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:4) (count:2) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:5)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:5) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:5) (count:3) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:6)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:6) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:6) (count:4) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:7)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:7) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:7) (count:5) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:8)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:8) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:8) (count:6) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:9)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:9) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:9) (count:7) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (ALLOCATION) (bufid:10)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (OBP.GET) (poolid:28316044) (key:8192) (bufid:10) (count:0) (ConOraBufPool.Init)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.PUT) (poolid:1) (key:8192) (bufid:10) (count:8) (OracleConnectionImpl.Connect)
2016-06-07 19:35:02.741723 TID:4   (PRI) (BUF) (COBP.GET) (poolid:1) (key:8192) (bufid:10) (count:7) (OraBufWriter.Initialize)
2016-06-07 19:35:02.741723 TID:4   (PRI) (SVC) (ENT) OracleConnectionImpl.DoProtocolNegotiation()
2016-06-07 19:35:02.757348 TID:4   (PRI) (TTC) (ENT) TTCProtocolNegotiation.WriteMessage()
2016-06-07 19:35:02.757348 TID:4   (PRI) (TTC) (ENT) TTCMessage.WriteTTCCode()
2016-06-07 19:35:02.757348 TID:4   (PRI) (TTC) (EXT) TTCMessage.WriteTTCCode()
2016-06-07 19:35:02.757348 TID:4   (PRI) (TTC) (EXT) TTCProtocolNegotiation.WriteMessage()
2016-06-07 19:35:02.757348 TID:4   (NET) (SND) 00 1D 00 00 06 00 00 00   |........|
2016-06-07 19:35:02.757348 TID:4   (NET) (SND) 00 00                     |..      |
2016-06-07 19:35:02.757348 TID:4   (NET) (SND) 01 06 00 4F 44 50 2E 4E   |...ODP.N|
2016-06-07 19:35:02.757348 TID:4   (NET) (SND) 45 54 5F 4D 61 6E 61 67   |ET_Manag|
2016-06-07 19:35:02.757348 TID:4   (NET) (SND) 65 64 00                  |ed.     |
2016-06-07 19:35:02.757348 TID:4   (PRI) (TTC) (ENT) TTCProtocolNegotiation.ReadResponse()
2016-06-07 19:35:02.757348 TID:4   (PRI) (BUF) (COBP.GET) (poolid:1) (key:8192) (bufid:9) (count:6) (OraBufReader.GetDataFromNetwork)
2016-06-07 19:35:32.569848 TID:1   (PRI) (CP) PoolManager`3.CreateNewPR() (DUMP)
(CP) =================================
(CP) USER ID=Crystal_Messenger_AL_HAJ;CONNECTION TIMEOUT=30;PASSWORD=;DATA SOURCE=flirthaj
(CP) pmid=
32972388
(CP) =================================


2016-06-07 19:35:32.569848 TID:1   (PRI) (ENT) OracleException.ctor()
2016-06-07 19:35:32.569848 TID:1   (PRI) (ENT) OracleError.ctor()
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) OracleError.ctor()
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) OracleException.ctor()
2016-06-07 19:35:32.585473 TID:1   (PRI) (ENT) PoolManager`3.CreateNewPR()
2016-06-07 19:35:32.585473 TID:1   (PRI) (ERR) (CP) PoolManager`3.CreateNewPR() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.CreateNewPR(Int32 reqCount, Boolean bForPoolPopulation, ConnectionString csWithDiffOrNewPwd, String instanceName)
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) PoolManager`3.CreateNewPR()
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) (CP) PoolManager`3.CreateNewPR() (aff=n/a) (inst=) (affmatch=n/a) (sessid=-1:-1) (F;F;F;;N) (pmid=32972388) 
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) (CP) PoolManager`3.Get() (txnid=n/a) PM.Get(aff=;force=F) returning (null)
2016-06-07 19:35:32.585473 TID:1   (PRI) (ENT) OraclePoolManager.Get()
2016-06-07 19:35:32.585473 TID:1   (PRI) (ERR) (CP) OraclePoolManager.Get() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) OraclePoolManager.Get()
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) (CP) OraclePoolManager.Get() (txnid=n/a) 
2016-06-07 19:35:32.585473 TID:1   (PRI) (ENT) OracleConnectionDispenser`3.Get()
2016-06-07 19:35:32.585473 TID:1   (PRI) (ERR) (CP) OracleConnectionDispenser`3.Get() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword)
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) OracleConnectionDispenser`3.Get()
2016-06-07 19:35:32.585473 TID:1   (PRI) (EXT) (CP) OracleConnectionDispenser`3.Get() (txnid=n/a) 
2016-06-07 19:35:32.585473 TID:1   (PRI) (ENT) OracleConnection.Open()
2016-06-07 19:35:32.585473 TID:1   (PUB) (ERR) OracleConnection.Open() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword)
   bei Oracle.ManagedDataAccess.Client.OracleConnection.Open()
2016-06-07 19:35:32.601098 TID:1   (PRI) (EXT) OracleConnection.Open()
2016-06-07 19:35:32.601098 TID:1   (PUB) (EXT) OracleConnection.Open() (conid=26148945) (state=Closed) (sessid=0) (implid=0) (pooling=T) (txnid=n/a) 
2016-06-07 19:35:32.601098 TID:1   (PUB) (ENT) OracleConnection.Dispose()
2016-06-07 19:35:32.601098 TID:1   (PUB) (EXT) OracleConnection.Dispose()
2016-06-07 19:35:32.601098 TID:1   (PUB) (ENT) OracleConnection.ctor()
2016-06-07 19:35:32.601098 TID:1   (PUB) (EXT) OracleConnection.ctor()
2016-06-07 19:35:32.647973 TID:2   (PUB) (ENT) OracleConnection.Finalize()
2016-06-07 19:35:32.647973 TID:2   (PUB) (ENT) OracleConnection.Dispose()
2016-06-07 19:35:32.647973 TID:2   (PUB) (EXT) OracleConnection.Dispose()
2016-06-07 19:35:32.647973 TID:2   (PUB) (EXT) OracleConnection.Finalize()
2016-06-07 19:35:32.647973 TID:2   (PUB) (ENT) OracleConnection.Dispose()
2016-06-07 19:35:32.647973 TID:2   (PUB) (EXT) OracleConnection.Dispose()

Alex Keh-Oracle

If you increase the Max Pool Size, does the problem continue? The more fundamental question is whether the timeout is occurring because there are no more connections in the pool to dispense or whether the DB is slow in returning a connection upon an Open() call. Are there a consistent set of circumstances under which the problem always occurs (i.e. upon the first connection attempt)?

I didn't find a known bug matching your circumstances.

Dmitry Sukhov

Alex, I'm not sure that the problem is related to the Max Pool Size, because in the same time we don't have more than 20 connection, although by default Max Pool Size is 100.

But in any case I will try to increase it, thank you for advice. Next week I will report about results.

Another thing, what I have noticed, when application after timeout exception tries to connect once again, it connects always successful. But connection timeout occurs not for each start, several times per day.

Alex Keh-Oracle

Then, it doesn't sound like Max Pool Size is the problem. I have another possible idea. Is the problem only happening upon application startup when it connects to the DB for the first time? If so, the problem could be occurring due to resolving TNS or LDAP connection info.

I see a 30 second gap in the ODP.NET trace, which means we may need a DB network trace (level 16) to see why it's taking so long.

2016-06-07 19:35:02.757348 TID:4 (PRI) (BUF) (COBP.GET) (poolid:1) (key:8192) (bufid:9) (count:6) (OraBufReader.GetDataFromNetwork)
2016-06-07 19:35:32.569848 TID:1 (PRI) (CP) PoolManager`3.CreateNewPR() (DUMP)

Dmitry Sukhov

Alex, yes, this problem happens only when it connects to the DB for the first time.

Changing Max/Min pool size didn't solve this issue.

I have changed TNS HOST settings from domain name to server IP address to check your idea. If it doesn't help, i will try to set trace level 16 on the oracle server side, to provide more info.

Dmitry Sukhov

Alex, we have created DB network trace, but I cannot attach it to this thread. I don't have such option.

I insert small parts of this traces here (please let me know if you need more info):

Application trace:

2016-06-16 11:20:04.144020 TID:4   (PRI) (TTC) (EXT) TTCProtocolNegotiation.WriteMessage()
2016-06-16 11:20:04.144020 TID:4   (NET) (SND) 00 1D 00 00 06 00 00 00   |........|
2016-06-16 11:20:04.144020 TID:4   (NET) (SND) 00 00                     |..      |
2016-06-16 11:20:04.144020 TID:4   (NET) (SND) 01 06 00 4F 44 50 2E 4E   |...ODP.N|
2016-06-16 11:20:04.144020 TID:4   (NET) (SND) 45 54 5F 4D 61 6E 61 67   |ET_Manag|
2016-06-16 11:20:04.144020 TID:4   (NET) (SND) 65 64 00                  |ed.     |
2016-06-16 11:20:04.144020 TID:4   (PRI) (TTC) (ENT) TTCProtocolNegotiation.ReadResponse()
2016-06-16 11:20:04.159645 TID:4   (PRI) (BUF) (COBP.GET) (poolid:1) (key:8192) (bufid:9) (count:6) (OraBufReader.GetDataFromNetwork)
2016-06-16 11:20:18.862770 TID:1   (PRI) (CP) PoolManager`3.CreateNewPR() (DUMP)
(CP) =================================
(CP) User Id=crystal_messenger_AP_HAJ;Password=;Data Source=flirthaj;
(CP) pmid=
26753075
(CP) =================================


2016-06-16 11:20:18.862770 TID:1   (PRI) (ENT) OracleException.ctor()
2016-06-16 11:20:18.862770 TID:1   (PRI) (ENT) OracleError.ctor()
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) OracleError.ctor()
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) OracleException.ctor()
2016-06-16 11:20:18.878395 TID:1   (PRI) (ENT) PoolManager`3.CreateNewPR()
2016-06-16 11:20:18.878395 TID:1   (PRI) (ERR) (CP) PoolManager`3.CreateNewPR() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.CreateNewPR(Int32 reqCount, Boolean bForPoolPopulation, ConnectionString csWithDiffOrNewPwd, String instanceName)
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) PoolManager`3.CreateNewPR()
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) (CP) PoolManager`3.CreateNewPR() (aff=n/a) (inst=) (affmatch=n/a) (sessid=-1:-1) (F;F;F;;N) (pmid=26753075)
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) (CP) PoolManager`3.Get() (txnid=n/a) PM.Get(aff=;force=F) returning (null)
2016-06-16 11:20:18.878395 TID:1   (PRI) (ENT) OraclePoolManager.Get()
2016-06-16 11:20:18.878395 TID:1   (PRI) (ERR) (CP) OraclePoolManager.Get() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) OraclePoolManager.Get()
2016-06-16 11:20:18.878395 TID:1   (PRI) (EXT) (CP) OraclePoolManager.Get() (txnid=n/a)
2016-06-16 11:20:18.894020 TID:1   (PRI) (ENT) OracleConnectionDispenser`3.Get()
2016-06-16 11:20:18.894020 TID:1   (PRI) (ERR) (CP) OracleConnectionDispenser`3.Get() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword)
2016-06-16 11:20:18.894020 TID:1   (PRI) (EXT) OracleConnectionDispenser`3.Get()
2016-06-16 11:20:18.894020 TID:1   (PRI) (EXT) (CP) OracleConnectionDispenser`3.Get() (txnid=n/a)
2016-06-16 11:20:18.894020 TID:1   (PRI) (ENT) OracleConnection.Open()
2016-06-16 11:20:18.894020 TID:1   (PUB) (ERR) OracleConnection.Open() (txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Timeout bei Verbindungsanforderung
   bei OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, String affinityInstanceName, Boolean bForceMatch)
   bei OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword)
   bei Oracle.ManagedDataAccess.Client.OracleConnection.Open()

Oracle DB trace:

2016-06-16 11:20:04.253602 : nsvntx_dei:exit

2016-06-16 11:20:04.253630 : nsopenfree_nsntx:nlhthdel from mplx_ht_nsgbu, ctx=6371900 nsntx=5d01070

2016-06-16 11:20:04.253658 : nsiocancel:entry

2016-06-16 11:20:04.253682 : nsiofrrg:entry

2016-06-16 11:20:04.253705 : nsiofrrg:exit

2016-06-16 11:20:04.253729 : nsiocancel:exit

2016-06-16 11:20:04.253754 : nsmfr:entry

2016-06-16 11:20:04.253781 : nsmfr:2944 bytes at 0x5d01070

2016-06-16 11:20:04.253807 : nsmfr:normal exit

2016-06-16 11:20:04.253831 : nsmfr:entry

2016-06-16 11:20:04.253862 : nsmfr:1544 bytes at 0x6371900

2016-06-16 11:20:04.253890 : nsmfr:normal exit

2016-06-16 11:20:04.253917 : nsclose:normal exit

2016-06-16 11:20:04.253945 : nsbeqaddr:connect handshake is complete

2016-06-16 11:20:04.253971 : nsbeqaddr:normal exit

2016-06-16 11:20:04.253997 : nsbequeath:normal exit

2016-06-16 11:20:04.270264 : nsglhe:exit

2016-06-16 11:20:04.270322 : nsevwait:entry

2016-06-16 11:20:04.270354 : nsevwait:4 registered connection(s)

2016-06-16 11:20:04.270383 : nsevwait:0 pre-posted event(s)

2016-06-16 11:20:04.270410 : nsevwait:waiting for transport event (0 thru 4)...

2016-06-16 11:20:19.083984 : nsevwait:1 newly-posted event(s)

2016-06-16 11:20:19.084101 : nsevfnt:cxd: 0x5c91aa0 stage 0: NT events set:

CONNECTION REQUEST

2016-06-16 11:20:19.084149 : nsevfnt:cxd: 0x5c91aa0 stage 0: NS events set:

INCOMING CALL

2016-06-16 11:20:19.084191 : nsevrec:event is 0x1, on 0

2016-06-16 11:20:19.084220 : nsevwait:1 posted event(s)

2016-06-16 11:20:19.084246 : nsevwait:exit (0)

2016-06-16 11:20:19.084293 : nsglhe:entry

2016-06-16 11:20:19.084324 : nsglhe:Event on cxd 0x5c91aa0.

2016-06-16 11:20:19.084360 : nsglhc:Allocating cxd 0x5d2e780

2016-06-16 11:20:19.084442 : nsanswer:entry

2016-06-16 11:20:19.084479 : nsopen:entry

2016-06-16 11:20:19.084507 : nsmal:entry

2016-06-16 11:20:19.084536 : nsmal:1544 bytes at 0x6371900

2016-06-16 11:20:19.084647 : nsmal:normal exit

2016-06-16 11:20:19.084684 : nsopenmplx:entry

2016-06-16 11:20:19.084913 : nsmal:entry

2016-06-16 11:20:19.084961 : nsmal:2944 bytes at 0x5d01070

2016-06-16 11:20:19.084986 : nsmal:normal exit

Here in both traces you can see that both sides are waiting something between 11:20:04 and 11:20:19 and I still don't understand why.

BTW: I would like to attach couple file with more detailed info but cannot. I don't have "Attach" in my editor. Could you tell me please how to enable this option.

Alex Keh-Oracle

I'm going to need your entire DB trace. Can you open up a service request with Oracle Support, upload your trace files and indicate to the support analyst to contact me? They'll know how to reach me.

Alex Keh-Oracle

Alternatively, If the attachments will fit, you can email it to dotnet_us(at)oracle.com. I'll be able to access the files there.

Dmitry Sukhov

Alex Keh - Product Manager-Oracle wrote:

Alternatively, If the attachments will fit, you can email it to dotnet_us(at)oracle.com. I'll be able to access the files there.

Alex, I have sent email on specified email address. I hope it will help to investigate this issue.

Please let me know if you need more information.

Thank you for your help

Rostislav Kushnirenko

Dear Mr. Keh,

We want to excuse for so long silence since last update.

I am colleague of topic's author, and in the current story he is responsible for the C# code, which use database, but I am responsible for the database(s), to which his code is trying to establish connection. So, in the current story I will prepare and provide traces from DB side.

As it was requested, I have collected traces from DB side, trying to catch moment, when test application was establishing connection with DB and failed with “Connection timeout occurred” error. As we made our tests at client’s site, on production system – there are lots of other sessions, that’s why it’s not so easy task to provide you necessary trace file. Our test application executes every 5 mintes (simple attempt to establish connection with DB and immediate disconnect) and error comes once per 2-3 hours (sometimes more often, sometimes less).

So, I have sent archive with traces to your e-mail address – as traces are from real prod system, they contain data, which I do not want to post here, you understand. Traces are of level 8, not 16 – sorry for that, if you really need level 16 – OK, I will made them. Simply, as I said, system is production, a lot of other sessions continuously connect to the DB, they all produce millions of trace records (level 16, Carl!) and to find at least correct trace file, where recorded our “connection timeout” error – is not an easy task.

Inside archive 2016.09.02_traces.level8.zip you will see 3 files:

ORACLECONNECTIONTEST.EXE_PID_4676_DATE_2016_09_01_TIME_16_25_02.trc – trace from our test C# application, connection attempt made on 2016/Sep/01, between 16:25:02 and 16:25:18 – e.g. 15 seconds of waiting and then crash
flirthaj_ora_12372.trc
flirthaj_ora_13200.trc

Both TRC files contains entries, which covers window in question. E.g. unfortunately I can’t provide you exact file, it’s not easy to find it between hundreds and hundreds of traces from other sessions.

BTW, if you can share some advice – how to effectively organize tracing in our circumstances, and how to find then correct trace file – I will say you big thanks!

Rostislav

P.S. If needed, I can parse traces with trcasst utility.

Dmitry Sukhov

We have found a workaround.

When Managed client is configured to not use AUTHENTICATION_SERVICES it works stable without timeouts.

<oracle.manageddataaccess.client>

</settings>

</version>

</oracle.manageddataaccess.client>

But actually it is strange because Unmanaged driver works smoothly even with SQLNET.AUTHENTICATION_SERVICES=(NTS) value.

TisMeTip

Hi there,

Any luck on the issue? beside of do not use NTS.

user8092400

Hi All,

It seems that we are encountered the same timeout issue.

It happens very rarely even when there is not load on db and not more then 10 connections opened.

I applied the fix suggested by Dmitry Sukhov but it seems to not work.

This issue came once we upgraded our solution to .net 4.5.2 framework, latest NHibernate version and latest Oracle.ManagerDacaAccess provider. The db is Oracle 11 g on Windows 7. I don't know if this issue is reproducing only in a specific environment or it depends only by Oracle.ManagerDacaAccess provider.

If you have further information on this please let me know.

Thanks

mtramullas

Hello Mr. Keh,

We have found the same issue, but in our case it is not related to the first connection. We created a question in the community forums, but it has not been answered yet.

We have also a small program that reproduced the problem, but we have not found the way to attach it.. Could you give us a tip how to create the ticket bug? We have not support account.

This is the link to our question:

Dmitry Sukhov

Just wanted to add couple words.

After applying the trick with SQLNET.AUTHENTICATION_SERVICES the problem is still actual for us, although not so sharp as early. It helped only on one installation, some our other customers still experience couple times per week the same issue as I described in my first post.

Dmitry Sukhov

The issue is still actual with Managed ODP.Net product version 4.122.1.20170524

1 - 15

Locked Post

New comments cannot be posted to this locked post.

Locked on Jul 6 2017

Added on Jun 9 2016

#exception, #odp-net

15 comments

24,267 views

ODP.NET

ODP.Net Managed Driver Connection Timeout

Comments

Post Details