Category: Troubleshooting

Awareness Test

I came across this video the other day and I immediately thought of rule #3 from my Got Root Cause? post:

Be detail oriented, but do not become too obsessed with any one detail.

Watch the video and see if you pass the Awareness Test. Most importantly, remember the punch line of the video the next time you are troubleshooting.

ANSI Outer Joins And Lateral Views

A few months ago the Oracle Optimizer Team did a blog post entitled Outerjoins in Oracle. In the Lateral View section of that post they go through some examples and discuss how a query is transformed with the ANSI outer join syntax. I thought it would be useful to go through an example that recently came through the Real-World Performance Group. For simplicity purposes and so that you can play along at home, the test case has been recreated to use EMP and DEPT which have been created and populated via the $ORACLE_HOME/rdbms/admin/utlsampl.sql script.

The Three Test Cases

Consider the following three SQL statements:

Query A: Oracle Outer Join Syntax

SELECT d.dname, d.deptno, e.ename
FROM   dept d, emp e
WHERE  d.deptno = e.deptno(+) and
       d.deptno in (10,40)

Query B: ANSI Outer Join Syntax Version 1

SELECT d.dname, d.deptno, e.ename
FROM   dept d LEFT OUTER JOIN emp e
ON     d.deptno = e.deptno
WHERE  d.deptno in (10,40)

Query C: ANSI Outer Join Syntax Version 2

SELECT d.dname, d.deptno, e.ename
FROM   dept d LEFT OUTER JOIN emp e
ON     d.deptno = e.deptno and
       d.deptno in (10,40)

Do note the slight difference between the two ANSI versions: Query B has the filter predicate in the WHERE clause, where Query C has the filter predicate in the ON clause.

Query Results

Query A

DNAME              DEPTNO ENAME
-------------- ---------- ----------
ACCOUNTING             10 CLARK
ACCOUNTING             10 KING
ACCOUNTING             10 MILLER
OPERATIONS             40

4 rows selected.

Query B

DNAME              DEPTNO ENAME
-------------- ---------- ----------
ACCOUNTING             10 CLARK
ACCOUNTING             10 KING
ACCOUNTING             10 MILLER
OPERATIONS             40

4 rows selected.

Query C

DNAME              DEPTNO ENAME
-------------- ---------- ----------
ACCOUNTING             10 CLARK
ACCOUNTING             10 KING
ACCOUNTING             10 MILLER
RESEARCH               20
SALES                  30
OPERATIONS             40

6 rows selected.

Whoa! Query C returned 6 rows, while Query A and Query B returned 4 rows. Must be a wrong results bug…or is it?

Execution Plans

To start troubleshooting the difference in results sets, lets examine the execution plan of each query.

Query A

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------
Plan hash value: 3713469723

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     9 |   198 |     5  (20)| 00:00:01 |
|*  1 |  HASH JOIN OUTER   |      |     9 |   198 |     5  (20)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL| DEPT |     2 |    26 |     2   (0)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| EMP  |    14 |   126 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("D"."DEPTNO"="E"."DEPTNO"(+))
   2 - filter("D"."DEPTNO"=10 OR "D"."DEPTNO"=40)

Query B

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------
Plan hash value: 3713469723

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     9 |   198 |     5  (20)| 00:00:01 |
|*  1 |  HASH JOIN OUTER   |      |     9 |   198 |     5  (20)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL| DEPT |     2 |    26 |     2   (0)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| EMP  |    14 |   126 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("D"."DEPTNO"="E"."DEPTNO"(+))
   2 - filter("D"."DEPTNO"=10 OR "D"."DEPTNO"=40)

Query C

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
Plan hash value: 498633241

-----------------------------------------------------------------------------
| Id  | Operation            | Name | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |     4 |    80 |    10   (0)| 00:00:01 |
|   1 |  NESTED LOOPS OUTER  |      |     4 |    80 |    10   (0)| 00:00:01 |
|   2 |   TABLE ACCESS FULL  | DEPT |     4 |    52 |     2   (0)| 00:00:01 |
|   3 |   VIEW               |      |     1 |     7 |     2   (0)| 00:00:01 |
|*  4 |    FILTER            |      |       |       |            |          |
|*  5 |     TABLE ACCESS FULL| EMP  |     1 |     9 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter("D"."DEPTNO"=10 OR "D"."DEPTNO"=40)
   5 - filter("D"."DEPTNO"="E"."DEPTNO" AND ("E"."DEPTNO"=10 OR
              "E"."DEPTNO"=40))

For some reason (which we need to investigate!), Query C has a different execution plan. Perhaps this is why the result sets are different.

The 10053 Trace

Perhaps the 10053 trace from Query C can help us understand why the execution plan is different. Looking at the trace file we find that Query C has been transformed (the below has been modified for formatting purposes):

SELECT d.dname, d.deptno, lv.ename
FROM dept d,
LATERAL(
 (SELECT e.deptno, e.ename
  FROM   emp e
  WHERE  d.deptno=e.deptno and
        (d.deptno=10 or d.deptno=40))
)(+) lv

You will notice that the transformation of Query C contains a Lateral View. The Oracle Optimizer Team’s post on Outerjoins in Oracle gives us the definition of a Lateral View:

A lateral view is an inline view that contains correlation referring to other tables that precede it in the FROM clause.

What does this mean? It means that Query C is not the same query as Query B and Query A. Just the slight change of the ANSI syntax causes the meaning of the business question being answered to change! Query C applies the deptno in (10,40) filter to EMP first (returning 3 rows in which deptno=10, there are no deptno=40 rows) and then outer joins that result set to DEPT but does not apply the deptno in (10,40) filter to DEPT, essentially resulting in this query, which is most likely not what the user had intended:

SELECT d.dname, d.deptno, sq.ename
FROM   dept d,
   (SELECT e.deptno, e.ename
    FROM   emp e
    WHERE  e.deptno in (10,40)) sq
WHERE d.deptno=sq.deptno (+)

Summary

Filters specified in the ON clause of outer joins are transformed internally into lateral views and will be applied before the join. While ANSI join syntax is preferred by some, be certain that your query matches the business question being asked!

Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR

Many times a DBA wants to know where a SQL statement is in its execution plan and where the time is being spent. There are a few ways to find out this information, but an 11g new feature makes gathering this information extremely easy. Oracle 11g Real-Time SQL Monitoring allows you to monitor the performance of SQL statements while they are executing as well as see the breakdown of time and resources used for recently completed statements. It is on by default when STATISTICS_LEVEL is set to to ALL or TYPICAL (the default value) and monitors statements that consume more than 5 seconds of CPU or IO time, as well as any parallel execution (PQ, PDML, PDDL). One can override the default actions by using the MONITOR or NO_MONITOR hint. The 11g Documentation has a text version of a SQL Monitor Report but the report output can be html, text or xml.

Real-Time SQL Monitoring Report Walkthrough

To demonstrate the Real-Time SQL Monitoring feature, I started a parallel query and every 60 seconds or so I captured a Real-Time SQL Monitoring report in html format using DBMS_SQLTUNE.REPORT_SQL_MONITOR. Reports 1 through 4 are captures while the query is executing, Report 5 is a post execution capture. Each of the below links will open in a new window.

As you browse through the SQL Monitoring Reports you will see which operation(s) of the execution plan is/are active, how long they have been active, as well as wait events and database time. You can mouse over each of the colored bars to get more detail. As the SQL Monitoring Report notes, this query was executed using a DOP of 8, but there were 16 slaves, 2 sets of 8 which act in a producer/consumer pair. In the SQL Plan Monitoring Details section you can see which operations were performed by each slave set, as well as the QC, by the colors of the Id column. This report also makes it very easy to see that there was some skew in the work for the first slave set. Slaves p003 and p004 performed much more IO than the other slaves and it stands out by the length of the colored bars. The “Active Period” column allows one to see which operations were active, for how long, and at what point of the overall execution. I feel this report gives a great visualization of the execution and a visual breakdown of DB Time and Wait Activity. I’m quite certain I will be using this feature frequently when troubleshooting execution plans and as well as db time drill down.

I’m really excited about Real-Time SQL Monitoring’s ability to capture the Estimated and Actual number of rows for each row source. This eliminates the need to run a query with a GATHER_PLAN_STATISTICS hint as I discussed in my post: Troubleshooting Bad Execution Plans.

More Information

There are a few slides on Real-Time SQL Monitoring in the DBAs’ New Best Friend: Advanced SQL Tuning Features of Oracle Database 11g (starting on page 27) presentation from OOW 2007. As the presentation mentions, Real-Time SQL Monitoring will also be a part of 11g Enterprise Manager Grid Control.

Addendum (2008/02/12)

If you want to get a SQL Monitor report for a statement you just ran in your session (similar to dbms_xplan.display_cursor) then use this command:

set pagesize 0 echo off timing off linesize 1000 trimspool on trim on long 2000000 longchunksize 2000000
select DBMS_SQLTUNE.REPORT_SQL_MONITOR(
   session_id=>sys_context('userenv','sid'),
   report_level=>'ALL') as report
from dual;

Or if you want to generate the EM Active SQL Monitor Report (my recommendation) from any SQL_ID you can use:

set pagesize 0 echo off timing off linesize 1000 trimspool on trim on long 2000000 longchunksize 2000000 feedback off
spool sqlmon_4vbqtp97hwqk8.html
select dbms_sqltune.report_sql_monitor(type=>'EM', sql_id=>'4vbqtp97hwqk8') monitor_report from dual;
spool off

Oracle Myth Busting: Show, Don’t Tell

Richard Foote has recently started blogging (as of December 11th) and one of his recent posts discusses Oracle Myths and Information Pollution. I find this topic very interesting as I’m always amazed at the number of people who make changes to their production database based on the results from their favorite Internet search engine, and don’t even bother to test it themselves first! Like Richard, I’d encourage anyone who gets information from the Internet to do your diligence and understand the why, and not just the results someone else observed. I guess one could associate it to third grade arithmetic, where having the answer (or making a claim) is not sufficient, one must show their work to get full credit. This way even if the answer (or claim) is incorrect, one can understand the line of thought and where the “miscalculation” took place.

I’m also adding Richard Foote to my blogroll.

Bloggers’ Note: In this post I was going to use a reference to masses of lemmings running off a cliff, but then I found out that is a myth also. Amazing what a little research turns up…

Oracle Optimizer Development Team Starts A Blog

Since the introduction of the Cost Based Optimizer (CBO) in Oracle 7.0, people have been both fascinated and terrified by it and the statistics that feed it. There has long been a belief that a degree in witchcraft or black magic is required to successfully work with the CBO. Some people feel this shroud of mystery is caused in part by the lack of documentation or detailed examples about the Optimizer. In order to help remove this shroud and the black magic that surround the Optimizer, the development team responsible for it have started a blog. The blog postings will give in-depth descriptions of the technology behind the CBO, as well as practical advice like best practices for using the Optimizer. Their first blog post, Why are there more cursors in 11g for my query containing bind variables? went up on December 3rd and it discusses the controversial topic of Bind Peeking and how it has been enhanced in 11g. I recommend you check out their blog at http://optimizermagic.blogspot.com.

Troubleshooting Bad Execution Plans

One of the most common performance issues DBAs encounter are bad execution plans. Many try to resolve bad executions plans by setting optimizer related parameters or even hidden underscore parameters. Some even try to decipher a long and complex 10053 trace in hopes to find an answer. While changing parameters or analyzing a 10053 trace might be useful for debugging at some point, I feel there is a much more simple way to start to troubleshoot bad execution plans.

Verify The Query Matches The Business Question

This seems like an obvious thing to do, but I’ve seen numerous cases where the SQL query does not match the business question being asked. Do a quick sanity check verifying things like: join columns, group by, subqueries, etc. The last thing you want to do is consume time trying to debug a bad plan for an improperly written SQL query. Frequently I’ve found that this is the case for many of those “I’ve never got it to run to completion” queries.

What Influences The Execution Plan

I think it’s important to understand what variables influence the Optimizer in order to focus the debugging effort. There are quite a number of variables, but frequently the cause of the problem ones are: (1) non-default optimizer parameters and (2) non-representative object/system statistics. Based on my observations I would say that the most abused Optimizer parameters are:

  • OPTIMIZER_INDEX_CACHING
  • OPTIMIZER_INDEX_COST_ADJ
  • DB_FILE_MULTIBLOCK_READ_COUNT

Many see setting these as a solution to get the Optimizer to choose an index plan over a table scan plan, but this is problematic in several ways:

  1. This is a global change to a local problem
  2. Although it appears to solve one problem, it is unknown how many bad execution plans resulted from this change
  3. The root cause of why the index plan was not chosen is unknown, just that tweaking parameters gave the desired result
  4. Using non-default parameters makes it almost impossible to correctly and effectively troubleshoot the root cause

Object and system statistics can have a large influence on execution plans, but few actually take the time to sanity check them during triage. These statistics exist in views like:

  • ALL_TAB_COL_STATISTICS
  • ALL_PART_COL_STATISTICS
  • ALL_INDEXES
  • SYS.AUX_STATS$

Using GATHER_PLAN_STATISTICS With DBMS_XPLAN.DISPLAY_CURSOR

As a first step of triage, I would suggest executing the query with a GATHER_PLAN_STATISTICS hint followed by a call to DBMS_XPLAN.DISPLAY_CURSOR. The GATHER_PLAN_STATISTICS hint allows for the collection of extra metrics during the execution of the query. Specifically, it shows us the Optimizer’s estimated number of rows (E-Rows) and the actual number of rows (A-Rows) for each row source. If the estimates are vastly different from the actual, one probably needs to investigate why. For example: In the below plan, look at line 8. The Optimizer estimates 5,899 rows and the row source actually returns 5,479,000 rows. If the estimate is off by three orders of magnitude (1000), chances are the plan will be sub-optimal. Do note that with Nested Loop Joins you need to multiply the Starts column by the E-Rows column to get the A-Rows values (see line 10).

select /*+ gather_plan_statistics */ ... from ... ;
select * from table(dbms_xplan.display_cursor(null, null, 'ALLSTATS LAST'));

------------------------------------------------------------------------------------------
|  Id | Operation                              | Name         | Starts | E-Rows | A-Rows |
------------------------------------------------------------------------------------------
|   1 | SORT GROUP BY                          |              |     1  |      1 | 1      |
|*  2 |  FILTER                                |              |     1  |        | 1728K  |
|   3 |   NESTED LOOPS                         |              |     1  |      1 | 1728K  |
|*  4 |    HASH JOIN                           |              |     1  |      1 | 1728K  |
|   5 |     PARTITION LIST SINGLE              |              |     1  |   6844 | 3029   |
|*  6 |      INDEX RANGE SCAN                  | PROV_IX13    |     1  |   6844 | 3029   |
|   7 |     PARTITION LIST SINGLE              |              |     1  |   5899 | 5479K  |
|*  8 |      TABLE ACCESS BY LOCAL INDEX ROWID | SERVICE      |     1  |   5899 | 5479K  |
|*  9 |       INDEX SKIP SCAN                  | SERVICE_IX8  |     1  |   4934 | 5479K  |
|  10 |    PARTITION LIST SINGLE               |              |  1728K |      1 | 1728K  |
|* 11 |     INDEX RANGE SCAN                   | CLAIM_IX7    |  1728K |      1 | 1728K  |
------------------------------------------------------------------------------------------

Using The CARDINALITY Hint

Now that I’ve demonstrated how to compare the cardinality estimates to the actual number of rows, what are the debugging options? If one asserts that the Optimizer will choose the optimal plan if it can accurately estimate the number of rows, one can test using the not so well (un)documented CARDINALITY hint. The CARDINALITY hint tells the Optimizer how many rows are coming out of a row source. The hint is generally used like such:

select /*+ cardinality(a 100) */ * from dual a;

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   100 |   200 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS FULL| DUAL |   100 |   200 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

In this case I told the Optimizer that DUAL would return 100 rows (when in reality it returns 1 row) as seen in the Rows column from the autotrace output. The CARDINALITY hint is one tool one can use to give the Optimizer accurate information. I usually find this the best way to triage a bad plan as it is not a global change, it only effects a single execution of a statement in my session. If luck has it that using a CARDINALITY hint yields an optimal plan, one can move on to debugging where the cardinality is being miscalculated. Generally the bad cardinality is the result of non-representative table/column stats, but it also may be due to data correlation or other factors. This is where it pays off to know and understand the size and shape of the data. If the Optimizer still chooses a bad plan even with the correct cardinality estimates, it’s time to place a call to Oracle Support as more in-depth debugging is likely required.

Where Cardinality Can Go Wrong

There are several common scenarios that can lead to inaccurate cardinality estimates. Some of those on the list are:

  1. Data skew: Is the NDV inaccurate due to data skew and a poor dbms_stats sample?
  2. Data correlation: Are two or more predicates related to each other?
  3. Out-of-range values: Is the predicate within the range of known values?
  4. Use of functions in predicates: Is the 5% cardinality guess for functions accurate?
  5. Stats gathering strategies: Is your stats gathering strategy yielding representative stats?

Some possible solutions to these issues are:

  1. Data skew: Choose a sample size that yields accurate NDV. Use DBMS_STATS.AUTO_SAMPLE_SIZE in 11g.
  2. Data correlation: Use Extended Stats in 11g. If <= 10.2.0.3 use a CARDINALITY hint if possible.
  3. Out-of-range values: Gather or manually set the statistics.
  4. Use of functions in predicates: Use a CARDINALITY hint where possible.
  5. Stats gathering strategies: Use AUTO_SAMPLE_SIZE. Adjust only where necessary. Be mindful of tables with skewed data.

How To Best Work With Oracle Support

If you are unable to get to the root cause on your own, it is likely that you will be in contact with Oracle Support. To best assist the support analyst I would recommend you gather the following in addition to the query text:

  1. Output from the GATHER_PLAN_STATISTICS and DBMS_XPLAN.DISPLAY_CURSOR
  2. SQLTXPLAN output. See Metalink Note 215187.1
  3. 10053 trace output. See Metalink Note 225598.1
  4. DDL for all objects used (and dependencies) in the query. This is best gotten as a expdp (data pump) using CONTENT=METADATA_ONLY. This will also include the object statistics.
  5. Output from: select pname, pval1 from sys.aux_stats$ where sname='SYSSTATS_MAIN';
  6. A copy of your init.ora

Having this data ready before you even make the call (or create the SR on-line) should give you a jump on getting a quick(er) resolution.

Summary

While this blog post is not meant to be a comprehensive troubleshooting guide for bad execution plans, I do hope that it does help point you in the right direction the next time you encounter one. Many of the Optimizer issues I’ve seen are due to incorrect cardinality estimates, quite often due to inaccurate NDV or the result of data correlation. I believe that if you use a systematic approach you will find that debugging bad execution plans may be as easy as just getting the cardinality estimate correct.

Ideas For Oracle Performance Topics

From time to time I get a little writer’s block and sometime search for topics to blog about. I thought, what better way to get ideas for blog posts than to ask the readers of this blog. Here is your chance to influence the topic of upcoming blog posts. I just have a few requests to keep things orderly:

  • Topics should in the context of the Oracle database and performance there of.
  • It’s not meant to be a Q & A, but rather the subject of a blog post.
  • Try to say as much as necessary, with the least amount of words.
  • It’s not meant to be a alternative to Oracle Support or Ask Tom.
  • Keep in mind it’s for a blog post, not a white paper or dissertation.
  • You get the gist…

Just a heads up: comments are moderated so don’t be surprised if they don’t show up immediately. Thanks much for taking the time to post your ideas/comments!

How to Display HIGH_VALUE/LOW_VALUE Columns from USER_TAB_COL_STATISTICS

Here is some code to display the HIGH_VALUE/LOW_VALUE columns from USER_TAB_COL_STATISTICS which are stored as RAW datatypes.

https://github.com/grahn/oracle_scripts/blob/master/display_raw.sql

COLUMN_NAME          LOW_VAL          HIGH_VAL         DATA_TYPE
-------------------- ---------------- ---------------- ---------
ORGANIZATION_ID      00D000000000062  00D300000000tgk  CHAR
UG_ID                00500000000008U  00GD0000000mBda  CHAR
USERS_ID             005000000000063  00G30000000mBcq  CHAR
IS_TRANSITIVE        0                1                CHAR
SUPPRESS_RULES       0                1                CHAR

Oracle OpenWorld 2007: The Real-World Performance Group (2)

Andrew Holdsworth, the Senior Director of the Real-World Performance Group, will be having two presentation sessions at Oracle OpenWorld 2007, in addition to the Real-World Performance Group Roundtable session. The first presentation is Current Trends in Database Performance and the second one is When to Use the Appropriate Database Technology. Full session details are below. The content of these presentations has come from the Real-World Performance Group’s customer interactions over the past year. I would encourage all of you who want to get the best performance out of your Oracle Database to consider attending. Hope to see you there!

Session Details

Session ID: S291304
Session Title: When to Use the Appropriate Database Technology
Session Abstract: This session reinforces good database design practices. With so many database features available in Oracle Database 10g and 11g, architects and programmers are faced with these questions: How do I implement something, and which technologies should I use? This session defines when to use various occasionally overlapping and complementary technologies to achieve a reliable, high-performing design.
   
Session ID: S291301
Session Title: Current Trends in Database Performance
Session Abstract: This session attempts to visit the hot performance topics of the day, which include the following: (1) system design (architecture to SQL), (2) benchmarking today (TPC versus real-world benchmarking), and (3) capacity planning (so where do you spend your money?).

Upscaling Your Database Application Performance: Cursor Management

In my previous post, Bind Variables, I discussed why using bind variables is one of the most important fundamentals in engineering scalable database applications. I briefly touch on the point that cursor management is also very important. In this post I will go into why this is important, demonstrating by example.

As a precursor to this post, you may want to read the section “Analyzing Cursor Operations” in Designing Applications For Performance And Scalability.

The Performance Issue
A Java application is making a database call which consists of an anonymous block of PL/SQL containing insert statements. The text of this PL/SQL block looks like such:

DECLARE
BEGIN
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO)
    VALUES (:1, :2, :3, :4, SYSDATE, :5, :6, :7);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO)
    VALUES (:8, :9, :10, :11, SYSDATE, :12, :13, :14);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO)
    VALUES (:15, :16, :17, :18, SYSDATE, :19, :20, :21);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:22, :23, :24);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:25, :26, :27);
END;

As the application executes this insert block again and again, the execution time increases until the point that the application server is timing out the database connection.

Debugging Analysis
The same anonymous PL/SQL block was run with bind variables in SQL*Plus and it did not display any increase in CPU or elapsed time after the same number of calls.

SQL Trace File
Below is part of a SQL trace file from the Java application session.


=====================
PARSING IN CURSOR #2 len=512 dep=0 uid=45 oct=47 lid=45 tim=261783946058 hv=283572372 ad='24e8718c'
DECLARE
BEGIN
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:1, :2, :3, :4, SYSDATE, :5, :6, :7);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:8, :9, :10, :11, SYSDATE, :12, :13, :14);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:15, :16, :17, :18, SYSDATE, :19, :20, :21);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:22, :23, :24);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:25, :26, :27);
END;
END OF STMT
PARSE #2:c=0,e=853,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=261783946053
=====================
PARSING IN CURSOR #5 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783949786 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #5:c=0,e=171,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=261783949780
EXEC #5:c=0,e=911,p=2,cr=4,cu=23,mis=1,r=1,dep=1,og=1,tim=261783950888
=====================
PARSING IN CURSOR #6 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783951074 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #6:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783951070
EXEC #6:c=0,e=77,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783951266
=====================
PARSING IN CURSOR #7 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783951338 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #7:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783951334
EXEC #7:c=0,e=37,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783951475
=====================
PARSING IN CURSOR #8 len=60 dep=1 uid=45 oct=2 lid=45 tim=261783951671 hv=2406633223 ad='24fbe7c4'
INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:B1, :B2, :B3)
END OF STMT
PARSE #8:c=0,e=145,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=261783951667
EXEC #8:c=0,e=7255,p=2,cr=4,cu=22,mis=1,r=1,dep=1,og=1,tim=261783959040
=====================
PARSING IN CURSOR #9 len=60 dep=1 uid=45 oct=2 lid=45 tim=261783959234 hv=2406633223 ad='24fbe7c4'
INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:B1, :B2, :B3)
END OF STMT
PARSE #9:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783959229
EXEC #9:c=0,e=60,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783959405
EXEC #2:c=0,e=13165,p=4,cr=11,cu=54,mis=1,r=1,dep=0,og=1,tim=261783959474
=====================
PARSING IN CURSOR #10 len=512 dep=0 uid=45 oct=47 lid=45 tim=261783961860 hv=283572372 ad='24e8718c'
DECLARE
BEGIN
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:1, :2, :3, :4, SYSDATE, :5, :6, :7);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:8, :9, :10, :11, SYSDATE, :12, :13, :14);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:15, :16, :17, :18, SYSDATE, :19, :20, :21);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:22, :23, :24);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:25, :26, :27);
END;
END OF STMT
PARSE #10:c=0,e=142,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=261783961853
=====================
PARSING IN CURSOR #11 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783962232 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #11:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783962228
EXEC #11:c=0,e=111,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783962450
=====================
PARSING IN CURSOR #12 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783962542 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #12:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783962538
EXEC #12:c=0,e=44,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783962689
=====================
PARSING IN CURSOR #13 len=121 dep=1 uid=45 oct=2 lid=45 tim=261783962755 hv=1783440776 ad='2a669628'
INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:B1, :B2, :B3, :B4, SYSDATE, :B5, :B6, :B7)
END OF STMT
PARSE #13:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783962751
EXEC #13:c=0,e=36,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783962891
=====================
PARSING IN CURSOR #14 len=60 dep=1 uid=45 oct=2 lid=45 tim=261783962958 hv=2406633223 ad='24fbe7c4'
INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:B1, :B2, :B3)
END OF STMT
PARSE #14:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783962954
EXEC #14:c=0,e=36,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783963092
=====================
PARSING IN CURSOR #15 len=60 dep=1 uid=45 oct=2 lid=45 tim=261783963158 hv=2406633223 ad='24fbe7c4'
INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:B1, :B2, :B3)
END OF STMT
PARSE #15:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=261783963154
EXEC #15:c=0,e=36,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=261783963293
EXEC #10:c=0,e=1231,p=0,cr=5,cu=15,mis=0,r=1,dep=0,og=1,tim=261783963346
=====================
PARSING IN CURSOR #16 len=512 dep=0 uid=45 oct=47 lid=45 tim=261783970060 hv=283572372 ad='24e8718c'
DECLARE
BEGIN
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:1, :2, :3, :4, SYSDATE, :5, :6, :7);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:8, :9, :10, :11, SYSDATE, :12, :13, :14);
  INSERT INTO EMP (EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO) VALUES (:15, :16, :17, :18, SYSDATE, :19, :20, :21);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:22, :23, :24);
  INSERT INTO DEPT (DEPTNO, DNAME, LOC) VALUES (:25, :26, :27);
END;
END OF STMT
PARSE #16:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=261783970054
=====================

The Java code that executes this PL/SQL looks something like:

public void execPLSQL(Connection conn) throws SQLException {
   PreparedStatement ps;
   ps = conn.prepareStatement(plsqlText);
   bindData(ps);
   ps.execute();
}

For those of you who are not familiar with Java/JDBC this function:

  • instantiates a new cursor
  • binds the values to the cursor
  • executes the cursor

Root Cause Analysis
If you look a the SQL trace file you will notice that the cursor numbers keep increasing in value even though the exact same SQL is executed again and again. This is because the Java code block opens a new cursor each time it is called. The open cursors keep accumulating until the connection is closed. This is commonly referred to as a cursor leak. The Closing the ResultSet and Statement Objects section of the Oracle JDBC Developer’s Guide and Reference states:

If you do not explicitly close the ResultSet and Statement objects, serious memory leaks could occur. You could also run out of cursors in the database.

Solution
The cursor leak can be resolved by explicitly closing the PreparedStatement object. While this resolves the immediate problem, in my opinion there are bigger issues. Even with the explicit close, the execPLSQL routine is inefficient because it opens, binds, executes, then closes the cursor each time it is called (and this function is called many times). The insert statements were put into an anonymous PL/SQL block as result of an enhancement request to move the code from using literal values to using bind values. By wrapping the insert statements in the anonymous PL/SQL block it does reduce the number of round trips to the database. While the intention was good, the implementation can be better. In fact, JDBC has this functionality built into it. The Oracle JDBC Developer’s Guide and Reference contains an entire section on update batching. As an added benefit, using batching will leverage the array interface as well.

Summary
As demonstrated by example, poor cursor management can lead to serious performance issues with both the application and database. Java database developers need to understand if they open a Statement or ResultSet, they should explicitly close it as well. At any time one can query to find out how many open cursors each session has with this query:

select a.value, s.username, s.sid, s.serial#
from v$sesstat a, v$statname b, v$session s
where a.statistic# = b.statistic#  and s.sid=a.sid and
b.name = 'opened cursors current';