SUN JES 8.1 Q2UR2: Long time taken in getting database connection.
Application server registered intermittent slowness in getting database connection from javax.sql.DataSource. Based on the following JMX value, the application servers still haven抰 reached the threshold. Its identified the slowness was due to application server performing validation (select count(*) from dual).
Sample code:
ds.getConnection(username, password); // where DS is the javax.sql.DataSource
Network
It is observed that the bi-directional ping stats showed that the response time < 1.19 ms. Network Switch port utilisation was <30% and there were no errors and collision detected.
Database
Based on oracle database statspack, it showed that the database is healthy. On top of that, the following query was scheduled to be executed every second to monitor Select count(*) from dual elapsed time.
select sess.sid, sess.serial#, sess.client_info, sess.program, sql.sql_text, sql.elapsed_time from V$SESSION sess, V$SQL sql where sess.sql_hash_value=sql.hash_value and upper(sql.sql_text) like 'SELECT COUNT(*) FROM DUAL' order by sess.sid
Basically this query will capture the cumulative elapsed time per session id. This query is able to caption 揝elect count(*) from dual?that ran more than 2 seconds.
Example 1 ?how the cumulative elapsed time registered in the log:
2006_11_02_16_53_55,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 10 ms.
2006_11_02_16_53_55,Connection 2, SID 2 perform a select count(*) from dual. Oracle registered elapsed time 10 ms.
2006_11_02_16_54_57,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 20 ms.
2006_11_02_16_54_58,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 30 ms.
2006_11_02_16_54_58,Connection 2, SID 2 perform a select count(*) from dual. Oracle registered elapsed time 20 ms.
Example 2 ?If query ran more than 2 sec:
2006_11_02_16_53_55,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 10 ms.
2006_11_02_16_53_57,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 20 ms.
2006_11_02_16_54_57,Connection 1, SID 1 perform a select count(*) from dual. Oracle registered elapsed time 2030 ms. << if query that ran more than 2 secs, there will be a sudden jump of 2 secs in the subsequent cumulative elapsed time.
Previously based on jmx log, it do registered 10k connections was acquired in 1 second and only 6 active connections was used. If same connection was used and on the same second, the cumulative elapsed time will registered in the log. The longest elapsed time that registered in 2 Nov 2006 01:00 pm to 05:00 pm logs was 800 ms but long get database connection still registered 5 to 7 seconds.
Questions:
1) Is it possible that I can use dtrace to capture the bottleneck?
System information:
Oracle:
DriverVersion: [10.2.0.1.0]
DriverMajorVersion: [10]
DriverMinorVersion: [2]
DriverName: [Oracle JDBC driver]
URL: [jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS_LIST= (ADDRESS=(PROTOCOL = TCP) (HOST = XXXXXX) (PORT = 1524)) (ADDRESS=(PROTOCOL = TCP) (HOST = XXXXXX) (PORT = 1524))) (CONNECT_DATA = (SID = CP_P)) (source_route=yes))]
UserName: [CP_P1]
Database Product Name: [Oracle]
Database Product Version: [Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production]
Database Product Major: [9]
Database Product Minor: [2]
Drivers: Type 4
JDK
JDBC Major: [10]
JDBC Minor: [2]
The JDK version is 1.5.0_02
SUN JES Application Server
Sun Java System Application Server Enterprise Edition 8.1_02 running under solaris 10
