1 2 Previous Next 17 Replies Latest reply: Mar 8, 2013 12:01 AM by Billy~Verreynne RSS

    Strange Delay in Database Connections

    Sky13
      We are seeing a strange delay when our JDBC client tries to make 4 connections to the database. The first connection takes 27 seconds (Sometimes Longer) and the other 3 connections are less than 1 second. As you can see in the log from ourJDBCclient the request for connection number 0 started at 9:09:11. It hit the Listener at 9:09:11 and then a strange gap of 27 seconds before ourJDBCclient reports a successful connect at 9:09:38 on the second line of the ourJDBCclient log. In the source code the open connections are called one right after the other. Any idea where delay may be coming from?

      We are running Oracle 11.2.3 EE Server on Linux 2.6.18-92.el5

      ourJDBCclient log:
      Feb 28, 2013 *9:09:11* AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Opening connection: jdbc:oracle:thin:@ourserver.ourdomain.com:1521:oursid, OURJDBCCLIENT
      Feb 28, 2013 *9:09:38* AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Successfully connected to the database (Connection number 0)
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Opening connection: jdbc:oracle:thin:@ourserver.ourdomain.com:1521:oursid, OURJDBCCLIENT
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Successfully connected to the database (Connection number 1)
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Opening connection: jdbc:oracle:thin:@ourserver.ourdomain.com:1521:oursid, OURJDBCCLIENT
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Successfully connected to the database (Connection number 2)
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Opening connection: jdbc:oracle:thin:@ourserver.ourdomain.com:1521:oursid, OURJDBCCLIENT
      Feb 28, 2013 9:09:38 AM paradigm.ems.dbobjects.implementations.JDBC.DBObjectConnectionHandler openConnection FINE: Successfully connected to the database (Connection number 3)

      listener.log:
      28-FEB-2013 *09:09:11* * (CONNECT_DATA=(SID=oursid)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=ourjdbcclientuser))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.1)(PORT=56495)) * establish * oursid * 0
      28-FEB-2013 09:09:13 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=qa001.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.34)(PORT=47848)) * establish * othersid1.ourserver.ourdomain.com * 0
      28-FEB-2013 09:09:16 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=ourserver.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.35)(PORT=38159)) * establish * othersid1.ourserver.ourdomain.com * 0
      28-FEB-2013 09:09:22 * service_update * othersid1 * 0
      28-FEB-2013 09:09:32 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=ourserver.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.35)(PORT=38165)) * establish * othersid1.ourserver.ourdomain.com * 0
      28-FEB-2013 09:09:37 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=ourserver.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.35)(PORT=38166)) * establish * othersid1.ourserver.ourdomain.com * 0
      28-FEB-2013 *09:09:38* * (CONNECT_DATA=(SID=oursid)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=ourjdbcclientuser))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.1)(PORT=56496)) * establish * oursid * 0
      28-FEB-2013 *09:09:38* * (CONNECT_DATA=(SID=oursid)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=ourjdbcclientuser))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.1)(PORT=56497)) * establish * oursid * 0
      28-FEB-2013 *09:09:38* * (CONNECT_DATA=(SID=oursid)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=ourjdbcclientuser))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.1)(PORT=56498)) * establish * oursid * 0
      28-FEB-2013 09:09:40 * service_update * othersid1 * 0
      28-FEB-2013 09:09:40 * service_update * othersid1 * 0
      28-FEB-2013 09:09:42 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=ourserver.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.35)(PORT=38169)) * establish * othersid1.ourserver.ourdomain.com * 0
      28-FEB-2013 09:09:47 * (CONNECT_DATA=(SERVICE_NAME=othersid1.ourserver.ourdomain.com)(INSTANCE_NAME=othersid1)(CID=(PROGRAM=oracle)(HOST=ourserver.ourdomain.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.0.10.35)(PORT=38170)) * establish * othersid1.ourserver.ourdomain.com * 0
        • 1. Re: Strange Delay in Database Connections
          damorgan
          The first question to ask is whether the delay has anything to do with the database rather than the application itself.

          Have you determined where the delay is taking place?

          Also ... what Java technology ... what framework ... what app servers ... etc. ... [No Details] = [No Help Possible]
          • 2. Re: Strange Delay in Database Connections
            Sky13
            Hi Daniel,
            Thanks for kicking in on this one. I think it is in the database, but that is just a hunch. I have no idea about the java side but have asked for the information. I was attacking it from what could the DB be doing to delay this. I will post the java information when I get it.
            Thanks again.
            • 3. Re: Strange Delay in Database Connections
              Osama_Mustafa
              Refer to MOS
              Isolating Connection Delays [ID 1359821.1]
              DNS Issue: Connections To Oracle 11g are Slow or Delayed [ID 561429.1]
              • 4. Re: Strange Delay in Database Connections
                sb92075
                Osama_mustafa wrote:
                Refer to MOS
                Isolating Connection Delays [ID 1359821.1]
                DNS Issue: Connections To Oracle 11g are Slow or Delayed [ID 561429.1]
                NOT applicable for a couple of reasons
                1) Listener log file shows IP# being used so no DNS lookup there
                2) Any DNS lookup would be PRIOR to getting the connection request to the listener;
                not after the listener logged the connection request.
                • 5. Re: Strange Delay in Database Connections
                  sb92075
                  Sky13 wrote:
                  We are seeing a strange delay when our JDBC client tries to make 4 connections to the database. The first connection takes 27 seconds (Sometimes Longer) and the other 3 connections are less than 1 second. As you can see in the log from ourJDBCclient the request for connection number 0 started at 9:09:11. It hit the Listener at 9:09:11 and then a strange gap of 27 seconds before ourJDBCclient reports a successful connect at 9:09:38 on the second line of the ourJDBCclient log. In the source code the open connections are called one right after the other. Any idea where delay may be coming from?
                  Consider the delay results from undesired application behavior.
                  What must occur between the Application Server & the Database Server,
                  upon initial login to the application?

                  Does this application utilize Connection Pooling?
                  If not, why not?
                  • 6. Re: Strange Delay in Database Connections
                    Sky13
                    We did have audit turned on for logon so I did find these entries, notice the time is 9.09.38 still no accounting for the the missing 27 seconds:

                    os_ourjdbcclientuser     OURJDBCCLIENTUSER userhost.ourdomain.com     unknown     LOGON     0     28-FEB-13 *09.09.38*.424166000 AM AMERICA/LOS_ANGELES
                    os_ourjdbcclientuser     OURJDBCCLIENTUSER userhost.ourdomain.com     unknown     LOGON     0     28-FEB-13 *09.09.38*.501727000 AM AMERICA/LOS_ANGELES
                    os_ourjdbcclientuser     OURJDBCCLIENTUSER     userhost.ourdomain.com     unknown     LOGON     0     28-FEB-13 *09.09.38*.596971000 AM AMERICA/LOS_ANGELES
                    os_ourjdbcclientuser     OURJDBCCLIENTUSER userhost.ourdomain.com     unknown     LOGON     0     28-FEB-13 *09.09.38*.676029000 AM AMERICA/LOS_ANGELES

                    Yes it does use connection pooling. From what I gather this is happening due=ring the connection pool setup. I am told that we create a connection pool then these 4 connections are opened to the database and make up the connection pool.

                    As for DNS slowness the JDBC connection does use a name not a IP Address "jdbc:oracle:thin:@ourserver.ourdomain.com:1521:oursid, OURJDBCCLIENT"
                    • 7. Re: Strange Delay in Database Connections
                      rp0428
                      >
                      We did have audit turned on for logon so I did find these entries, notice the time is 9.09.38 still no accounting for the the missing 27 seconds:

                      os_ourjdbcclientuser OURJDBCCLIENTUSER userhost.ourdomain.com unknown LOGON 0 28-FEB-13 09.09.38.424166000 AM AMERICA/LOS_ANGELES
                      >
                      Turned on where? In the DB?

                      If those logs are from the DB and show 09.09.38 and the listener shows 09.09.38 then the delay is at the server.
                      • 8. Re: Strange Delay in Database Connections
                        jgarry
                        Try letting the db get bored, then login remotely using sqlplus, repeat. Do you see the same issue?

                        I think the first doc Osama referenced has some interesting possibilities in it. I see this happen on beq connections to my hp-ux test db and dblinks to a lesser used remote XE, too. Something isn't being used, the OS pays less attention.
                        • 9. Re: Strange Delay in Database Connections
                          Hemant K Chitale
                          I will assume that
                          a) the "connection pool" is on the application server, not the database server
                          b) you are using dedicated server connections on the database server

                          It could be happening that the database server takes some time to spawn the new process for the first connection. Thereafter, once the code pages are already present in memory, the subsequent new processes are much faster.

                          Does this happen at the beginning of the day OR at any time of the day (even when there are many connections being opened) ?




                          Hemant K Chitale
                          • 10. Re: Strange Delay in Database Connections
                            Billy~Verreynne
                            Sky13 wrote:
                            We are seeing a strange delay when our JDBC client tries to make 4 connections to the database. The first connection takes 27 seconds (Sometimes Longer) and the other 3 connections are less than 1 second.
                            You will need to isolate the problem - is it the network, the listener, or the database? Or a combination.

                            Your Java client (app pool) creates a socket to connect to the database listener. It uses a hostname. So the platform running that code needs to perform hostname-to-IP resolution. It may need to wait for an ARP response (that's stored in its local ARP table for subsequent use). Etc.

                            The listener could be slow... though this would seem to be unlikely. The listener is a very basic piece of networking s/w that performs the traditional role of the Internet Super Daemon. It is not very complex ito socket programming. And a performance impact would mean some kind of underlying issue such as a logon storm (100's of TCP connect requests hitting it per seconds - a DoS attack most likely). Or perhaps reverse DNS lookup for incoming connection requests (not a common setup).

                            What could be slow is the listener-database hand off. The listener (assuming servicing a dedicated connection request) needs to create the Oracle server process for that client connection. This means a kernel call like execve or CreateRemoteThread to create the process/thread - and the kernel can be busy and could take time to allocate resources like process/thread memory, CPU register stack, etc.

                            From the database side - what could cause a performance problem is the custom initialisation code for that database process. Such as a logon trigger.

                            Joel's suggestion using SQL*Plus is a good one. It is an ideal tool for starters, trying to isolate the problem.
                            • 11. Re: Strange Delay in Database Connections
                              Sky13
                              I got some more information about the java ODBC client. We are using a proprietary application built under Java 1.6 (JDK) with the Oracle JDBC driver. The servers are running Linux. We don’t use tomcat or anything like that. I am not sure if this helps.

                              We are using dedicated connection on the database so the connection pool is on the java side.
                              • 12. Re: Strange Delay in Database Connections
                                Billy~Verreynne
                                You will still need to isolate the error. And that means finding ways to test components/layers in isolation.
                                • 13. Re: Strange Delay in Database Connections
                                  Sky13
                                  Hi Bill and All,

                                  I agree with the problem isolation as trouble shooting always comes down to that. I think I have done some of that at a high level by looking at the logs. It seems to be pointing at hand off from the Listener to the Database but just for the first one. I was reading Doc ID 561429.1 and it seems to match and applies to my version of 11.2.0.1. We are planning to upgrade to 11.2.0.2 anyway so I will keep you all posted to what happens after the upgrade.
                                  • 14. Re: Strange Delay in Database Connections
                                    Hemant K Chitale
                                    Curious that it is an Oracle bug.


                                    Hemant K Chitale
                                    1 2 Previous Next