Long Connect Duration

Discussion of open issues, suggestions and bugs regarding ODAC (Oracle Data Access Components) for Delphi, C++Builder, Lazarus (and FPC)
Post Reply
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Long Connect Duration

Post by jfudickar » Mon 20 Oct 2008 21:45

Hi,

any ideas why the time between the before and the after connect could be so long.

I've got distances between this two events up to 40 seconds, while a connect to the same user/database with sql*plus takes only a second.

Any idea where i can have a look.

Greetings
Jens

P.S ODAC 6.50, Oracle 9/Oracle 10
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Wed 22 Oct 2008 07:47

Maybe it depend on OCI environment settings. Try to set OCIEvents variable from OraCall unit to False (in the initialization section of some unit of your application).
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Mon 27 Oct 2008 08:08

Hi Oleg,

this doesn't solve the problem.

I've done some testing, but i didn't found the problem :-(

THis is an extract of the dbmonitor log which i have enhanced with additional debug messages.

Code: Select all

  27.10.2008 08:53:20 n/a ODAC monitoring is started. Complete
  27.10.2008 08:54:14 0:0.0 TLoginSplashForm.LogonThreadExecute : Before Disconnect Complete
  27.10.2008 08:54:14 0:0.0 TLoginSplashForm.LogonThreadExecute : Between Disconnect and Connect Complete
  27.10.2008 08:54:14 0:0.0 **************************************************** Complete
  27.10.2008 08:54:14 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # Start Complete
  27.10.2008 08:54:14 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # End Complete
  27.10.2008 08:54:14 0:26.156 Connect: REP_MASTER@TAPPENTW Complete
  27.10.2008 08:54:40 0:0.0 TLoginSplashForm.LogonThreadExecute : After Connect  Complete
  27.10.2008 08:54:40 0:0.0 MainOracleSession : IntConnect Change Start Complete
  27.10.2008 08:54:40 0:0.0 MainOracleSession : IntConnect Change End Complete
  27.10.2008 08:54:40 0:0.0 tOraToolMainForm.MainOracleSessionAfterConnect # Start Complete
  27.10.2008 08:54:44 0:0.0 tOraToolMainForm.MainOracleSessionAfterConnect # End Complete
The question is: where are the 26 seconds comming from.

I have entered custom messages to all events of the session, but i can't see anything in this time.

An other interesting question is: when i do a reconnect in the same instance of the application (without restarting the program), the performance is much much better:

Code: Select all


  27.10.2008 08:58:22 0:0.0 TLoginSplashForm.LogonThreadExecute : Before Disconnect Complete
  27.10.2008 08:58:22 0:0.0 Disconnect: REP_MASTER@TAPPENTW Complete
  27.10.2008 08:58:22 0:0.0 TLoginSplashForm.LogonThreadExecute : Between Disconnect and Connect Complete
  27.10.2008 08:58:22 0:0.0 **************************************************** Complete
  27.10.2008 08:58:22 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # Start Complete
  27.10.2008 08:58:22 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # End Complete
  27.10.2008 08:58:22 0:0.140 Connect: REP_MASTER@TAPPENTW Complete
  27.10.2008 08:58:22 0:0.0 TLoginSplashForm.LogonThreadExecute : After Connect  Complete
  27.10.2008 08:58:22 0:0.0 MainOracleSession : IntConnect Change Start Complete
  27.10.2008 08:58:22 0:0.0 MainOracleSession : IntConnect Change End Complete
  27.10.2008 08:58:22 0:0.0 tOraToolMainForm.MainOracleSessionAfterConnect # Start Complete
  27.10.2008 08:58:24 0:0.0 tOraToolMainForm.MainOracleSessionAfterConnect # End Complete
Now we have a connect time less then a second, why ????

Any ideas?

Greetings and thanks
Jens
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Wed 29 Oct 2008 08:49

There are only two statements between sending 'Connect Complete' event to DBMonitor and the AfterConnect event:

Code: Select all

    Inc(FConnectCount);
    SendConnectEvent(True);
If you have ODAC sources, you can find this code in the TCustomDAConnection.PerformConnect method in the DBAccess unit.
Please try to execute this procedure in debuger step by step, and see whether the delay occurs on calling the SendConnectEvent method.
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Fri 31 Oct 2008 07:41

Hi Plash,

the debugging is not so easy, because the problem doesn't occure on my development System.

But i have enhanced the internal source with additional MonitorMessage and these are the results (be aware of the situation, that each message is done above the line, which is mentioned in the message).

First connect shows:

Code: Select all

  31.10.2008 08:26:03 0:0.0   TCustomDAConnection.PerformConnect: BeforeConnect(Self) Complete
  31.10.2008 08:26:03 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # Start Complete
  31.10.2008 08:26:03 0:0.0 tOraToolMainForm.MainOracleSessionBeforeConnect # End Complete
  31.10.2008 08:26:03 0:0.0   TCustomDAConnection.PerformConnect: DoConnect Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: TDASQLMonitorClass(SQLMonitorClass).DBConnect True Complete
  31.10.2008 08:26:03 0:28.156 Connect: PASADM@PASDB10 Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: CreateIConnection Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: PushOperation(clConnect) Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: StartWait Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: FInternalDefTransaction.CheckITransaction Complete
  31.10.2008 08:26:03 0:0.0     TCustomDAConnection.DoConnect: FIConnection.Connect Complete
  31.10.2008 08:26:31 0:0.0     TCustomDAConnection.DoConnect: StopWait Complete
  31.10.2008 08:26:31 0:0.0     TCustomDAConnection.DoConnect: PopOperation Complete
  31.10.2008 08:26:31 0:0.0     TCustomDAConnection.DoConnect: TDASQLMonitorClass(SQLMonitorClass).DBConnect False Complete
  31.10.2008 08:26:31 0:0.0   TCustomDAConnection.PerformConnect: Inc(FConnectCount) Complete
  31.10.2008 08:26:31 0:0.0   TCustomDAConnection.PerformConnect: SendConnectEvent(True) Complete
  31.10.2008 08:26:31 0:0.0   TCustomDAConnection.PerformConnect: AfterConnect(Self) Complete
  31.10.2008 08:26:31 0:0.0 TLoginSplashForm.LogonThreadExecute : After Connect  Complete
  31.10.2008 08:26:31 0:0.0 MainOracleSession : IntConnect Change Start Complete
  31.10.2008 08:26:31 0:0.0 MainOracleSession : IntConnect Change End Complete
  31.10.2008 08:26:31 0:0.0 tOraToolMainForm.MainOracleSessionAfterConnect # Start Complete
28 Seconds for the call

Code: Select all

TCustomDAConnection.DoConnect: FIConnection.Connect
When i retry the connect in the same instance the timing is different:

Code: Select all

  31.10.2008 08:26:32 0:0.0   TCustomDAConnection.PerformConnect: BeforeConnect(Self) Complete
  31.10.2008 08:26:32 0:0.0   TCustomDAConnection.PerformConnect: DoConnect Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: TDASQLMonitorClass(SQLMonitorClass).DBConnect True Complete
  31.10.2008 08:26:32 0:0.265 Connect: PASADM@PASDB10 Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: CreateIConnection Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: PushOperation(clConnect) Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: StartWait Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: FInternalDefTransaction.CheckITransaction Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: FIConnection.Connect Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: StopWait Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: PopOperation Complete
  31.10.2008 08:26:32 0:0.0     TCustomDAConnection.DoConnect: TDASQLMonitorClass(SQLMonitorClass).DBConnect False Complete
  31.10.2008 08:26:32 0:0.0 TempOracleDatabaseRepositorySession : IntConnect Change Start Complete
  31.10.2008 08:26:32 0:0.0 TempOracleDatabaseRepositorySession : IntConnect Change End Complete
  31.10.2008 08:26:32 0:0.0   TCustomDAConnection.PerformConnect: Inc(FConnectCount) Complete
  31.10.2008 08:26:32 0:0.0   TCustomDAConnection.PerformConnect: SendConnectEvent(True) Complete
  31.10.2008 08:26:32 0:0.0   TCustomDAConnection.PerformConnect: AfterConnect(Self) Complete
Now we have less then one second for the connect.

Any further ideas?

Greetings
Jens
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Fri 31 Oct 2008 08:18

And here are some additional Informations

Code: Select all

Odac Global Information:
^Description Value
OCI-DLL C:\Programme\oracle\product\10.2.0\BIN\oci.dll
OCI-Client-DLL C:\Programme\oracle\product\10.2.0\BIN\oci.dll
OCI-Version 10.2.0.1.0
OCI-Lite False
OCI-Events False
OCI-Threaded True
OCI-Shared False
Odac-Version 6.70.0.41

Session 1 MainOracleSession
HomeName
InTransaction False
Connected True
AutoCommit True
Pooling False
ConvertEOL True
Schema PASADM
Options.CharLength 0
Options.Charset
Options.ConvertEOL True
Options.DateFormat DD-MON-RR
Options.DateLanguage AMERICAN
Options.Direct False
Options.EnableIntegers True
Options.EnableNumbers False
Options.LocalFailOver False
Options.Net False
Options.NeverConnect False
Options.StatementCache False
Options.StatementCacheSize 20
Options.UseOCI7 False
Options.UseUnicode True
SQLUtil.SelectCatalogRole True
SQLUtil.InTransaction False
Greetings
Jens[/code]
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Fri 31 Oct 2008 11:09

Initialization of the OCI environment occurs on the first connect. Try to call the InitOCI procedure from OraCall manually before the connect, and see what time it will spend.
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Tue 04 Nov 2008 07:28

Hi Oleg,

this doesn't solve the problem.

The timing is unchanged. Any further ideas?

Greetings
Jens
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Wed 05 Nov 2008 09:23

You can add log messages to the TOCIConnection.Connect procedure in the OraClasses unit. You can add this messages before and after calls to OCIServerAttach and OCISessionBegin in the ConnectDefaultOCI80 subprocedure. This will make you sure that the delay occurs on one of this OCI calls.

But I think that nothing can be done to make the connection faster. Probably this depends on the network and Oracle server. And maybe SQL*Plus uses some different way to connect.
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Fri 07 Nov 2008 09:31

Is there a way to use the monitormessage procedure in this situation also?

Greetings
Jens
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Mon 10 Nov 2008 08:58

You can use the MonitorMessage method if you add a global variable to the OraClasses unit and assing the TOraSession component to this variable. Note that you can add the Ora unit to USES in IMPLEMENTATION section of OraClasses only.
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Wed 12 Nov 2008 08:09

Hi Oleg,

here is the log of the oraclasses parts:

Code: Select all

 
  12.11.2008 09:04:34 0:0.0 oraclasses : ConnectDefaultOCI80 Complete
  12.11.2008 09:04:34 0:0.0 oraclasses : ConnectDefaultOCI80 - Start Complete
  12.11.2008 09:04:34 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_CLIENT_IDENTIFIER Complete
  12.11.2008 09:04:34 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIServerAttach Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_INTERNAL_NAME Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - Set the server context in the service context Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_USERNAME Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_PASSWORD Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - GetOraConnectMode Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - hLockConnect.Enter Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - OCISessionBegin Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_SESSION Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : ConnectDefaultOCI80 - End Complete
  12.11.2008 09:05:00 0:0.0 oraclasses : SetStatementCacheSize Complete
But the realy interesting thing is: i've done the same with the odacdemo and here is the logon much faster. (Same database, same connect, same pc, same versions)
Any idea which session property/setting could result the difference?

Code: Select all

 12.11.2008 09:01:45 0:0.0 oraclasses : SetupEnvironment Complete
  12.11.2008 09:01:45 0:0.0 oraclasses : OCIInit Complete
  12.11.2008 09:01:45 0:0.0 oraclasses : ConnectDefaultOCI80 Complete
  12.11.2008 09:01:45 0:0.0 oraclasses : ConnectDefaultOCI80 - Start Complete
  12.11.2008 09:01:45 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_CLIENT_IDENTIFIER Complete
  12.11.2008 09:01:45 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIServerAttach Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_INTERNAL_NAME Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - Set the server context in the service context Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_USERNAME Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_PASSWORD Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - GetOraConnectMode Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - hLockConnect.Enter Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - OCISessionBegin Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - OCIAttrSet1 OCI_ATTR_SESSION Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : ConnectDefaultOCI80 - End Complete
  12.11.2008 09:01:46 0:0.0 oraclasses : SetStatementCacheSize Complete
Greetings
Jens
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Thu 13 Nov 2008 09:03

Please try this test also with a test application that contains only TOraSession component with default settings.
Top
jfudickar
Posts: 202
Joined: Fri 10 Mar 2006 13:03
Location: Oberursel / Germany

Post by jfudickar » Thu 04 Dec 2008 13:04

Now i found the solution, and it's unbelievable :-(

It was the filestorage of exe file.

When i install the exefile on a network drive it takes 25-30 seconds, when i install the same file on a local drive it takes only 2-5 seconds :-)

Greetings
Jens
Top
Plash
Devart Team
Posts: 2844
Joined: Wed 10 May 2006 07:09

Post by Plash » Fri 05 Dec 2008 09:05

It is good to see that this problem has been solved.
Top
Post Reply

Return to “Oracle Data Access Components”