This discussion is archived
8 Replies Latest reply: Apr 23, 2012 5:20 AM by 931613 RSS

10g express taking 20+ seconds to logon

931613 Newbie
Currently Being Moderated
I have a Pramati Java server that makes several connections to Oracle 10g express on startup, all running on my Windows 7 32-bit workstation. Each connection takes 20 seconds or more, which adds up to a lot.

Here is the SQLNET trace. Note that nlstdipi takes 5 seconds, and nrigbni takes 10 seconds. I think the other 5 second wait may be in the listener.

Any ideas on what could cause this?

[18-APR-2012 15:06:39:111] --- TRACE CONFIGURATION INFORMATION FOLLOWS ---
[18-APR-2012 15:06:39:111] New trace stream is C:\oraclexe\app\oracle\product\10.2.0\server\network\trace\svr_2716.trc
[18-APR-2012 15:06:39:111] New trace level is 6
[18-APR-2012 15:06:39:111] --- TRACE CONFIGURATION INFORMATION ENDS ---
[18-APR-2012 15:06:39:111] --- PARAMETER SOURCE INFORMATION FOLLOWS ---
[18-APR-2012 15:06:39:111] Attempted load of system pfile source C:\oraclexe\app\oracle\product\10.2.0\server\network\admin\sqlnet.ora
[18-APR-2012 15:06:39:111] Parameter source loaded successfully
[18-APR-2012 15:06:39:111]
[18-APR-2012 15:06:39:111] -> PARAMETER TABLE LOAD RESULTS FOLLOW <-
[18-APR-2012 15:06:39:111] Successful parameter table load
[18-APR-2012 15:06:39:111] -> PARAMETER TABLE HAS THE FOLLOWING CONTENTS <-
[18-APR-2012 15:06:39:111] TRACE_LEVEL_SERVER = ADMIN
[18-APR-2012 15:06:39:111] TRACE_LEVEL_CLIENT = USER
[18-APR-2012 15:06:39:111] TRACE_UNIQUE_CLIENT = ON
[18-APR-2012 15:06:39:111] --- PARAMETER SOURCE INFORMATION ENDS ---
[18-APR-2012 15:06:39:111] --- LOG CONFIGURATION INFORMATION FOLLOWS ---
[18-APR-2012 15:06:39:111] Log stream will be "C:\oraclexe\app\oracle\product\10.2.0\server\network\log\sqlnet.log"
[18-APR-2012 15:06:39:111] Log stream validation not requested
[18-APR-2012 15:06:39:111] --- LOG CONFIGURATION INFORMATION ENDS ---

[18-APR-2012 15:06:39:111] nlstdipi: entry
[18-APR-2012 15:06:44:118] nlstdipi: exit
[18-APR-2012 15:06:44:118] nagblini: entry
[18-APR-2012 15:06:44:118] nau_gin: entry
[18-APR-2012 15:06:44:118] nau_gparams: entry
[18-APR-2012 15:06:44:118] nam_gbp: Reading parameter "sqlnet.authentication_required" from parameter file
[18-APR-2012 15:06:44:118] nam_gbp: Parameter not found
[18-APR-2012 15:06:44:118] nau_gparams: Using default value "FALSE"
[18-APR-2012 15:06:44:118] nau_gslf: entry
[18-APR-2012 15:06:44:118] nam_gic: entry
[18-APR-2012 15:06:44:118] nam_gic: Counting # of items in "sqlnet.authentication_services" parameter
[18-APR-2012 15:06:44:118] nam_gic: Parameter not found
[18-APR-2012 15:06:44:118] nam_gic: Found 0 items
[18-APR-2012 15:06:44:118] nam_gic: exit
[18-APR-2012 15:06:44:118] nau_gslf: Using default value "all available adapters"
[18-APR-2012 15:06:44:118] nauss_set_state: entry
[18-APR-2012 15:06:44:118] nauss_set_state: exit
[18-APR-2012 15:06:44:118] nau_gslf: exit
[18-APR-2012 15:06:44:118] nau_gparams: exit
[18-APR-2012 15:06:44:118] nau_gin: exit
[18-APR-2012 15:06:44:118] nagblini: exit
[18-APR-2012 15:06:44:118] nigini: entry
[18-APR-2012 15:06:44:118] nigini: Count in the NL global area is now 2
[18-APR-2012 15:06:44:118] nigini: Count in NI global area now: 1
[18-APR-2012 15:06:44:118] nrigbi: entry
[18-APR-2012 15:06:44:118] nrigbni: entry
[18-APR-2012 15:06:54:149] nrigbni: Unable to get data from navigation file tnsnav.ora
[18-APR-2012 15:06:54:149] nrigbni: exit
[18-APR-2012 15:06:54:149] nrigbi: exit

[... connection continues until 15:06:54:180]
  • 1. Re: 10g express taking 20+ seconds to logon
    clcarter Expert
    Currently Being Moderated
    All the Java stuff is running on the same host? Going via the listener, with a JDBC type of connect string (host:port:sid) ?

    How about a regular sqlplus login session? Just to try taking Java and networking out of the equation.

    And a sqlplus connect <username>@<tnsname> to put networking back into the equation?

    And all the networking items (hostname, nslookup, IP address, ipconfig, NIC configuration) is all healthy? DHCP?
  • 2. Re: 10g express taking 20+ seconds to logon
    931613 Newbie
    Currently Being Moderated
    Running "sqlplus user/pass" on its own is quick. The trace shows under 1 ms for the given procedures.
    Runinng "sqlplus user/pass" while the server is connecting shows the same behavior as the server. 5 seconds for nlstdipi, 10 seconds for nrigbni.
  • 3. Re: 10g express taking 20+ seconds to logon
    clcarter Expert
    Currently Being Moderated
    while the server is connecting
    You mean the JSP or tomcat, the java server stuff? What about after "server is connected" ... if it needs lots of separate sessions, and they're all trying to connect at the exact same moment it just might take several moments for them all to get established.

    How about sqlplus user/pass@xe, that one will go through the listener.
    makes several connections to Oracle 10g express on startup
    Define "several". Is it 20? 50? All within 1 second? 10 seconds?

    If there is a way to make the JDBC connect string use the service name instead of the ORACLE_SID, and specify a shared server connection- that will eliminate the overhead of starting up a server process for each connection.

    An out-of-the-box XE networking configuration should be using a shared connections anyway, normally you'll get a shared server connection unless you specify that you want a dedicated session.
  • 4. Re: 10g express taking 20+ seconds to logon
    931613 Newbie
    Currently Being Moderated
    The application server is Pramati 6.0R4. There are two instances, an EJB server and a portal server. They are used to run Savvion BPM from Progress.

    As far as I can tell, the server is doing its own pooling. It seems that the two servers only have one thread each making a connection, The startup process results in a total of 69 connections. Here's a sample from the beginning and end.

    select sid, serial#, logon_time
    from v$session
    where program like 'JDBC Connect%'
    order by logon_time

    201 1 04/19/2012 08:37:27
    205 12 04/19/2012 08:37:27
    202 6 04/19/2012 08:37:48
    203 15 04/19/2012 08:38:08
    200 3 04/19/2012 08:38:28
    199 2 04/19/2012 08:38:48
    198 2 04/19/2012 08:39:08
    197 2 04/19/2012 08:39:28
    196 4 04/19/2012 08:39:48
    195 2 04/19/2012 08:40:08
    [dozens of rows ...]
    141 22 04/19/2012 08:59:59
    140 22 04/19/2012 09:00:19
    139 22 04/19/2012 09:00:39
    136 6 04/19/2012 09:01:11
    137 22 04/19/2012 09:01:46
    135 49 04/19/2012 09:02:11

    The wait between connections is almost always 20 seconds.
    After the startup process is finished, sqlplus will start instantly.

    Deploying a Java application causes the server to make four more connections.

    130 326 04/19/2012 09:31:47
    129 88 04/19/2012 09:31:57
    128 24 04/19/2012 09:32:17
    127 22 04/19/2012 09:32:38

    While this is happening, it again takes 15 seconds to start sqlplus.

    sqlplus will net connect to user/pass@xe...

    ERROR:
    ORA-12154: TNS:could not resolve the connect identifier specified

    ...which is odd, because XE is defined in tnsnames.ora.

    The application server is set up to connect via JDBC through Savvion's Oracle package:
    jdbc:savvion:oracle://FQDN:1521;SID=xe;serverName=FQDN
    where "FQDN" is the fully qualified domain name of my workstation.

    I'll try changing the connect string later today.
  • 5. Re: 10g express taking 20+ seconds to logon
    clcarter Expert
    Currently Being Moderated
    ORA-12154: TNS:could not resolve the connect identifier
    and
    XE is defined in tnsnames.ora.
    Hmmm maybe another Oracle client is in the way, something installed later might preempt the XE ORACLE_HOME and the tnsnames.ora in use might not be the one you think.

    A command box `tnsping xe` (or even `tnsping <anything>`) will reveal which sqlnet.ora file is in use - the path is in the line after "Used parameter files:" and will also be the same location of the tnsnames.ora file in use.

    And just for fun, on your v$session query add the SERVER column. If they show 'DEDICATED' maybe there's a way to make the jdbc use a shared server session. But ... probably not. :(
  • 6. Re: 10g express taking 20+ seconds to logon
    931613 Newbie
    Currently Being Moderated
    Looks like TNSPING is getting SQLNET.ORA from a network path, I think that's so we can get to the "public" internal DBs. I'll find out where that gets set.

    Yes, they're all dedicated.

    I'm having some trouble finding exactly where the JDBC URL gets set, or if the app server is building it from XML configuration fields.

    It's odd that something the Savvion JDBC client does causes the Oracle server to sieze up for 20 seconds - and not just in the dedicated process, because while the JDBC client is connecting, the delay occurs in a local connect from SQLPLUS.

    It might be a bad interaction with the virus scanner or other OS-level hook, I'm not sure what to look for there.

    Edited by: 928610 on Apr 20, 2012 5:46 AM
  • 7. Re: 10g express taking 20+ seconds to logon
    clcarter Expert
    Currently Being Moderated
    getting SQLNET.ORA from a network path
    Interesting. sqlnet.ora is for the client configuration, IMHO its not good to put a dependency on the network for a configuration file.
    where the JDBC URL gets set
    If you figure that out, try adjusting the connect string to <host>:<port>/<servicename> in place of <port>:<sid> that should let the connection go via shared server

    The service name for shared server connections shows in $ lsnrctl services in the stanza with handler(s) showing each Dxxx dispatcher. "Out of the box" it should be XEXDB with one dispatcher, "D000" and established:refused:current connect counts.

    And adjusting the MTS parameters to increase the number of dispatchers might help spread the connect load, i.e. with a system connection:
    alter system set dispatchers = '(PROTOCOL=TCP)(dispatchers=5)(SERVICE=XEXDB)' scope=both;
    alter system set max_dispatchers = 20 scope=both;
    alter system set max_shared_servers = 20 scope=both;
    alter system set shared_servers = 5 scope=both;
    Fairly sure all those adjustments can be made without stopping/starting the listener or database. If that SERVICE= name gets changed, might cause some glitches for Apex, if you're using that at all. Changing the SERVICE= will require at least an 'alter system register;' to push an instance registration through the listener.
  • 8. Re: 10g express taking 20+ seconds to logon
    931613 Newbie
    Currently Being Moderated
    Solved! That SQLNET.ORA was the key.

    Nothing to do with Pramati Server, I recreated the problem with SQL Developer.

    I had a previous Oracle Client installation on my workstation. Its TNS_ADMIN path was set to a network folder, where the TNS addresses for our non-personal DBs are stored. The Oracle Express server was trying to look at this path, but it did not have netlogon privileges, so it would block for 5 seconds and return - four blocks per connection = 20 seconds.

    Solution: set the TNS_ADMIN path for Oracle Express (XE)

    Open regedit, go to
    HKEY_LOCAL_MACHINE\SOFTWARE\ORACLE\KEY_XE

    And add string value:
    TNS_ADMIN
    C:\oraclexe\app\oracle\product\10.2.0\server\NETWORK\ADMIN


    Thanks!

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points