6 Replies Latest reply: Jul 12, 2012 7:08 PM by 705081 RSS

    Pro*C CONNECT or RELEASE taking 20+ seconds

    705081
      The basic problems are
      <li> the EXEC SQL ROLLBACK WORK RELEASE; statement takes a long time (I've seen 25 seconds)
      <li> the EXEC SQL CONNECT :usrname; statement also takes a long time (I've seen 8 seconds)
      What are the things I should check?

      h1.
      Details:
      The database server is on Linux (Red Hat Enterprise Linux ES release 3 (Taroon Update 7)), while the run-time environment, Pro*C++ precompiler, C++ compiler, and client libraries are on Alpha (Tru64 v 5.1B-4).

      On the Alpha, the Oracle version is 9.2.0.8.0 (both SQL*Plus and 'proc'), and the C++ compiler is Compaq C++ V6.5-042 for HP Tru64 UNIX V5.1B (Rev. 2650). On the Linux, the database server version is 9.2.0.4.0

      There is very little activity on this database, or on the server (about 1% processor load). For the most recent problem with long disconnect times, the only other known activity is another Pro*C process waiting on a DBMS_LOCK (user lock) being held by this one. But because this one is taking so long to exit, the other Pro*C process times out failing to get the lock (after which it does an EXEC SQL ROLLBACK RELEASE). There are three other Pro*C processes, but they have exited prior to t=13 (see below).

      One observation is that when the second process times out and does the EXEC SQL ROLLBACK RELEASE; both processes then return from that statement, after which they exit.

      My environment variables, in the client environment, are
      NLS_LANG=american_america.US7ASCII
      ORACLE_BASE=/u01/app/oracle
      ORACLE_SID=LINUX
      DBA=/u01/app/oracle/admin
      TNS_ADMIN=/u01/app/oracle/product/9.2.0/db/network/admin
      ORACLE_HOME=/u01/app/oracle/product/9.2.0/db
      TWO_TASK=LINUX
      The code fragments involved are
      const time_t startTime = time(0);   // seconds since epoch - executed at file scope 
                             // when both processes begin.
      #define COUTVAR(x)       if (DEBUGGING_STATUS) cout << x << ", t=" << (time(0) - m_startTime) << ": "
      #define CERRVAR(x)                             cerr << x << ", t=" << (time(0) - m_startTime) << ": "
      #define SQLINFOHERE     /* code to stash __FILE__ and __LINE__ into global vars, used if an error occurs */
      
      OracleConnection::OracleConnection(const char *processTag, time_t startTime, const Autotester &)
        : m_processTag(processTag), m_startTime(startTime)
      {
          EXEC SQL BEGIN DECLARE SECTION;
            char myUsername[] = "AUTOTESTER/xxxx";
          EXEC SQL END DECLARE SECTION;
      
          COUTVAR(m_processTag) << "About to EXEC SQL CONNECT" << endl;
          SQLINFOHERE;
          EXEC SQL CONNECT :myUsername;
          COUTVAR(m_processTag) << "EXEC SQL CONNECT successful" << endl;
      }
      
      OracleConnection::~OracleConnection()
      {
        // Function Try Blocks do not work in the HP compiler (at runtime, get this message:
        // Internal error: could not find live exception.)
        // Therefore nest normal try blocks.
        try
        {
          try
          {
            COUTVAR(m_processTag) << "About to EXEC SQL ROLLBACK RELEASE" << endl;    // Output t=13
            SQLINFOHERE;
            EXEC SQL ROLLBACK WORK RELEASE;
            COUTVAR(m_processTag) << "EXEC SQL ROLLBACK RELEASE successful" << endl;  // Output t=38 (25s later)
          }
          catch(...)
          {
            CERRVAR(m_processTag) << "Error in EXEC SQL ROLLBACK RELEASE" << endl;
          }
        }
        catch(...)
        {
          // Here we don't do ANYTHING, because we don't want to throw (another) exception
          // if it happens to be processing another exception.
        }
      }
      h2.
      Other things tried
      When I do this
      $ sqlplus autotester/xxxx < /dev/null
      it never takes more than 0.3 seconds to connect and disconnect. The environment variables are the same.

      The sqlnet.ora file has no mention of SQLNET.AUTHENTICATION_SERVICES, I have heard that setting it to (NTS) can slow things down, and someone else notes that you can generally comment it out. But we've never had it in our sqlnet.ora file.

      Using tnsping gives this:
      $ tnsping LINUX
      
      TNS Ping Utility for Compaq Tru64 UNIX: Version 9.2.0.8.0 - Production on 28-JUN-2012 12:02:16
      
      Copyright (c) 1997, 2006, Oracle Corporation.  All rights reserved.
      
      Used parameter files:
      /u01/app/oracle/product/9.2.0/db/network/admin/sqlnet.ora
      
      
      Used TNSNAMES adapter to resolve the alias
      Attempting to contact (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(Host = mylinuxhost.FICTIONAL.com)
        (Port = 1521)) (CONNECT_DATA = (SERVICE_NAME = unix.world)))
      OK (30 msec)
      What are the things I should check?

      Edited by: Logical_Star on 27-Jun-2012 20:36, to make code output narrower
        • 1. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
          prajithparan
          Try from a OCI connect/disconnect code and check the timing
          • 2. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
            705081
            OK, I have converted the program to OCI (I had to convert the whole program, because Pro*C and OCI cannot be mixed) and found similar behaviour.

            The OCI version of the program is (sometimes) taking 28 seconds to disconnect, whereas the Pro*C version is now taking 40 seconds to disconnect. I note that the frequency is much higher in the Pro*C program.

            The OCI version has this code
            #define LEN_SQLGLM_MSG      512   /* Oracle manual: can be max of 512 chars */
            
            const time_t startTime = time(0);   // seconds since epoch - executed at file scope 
                                              // when both processes begin.
            #define COUTVAR(x)       if (DEBUGGING_STATUS) cout << x << ", t=" << (time(0) - m_startTime) << ": "
            #define CERRVAR(x)                             cerr << x << ", t=" << (time(0) - m_startTime) << ": "
            
            #define CHECK_AND_THROW(r,m)   do {                                                    \
                                 if(r) { OraText errbuf[100] = "Failed to get error"; int errcode; \
             OCIErrorGet((dvoid *)p_err, (ub4) 1, (text *) NULL, &errcode, errbuf, (ub4) sizeof(errbuf), OCI_HTYPE_ERROR); \
             string errMsg(m); errMsg += " ... "; errMsg += reinterpret_cast<const char*>(errbuf); \
             if (errMsg.size() > LEN_SQLGLM_MSG) errMsg.erase(LEN_SQLGLM_MSG);                     \
             throw ExDb(r, errMsg.c_str(), __LINE__, __FILE__);} } while(0)
            
            OracleConnection::OracleConnection(const char *processTag, time_t startTime, const Autotester &)
              : m_processTag(processTag), m_startTime(startTime), p_env(0), p_err(0), p_svc(0),
                p_sql(0), p_dfn(0), p_bnd(0)
            {
              COUTVAR(m_processTag) << "About to connect" << endl;
            
              int rc = OCIInitialize((ub4) OCI_DEFAULT, (dvoid *)0,  /* Initialize OCI */
                      (dvoid * (*)(dvoid *, size_t)) 0,
                      (dvoid * (*)(dvoid *, dvoid *, size_t))0,
                      (void (*)(dvoid *, dvoid *)) 0 );
              CHECK_AND_THROW(rc, "OCIInitialize error");
            
              /* Initialize evironment */
              rc = OCIEnvInit( (OCIEnv **) &p_env, OCI_DEFAULT, (size_t) 0, (dvoid **) 0 );
              CHECK_AND_THROW(rc, "OCIEnvInit error");
            
              /* Initialize handles */
              rc = OCIHandleAlloc( (dvoid *) p_env, (dvoid **) &p_err, OCI_HTYPE_ERROR,
                      (size_t) 0, (dvoid **) 0);
              CHECK_AND_THROW(rc, "OCIHandleAlloc error 1");
              rc = OCIHandleAlloc( (dvoid *) p_env, (dvoid **) &p_svc, OCI_HTYPE_SVCCTX,
                      (size_t) 0, (dvoid **) 0);
              CHECK_AND_THROW(rc, "OCIHandleAlloc error 2");
            
              /* Connect to database server */
              rc = OCILogon(p_env, p_err, &p_svc, "AUTOTESTER", 10, "xxxxx", 10, "LINUX", 5);
              CHECK_AND_THROW(rc, "OCILogon error");
            
              COUTVAR(m_processTag) << "Connect successful" << endl;
            }
            
            
            OracleConnection::~OracleConnection()
            {
              // Function Try Blocks do not work in the HP compiler (at runtime, get this message:
              // Internal error: could not find live exception.)
              // Therefore nest normal try blocks.
              try
              {
                try
                {
                  COUTVAR(m_processTag) << "About to disconnect" << endl;     // Output t=13
            
                  int rc = OCILogoff(p_svc, p_err);
                  CHECK_AND_THROW(rc, "OCILogoff error");
                  rc = OCIHandleFree((dvoid *) p_sql, OCI_HTYPE_STMT);
                  CHECK_AND_THROW(rc, "OCIHandleFree error 1");
            
                  //NOTE: This OCIHandleFree call should be done, in theory, but it was giving
                  //      an unknown error for which OCIErrorGet was not retrieving the error.
                  //NOTE rc = OCIHandleFree((dvoid *) p_svc, OCI_HTYPE_SVCCTX);
                  //NOTE CHECK_AND_THROW(rc, "OCIHandleFree error 2");
            
                  rc = OCIHandleFree((dvoid *) p_err, OCI_HTYPE_ERROR);
                  CHECK_AND_THROW(rc, "OCIHandleFree error 3");
            
                  COUTVAR(m_processTag) << "Disconnect successful" << endl;   // output t=41 (28s later)
                }
                catch(ExDb &ex)
                {
                  CERRVAR(m_processTag) << "SQL Error while disconnecting" << endl;
                  ex.print_error();
                }
                catch(...)
                {
                  CERRVAR(m_processTag) << "Strange Error while disconnecting" << endl;
                }
              }
              catch(...)
              {
                // Here we don't do ANYTHING, because we don't want to throw (another) exception
                // if it happens to be processing another exception.
              }
            }
            Edited by: Logical_Star on 02-Jul-2012 00:53 (wrong TNSNAME)
            • 3. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
              705081
              I should explain, more fully, that there are five processes involved, known as C1 to C5. They each log in separately (all to the same account), and take certain user locks via Dbms_Lock package, in amongst sleep()ing and/or timing out after failing to take the lock held by another process. Then they log out.

              It sometimes appears that when C2 logs out, you get the message just prior to log out, then it hangs for a while. Then when C5 logs out, it prints its message just prior to log out, then both C2 and C5 print the message just after log out, as in the output fragments below. In other words, for some reason, process C2 hangs until C5 logs out.
              // For OCI version
              C2, t=14: About to disconnect
              C5, t=41: About to disconnect
              C2, t=41: Disconnect successful
              C5, t=41: Disconnect successful
              and
              // For Pro*C version
              C2, t=13: About to EXEC SQL ROLLBACK RELEASE
              C5, t=53: About to EXEC SQL ROLLBACK RELEASE
              C2, t=53: EXEC SQL ROLLBACK RELEASE successful
              C5, t=53: EXEC SQL ROLLBACK RELEASE successful
              So, given the above result, what should I check next?
              • 4. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
                prajithparan
                Let us isolate the issue. Try some small OCI which connects and discconnects after doing some selects from Dual or table.

                If this works fine then it should be DBMS -LOCK package you are using may be causing this.

                Hope you have dedicated connection for each C1 to C5 processes and not shared one.

                If shared try the dedicated also

                regards
                • 5. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
                  705081
                  Hi prajithparan,

                  I'm fairly sure the server was configured for dedicated server, but I have extended the connect string to specify dedicated, in the tnsnames.ora file.

                  I'm now running some tests, with a <tt>SELECT from DUAL</tt>. I've also made some changes to the OCIHandleAlloc/OCIHandleFree calls: I am now allocating and deallocating the p_sql (OCI_HTYPE_STMT) handle for each individual SQL statement, and therefore I have removed it from the destructor. I also realise the OCILogoff() call deallocates the p_svc (OCI_HTYPE_SVCCTX) handle, which explains the error alluded to in the commented code in the destructor. In parallel, I also realise the OCILogon() call allocates the p_svc (OCI_HTYPE_SVCCTX) handle, so I have removed the explicit OCIHandleAlloc() call for this handle from the constructor.

                  Results so far:
                  <li>The program with <tt>SELECT 42 FROM DUAL</tt> did not encounter any significant delays (maximum of 3 seconds to connect).
                  <li>The program with the OCI calls to the Dbms_Lock package +with the altered OCIHandleAlloc/OCIHandleFree for p_sql (OCI_HTYPE_STMT) also has not encountered any significant delays.
                  <li>tnsping now returns ... (note the SERVER=dedicated part):
                  $ tnsping LINUX
                  
                  TNS Ping Utility for Compaq Tru64 UNIX: Version 9.2.0.8.0 - Production on 11-JUL-2012 16:09:11
                  
                  Copyright (c) 1997, 2006, Oracle Corporation.  All rights reserved.
                  
                  Used parameter files:
                  /u01/app/oracle/product/9.2.0/db/network/admin/sqlnet.ora
                  
                  
                  Used TNSNAMES adapter to resolve the alias
                  Attempting to contact (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(Host = mylinuxhost.FICTIONAL.com)
                   (Port = 1521)) (CONNECT_DATA = (SERVICE_NAME = unix.world) (SERVER = dedicated)))
                  I will continue to test, as it can take some time before delays become evident. I will also test the Pro*C version with the explicitly <tt>SERVER = dedicated</tt> connect string.
                  • 6. Re: Pro*C CONNECT or RELEASE taking 20+ seconds
                    705081
                    The problem disappeared when I included <tt>(SERVER = dedicated)</tt> in the connection string, for both OCI and Pro*C versions.

                    My database had been set up to allow shared server, contrary to what I earlier thought.

                    While you would think that shared server connections would be transparent to the client processes, my latest observations are:
                    <li> The OCI version takes 27 seconds to disconnect.
                    <li> The Pro*C version takes 8 seconds to connect.