Page 1 of 1
Long Connect Duration
Posted: Mon 20 Oct 2008 21:45
by jfudickar
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
Posted: Wed 22 Oct 2008 07:47
by Plash
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).
Posted: Mon 27 Oct 2008 08:08
by jfudickar
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
Posted: Wed 29 Oct 2008 08:49
by Plash
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.
Posted: Fri 31 Oct 2008 07:41
by jfudickar
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
Posted: Fri 31 Oct 2008 08:18
by jfudickar
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]
Posted: Fri 31 Oct 2008 11:09
by Plash
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.
Posted: Tue 04 Nov 2008 07:28
by jfudickar
Hi Oleg,
this doesn't solve the problem.
The timing is unchanged. Any further ideas?
Greetings
Jens
Posted: Wed 05 Nov 2008 09:23
by Plash
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.
Posted: Fri 07 Nov 2008 09:31
by jfudickar
Is there a way to use the monitormessage procedure in this situation also?
Greetings
Jens
Posted: Mon 10 Nov 2008 08:58
by Plash
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.
Posted: Wed 12 Nov 2008 08:09
by jfudickar
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
Posted: Thu 13 Nov 2008 09:03
by Plash
Please try this test also with a test application that contains only TOraSession component with default settings.
Posted: Thu 04 Dec 2008 13:04
by jfudickar
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
Posted: Fri 05 Dec 2008 09:05
by Plash
It is good to see that this problem has been solved.