Time to create datasource connection

Report · Jul 26, 2016

We are having intermittent performance problems with a relatively new web application. It seems to be related to the database, but our oracle logs show that the queries are being executed very quickly. I temporarily turned on database logging within the datasource and it looks like the delay is caused by determining if a connection is available or spinning up a new datasource connection. The log is below shows a time jump of seconds. This particular query uses a different datasource than the ones before it, so it does make sense that a new connection would need to be created. However, I've found that usually it only takes 300-400 ms to create a connection. Any suggestions?

Our environment:

Oracle 12c

Coldfusion 11 Enterprise Update 9

Redhat Enterprise Linux 7.2

Apache 2.4.6

Driver: macromedia.jdbc.oracle.OracleDriver 5.1

--Here's a small snippet of the log. Prior to this, it executes several queries quickly.

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> ResultSetMetaData[331].isCaseSensitive(int column)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> column = 1

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK (true)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> ResultSetMetaData[331].getColumnType(int column)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> column = 1

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK (12)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> ResultSetMetaData[331].getColumnTypeName(int column)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> column = 1

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK (varchar2)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> ResultSet[128].next()

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK (false)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> ResultSet[128].close()

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> PreparedStatement[119].setMaxRows(int max)

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> max = 0

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> PreparedStatement[119].close()

spy(ajp-bio-8014-exec-1026)(2016/06/24 13:39:33.365)>> OK

--All of a sudden, the clock jumps 4 seconds. The log that follows shows a new connection being created.

spy(Thread-38313)(2016/06/24 13:39:37.942)>> Connection[5].getMetaData()

spy(Thread-38313)(2016/06/24 13:39:37.943)>> OK (DatabaseMetaData[137])

spy(Thread-38313)(2016/06/24 13:39:37.943)>> DatabaseMetaData[137].getURL()

spy(Thread-38313)(2016/06/24 13:39:37.943)>> OK (jdbc:macromedia_direct:oracle://150.231.26.14:1521;JDBCBEHAVIOR=1;APPLICATIONNAME=;KEYPASSWORD=;ENCRYPTIONTYPES=(AES128,AES192,AES256,DES,3DES112,3DES168,RC4_40,RC4_56,RC4_128,RC4_256);SUPPORTLINKS=false;CATALOGOPTIONS=2;REFCURSORSUPPORT=true;INITIALCOLUMNBUFFERSIZE=-1;BULKLOADBATCHSIZE=1000;ENABLEBULKLOAD=false;CONNECTIONRETRYDELAY=1;CLIENTUSER=;SID=hdcctest;WORKAROUNDS=0;VALIDATESERVERCERTIFICATE=true;CONVERTNULL=1;DATAINTEGRITYLEVEL=Rejected;CONNECTIONRETRYCOUNT=5;ACTION=;TRUSTSTORE=;STRINGPARAMSMUSTMATCHCHARCOLUMNS=true;LOADLIBRARYPATH=;EDITIONNAME=;MAXPOOLEDSTATEMENTS=500;CLIENTID=java.lang.Thread;SENDFLOATPARAMETERSASSTRING=false;CRYPTOPROTOCOLVERSION=;SYSLOGINROLE=;SERVICENAME=;QUERYTIMEOUT=0;DATAINTEGRITYTYPES=(MD5,SHA1);PROGRAMID=;SECURERANDOMALGORITHM=;REGISTERSTATEMENTPOOLMONITORMBEAN=false;MODULE=java.lang.Thread;IMPORTSTATEMENTPOOL=;LOADBALANCING=false;KEYSTOREPASSWORD=;SERVERTYPE=;LOGINTIMEOUT=0;RANDOMGENERATOR=SECURERANDOM;FAILOVERGRANULARITY=nonAtomic;ACCOUNTINGINFO=;REPORTRECYCLEBIN=true;ENCRYPTIONMETHOD=NoEncryption;WIREPROTOCOLMODE=2;FAILOVERMODE=connect;ENABLESERVERRESULTCACHE=false;SDUSIZE=;SUPPORTBINARYXML=false;INITIALIZATIONSTRING=;BATCHPERFORMANCEWORKAROUND=false;SENDSTRINGPARAMETERSASUNICODE=false;JAVADOUBLETOSTRING=false;CODEPAGEOVERRIDE=;AUTHENTICATIONMETHOD=userIDPassword;CLIENTHOSTNAME=;TNSSERVERNAME=;COMMITBEHAVIOR=serverDefault;RESULTSETMETADATAOPTIONS=0;FAILOVERPRECONNECT=false;SPYATTRIBUTES=(log=(file)/opt/coldfusion11/cfusion/logs/dms_db1.log; linelimit=80;logTName=yes;timestamp=yes);INSENSITIVERESULTSETBUFFERSIZE=2048;TNSNAMESFILE=;ENABLECANCELTIMEOUT=false;EMBEDDED=true;ENCRYPTIONLEVEL=Rejected;HOSTNAMEINCERTIFICATE=;FETCHTSWTZASTIMESTAMP=false;ALTERNATESERVERS=;LOBPREFETCHSIZE=4000;BULKLOADOPTIONS=0;TRUSTSTOREPASSWORD=;KEYSTORE=)

spy(Thread-38313)(2016/06/24 13:39:37.943)>> DatabaseMetaData[137].getDriverName()

spy(Thread-38313)(2016/06/24 13:39:37.943)>> OK (Oracle)

spy(Thread-38313)(2016/06/24 13:39:37.943)>> DatabaseMetaData[137].getDriverVersion()

spy(Thread-38313)(2016/06/24 13:39:37.944)>> OK (5.1.4.000286 (F000250.U000108))

spy(Thread-38313)(2016/06/24 13:39:37.944)>> DatabaseMetaData[137].getDatabaseProductName()

spy(Thread-38313)(2016/06/24 13:39:37.944)>> OK (Oracle)

spy(Thread-38313)(2016/06/24 13:39:37.944)>> DatabaseMetaData[137].getDatabaseProductVersion()

spy(Thread-38313)(2016/06/24 13:39:37.944)>> OK (11.2.0.3.0)

Report · Jul 26, 2016

Have you considered checking the option for maintaining database connections, in the datasource, in CFAdmin?

HTH,

^_^

Report · Jul 27, 2016

Yes, maintain connections is enabled. This particular code is for logging into the application. Several queries are being performed to authenticate the user and then set up the user's session. There are some calls that are performed without passing the user's database credentials (functions that are also called from outside the login) and calls that are performed with passing credentials. Watching the pool, it appears a single user gets a connection set aside for each case. The first time that a query is made to the database passing user credentials is when we see a 4-5 second delay. It does not happen all the time, but when it does it is always at the same query.

Report · Feb 15, 2017

We continue to have problems with this. In my latest test case, I'm comparing creating of a new db connection to an oracle database between our development environment and testing environment. I'm the only user on these apps, however it is possible a small number of other users are on the servers in different apps.

Development - Page makes 3 queries quickly (<10ms each) using a connection that already exists. These early queries do not pass username/password and therefore use the credentials in the DSN configuration. Then the code make a simple query call, but passes username/password. This query executes in 300-400 ms.

Testing - Same code. Page makes 3 queries quickly (10-20ms each) using a connection that already exists. These early queries do not pass username/password and therefore use the credentials in the DSN configuration. Then the code make a simple query call, but passes username/password. This query executes in 5000-6000 ms.

The datasources for both servers are set with the same settings:

Maintain Connections - on

Max Pooled Statements - 100

Timeout - 20

Interval - 7

Query Timeout - 0

When I turn on database logging for the testing, I see the 5 second delay between the closing of the prepared statement for the 3rd query and the request for the new connection (log below, see jump between 15:29:07 -> 15:29:13). In the listener trace log on the database, we see these requests come in and the connection is established in thousands of a second.

spy(ajp-bio-8014-exec-266)(2017/02/14 15:29:07.989)>> PreparedStatement[183].close()

spy(ajp-bio-8014-exec-266)(2017/02/14 15:29:07.989)>> OK

spy(Thread-17369)(2017/02/14 15:29:13.029)>> Connection[33].getMetaData()

spy(Thread-17369)(2017/02/14 15:29:13.029)>> OK (DatabaseMetaData[258])

spy(Thread-17369)(2017/02/14 15:29:13.029)>> DatabaseMetaData[258].getURL()

spy(Thread-17369)(2017/02/14 15:29:13.030)>> OK (jdbc:macromedia_direct:oracle://plato.hes.hmc.psu.edu:1521;JDBCBEHAVIOR=1;APPLICATIONNAME=;KEYPASSWORD=;ENCRYPTIONTYPES=(AES128,AES192,AES256,DES,3DES112,3DES168,RC4_40,RC4_56,RC4_128,RC4_256);SUPPORTLINKS=false;CATALOGOPTIONS=2;REFCURSORSUPPORT=true;INITIALCOLUMNBUFFERSIZE=-1;BULKLOADBATCHSIZE=1000;ENABLEBULKLOAD=false;CONNECTIONRETRYDELAY=1;CLIENTUSER=;SID=hdcctest.phs.psu.edu;WORKAROUNDS=0;VALIDATESERVERCERTIFICATE=true;CONVERTNULL=1;DATAINTEGRITYLEVEL=Rejected;CONNECTIONRETRYCOUNT=5;ACTION=;TRUSTSTORE=;STRINGPARAMSMUSTMATCHCHARCOLUMNS=true;LOADLIBRARYPATH=;EDITIONNAME=;MAXPOOLEDSTATEMENTS=300;CLIENTID=java.lang.Thread;SENDFLOATPARAMETERSASSTRING=false;CRYPTOPROTOCOLVERSION=;SYSLOGINROLE=;SERVICENAME=;QUERYTIMEOUT=0;DATAINTEGRITYTYPES=(MD5,SHA1);PROGRAMID=;SECURERANDOMALGORITHM=;REGISTERSTATEMENTPOOLMONITORMBEAN=false;MODULE=java.lang.Thread;IMPORTSTATEMENTPOOL=;LOADBALANCING=false;KEYSTOREPASSWORD=;SERVERTYPE=;LOGINTIMEOUT=0;RANDOMGENERATOR=SECURERANDOM;FAILOVERGRANULARITY=nonAtomic;ACCOUNTINGINFO=;REPORTRECYCLEBIN=true;ENCRYPTIONMETHOD=NoEncryption;WIREPROTOCOLMODE=2;FAILOVERMODE=connect;ENABLESERVERRESULTCACHE=false;SDUSIZE=;SUPPORTBINARYXML=false;INITIALIZATIONSTRING=;BATCHPERFORMANCEWORKAROUND=false;SENDSTRINGPARAMETERSASUNICODE=false;JAVADOUBLETOSTRING=false;CODEPAGEOVERRIDE=;AUTHENTICATIONMETHOD=userIDPassword;CLIENTHOSTNAME=;TNSSERVERNAME=;COMMITBEHAVIOR=serverDefault;RESULTSETMETADATAOPTIONS=0;FAILOVERPRECONNECT=false;SPYATTRIBUTES=(log=(file)/opt/coldfusion11/cfusion/logs/db_asthmanet_web3.log; linelimit=80;logTName=yes;timestamp=yes);INSENSITIVERESULTSETBUFFERSIZE=2048;TNSNAMESFILE=;ENABLECANCELTIMEOUT=false;EMBEDDED=true;ENCRYPTIONLEVEL=Rejected;HOSTNAMEINCERTIFICATE=;FETCHTSWTZASTIMESTAMP=false;ALTERNATESERVERS=;LOBPREFETCHSIZE=4000;BULKLOADOPTIONS=0;TRUSTSTOREPASSWORD=;KEYSTORE=)

I've confirmed that our macromedia_drivers.jar file is the same on both servers. If I point the development DSN to the testing database, the results are still fast. If I point the testing DSN to the development database, the results are still slow.

Does anyone have any recommendations? Is there a place that I can look to see what is happening on the CF side in the 5 second lag?

Updated environment info:

Oracle 12c

Coldfusion 11 Enterprise Update 10

Redhat Enterprise Linux 7.3

Apache 2.4.6

Driver: [Macromedia][Oracle JDBC Driver]Driver Version: 5.1.4.000328 (F000281.U000124)

Report · Mar 03, 2017

I've found that adding -Dcoldfusion.disablejsafe=true to the JVM arguments resolved the performance issue. Creating a new database connection now consistently takes 300-400 ms.

Time to create datasource connection

1 Correct answer