Oracle Performance and Engineering

I was trying to build a simple, SQL*Plus based test case for cost of parsing (i.e., recursive calls coming back with each different literals). And I had some surprising finds on 9i - yet to explain it or say it's a 'bug' - but here goes the test.

Test Bed -

create table t (a number,
b number,
c number,
d number,
e number,
f varchar2(200),
g date);

declare
j pls_integer;
begin
for i in 1..1000000 loop
j := dbms_random.random;
insert into t values (j,j+1, j-1, j+7, j/2,'this is a row which will be tested...', sysdate);
end loop;
commit;
end;
/


create index i1 on t(b);

create index i2 on t(g);

analyze table t compute statistics for table
for all indexes
for all columns;


Now on 10g --

SQL> select * from t where b = 233221323 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (TABLE) (Cost=1 Card=
1 Bytes=79)

2 1 INDEX (RANGE SCAN) OF 'I1' (INDEX) (Cost=3 Card=1)




Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
3 consistent gets
1 physical reads
0 redo size
535 bytes sent via SQL*Net to client
373 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

on 9i --

SQL> select * from t where b = 2332213523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.62

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (Cost=2 Card=1 Bytes=
79)

2 1 INDEX (RANGE SCAN) OF 'I1' (NON-UNIQUE) (Cost=1 Card=1)




Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
2 physical reads
0 redo size
511 bytes sent via SQL*Net to client
368 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed


Both were immediate first execution of a SQL after the index creation!!

Is it a SQL*Plus issue or Oracle version issue. Hmm.. Setting up the "sql_trace = true" on both beds and changing the literal --

on 10g --
--------
SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.04
SQL> select * from t where b = 2332523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.01

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (TABLE) (Cost=1 Card=
1 Bytes=79)

2 1 INDEX (RANGE SCAN) OF 'I1' (INDEX) (Cost=3 Card=1)




Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
3 consistent gets
0 physical reads
0 redo size
535 bytes sent via SQL*Net to client
373 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

on 9i
-----

SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.04
SQL> select * from t where b = 2332523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.63

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (Cost=2 Card=1 Bytes=
79)

2 1 INDEX (RANGE SCAN) OF 'I1' (NON-UNIQUE) (Cost=1 Card=1)




Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
2 physical reads
0 redo size
511 bytes sent via SQL*Net to client
368 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

Note -- still shows 'recursive calls = 0"!

Let's look at the trace files -


for 10g --

select *
from
t where b = 2332523 and g > (sysdate - 1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 0

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID T (cr=3 pr=0 pw=0 time=55 us)
0 INDEX RANGE SCAN I1 (cr=3 pr=0 pw=0 time=48 us)(object id 394056)


for 9i --

select *
from
t where b = 2332523 and g > (sysdate - 1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 2 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 2 3 0 0

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 24

Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID T
0 INDEX RANGE SCAN I1 (object id 95644)

Plus, on 9i trace file we actually see a recursive call which is missing on 10g file --

select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
o.dataobj#,o.flags
from
obj$ o where o.obj#=:1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Overall for 10g --

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 1 3 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 3 3

Overall for 9i --

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 1 5 3
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 4 5 4


So, in spite of 9i actually doing more recursive calls than 10g -- 'autotrace' shows 9i doing less (actually none!).

I'm a little lost on why 9i autotrace shows '0 recursive calls' at this moment!!

I got some emails on why I named a particular method "Blind Tuning".

It's because the options to 'try out' were very limited. I received the query in email and a bunch of statistics - I had no access to customer data, database and thus was restricted to just 'methods'. Then I tried the 'if I were optimizer how I would approach the problem' method, found out the disparity with the explain plan I was sent - and suggested a cure.

However, I finally finished my paper and presentation. While making the last two slides on the importance of bulking up in PL/SQL - I wrote a small test case. Putting it up here. The results were gotten on a 9.2.0.5 database on Itanium Linux.

create table t (x number, y date);

Declare
begin
for I in 1 .. 100000
Loop
Insert into t values (i, sysdate);
End loop;
End;
/
-- t has 100K records

create table t1 as select * from t where 1 = 2;
-- t1 has 10K records.

-- X is indexed on both tables.

-- Business need is to update T set t.x = t1.x where there exists a record t.y = t1.y

-- LOOP method / Old iteration

Declare
begin
for c1_rec in (select x,y from t1)
Loop
update t set y = c1_rec.y where x = c1_rec.x;
End loop;
End;
/

1.94 secs

--using BULK COLLECT and FORALL

Declare
type i_num is table of number;
type i_date is table of date;
-- declare PL/SQL "collections"

p_num1 i_num;
p_num2 i_date;
-- initialize PL/SQL collections to hold CURSOR

begin

select x, y
BULK COLLECT into p_num1, p_num2
from t1 ;
--BULK BIND

forall indx in p_num1.FIRST .. p_num1.LAST
update t set y = p_num2(indx) where x = p_num1(indx);
-- BULK DML

End;
/

0.70 sec.

i.e., BULKING up saves about 64% time!

What if we try to do this non-procedurally through a single SQL ;)
Say,

update t set t.y = (select t1.y from t1
where t1.x = t.x)
where exists (select '' from t1 where t.x = t1.x);

2.83 sec

How to tune this up? ;)

Happy St. Patrick's Day people!

A bit busy to prepare a presentation on a site's "legacy performance issues" for the Managers and developers. A very first frill free draft can be read here.

This is supposed to be an one-hour long very high level overview of the mistakes (performance perspectives) the developers have been doing time and again. After solving hundreds of pieces of code and performance issues, I figured out that things are coming to a full circle. Same mistakes are being committed in the later branches - which I've already went and fixed in the earlier.

Thus had a long talk with managers and figured it would make perfect sense to pick a few "critical" and "recurring" issues and update the guys who actually can take ownership of this while developing.

Will keep writing on this more. Remember, though this is a very site-specific thing, in my eight years - most of these issues (and many more) always revisit me!!

Is there any other job in the world where people just ignore you where you can really help with your knowledge and experience (design phase), but looks up with cute puss in boots type eyes to you to 'save the day' when those designs don't work and an irate customer is threatening to walk out??

Well - if you're the 'performance evangelist' -- that's an integral part of the job. It's fun too. Because once you actually make the application 'Die another day' - you're a hero. People actually don't want to ask "What are you working on these days" during lunch. But they are wide-eared even if you're talking about some silly, stupid ideas. You, only you probably, secretly sigh thinking how *easy* it could have been to prevent the issue at the first place. As Einstein said, "Intelligent people solve problems, Geniuses prevent them (from happening)". But then when was someone declared a hero for doing things as expected?

However, I had a hard call today with one of the "big five's" consultant DBA frantically asking for help after getting thrashed by the customer.

The issue :

(winnowed down from several emails) -

The on-site consultant sent me the following SQL with the plan output and the execution statistics. Apparently, "they found another query that is costing too much I/O for them that they are claiming" and " forgot to mentione the problem: This is another sql statement that is using a large amount of sort space and is currently executing. It is over 2 GB right now. I have included the explain and execution plans with statistics for one project id."


SELECT top_proj.project_id as project_id,
kpw.period_id as period_id,
round(sum(kpc.actual_labor_cost* ACCN_EV_ANALYSIS_UTILS.GET_TASK_RATIO(kpw.period_id,kp.project_id)),2) as actual_labor_cost
from ACCN_project_costs kpc,
ACCN_projects kp,
ACCN_projects top_proj,
ACCN_periods kpw
where top_proj.project_id = :b1
and kpc.project_id = kp.project_id
and kp.project_path_id_list like top_proj.project_path_id_list||'%'
and kp.project_type_code = 'TASK'
and kpw.period_type_id = 3
and kpw.period_id in (select period_id
from ACCN_cost_metrics_by_period where project_id = :b1)
group by kpw.period_id, top_proj.project_id

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 468 | 44460 | 5074 |
| 1 | SORT GROUP BY | | 468 | 44460 | 5074 |
| 2 | HASH JOIN | | 77743 | 7212K| 4429 |
| 3 | VIEW | index$_join$_004 | 784 | 6272 | 9 |
| 4 | HASH JOIN | | 77743 | 7212K| 4429 |
| 5 | INDEX RANGE SCAN | ACCN_PERIODS_N2 | 784 | 6272 | 3 |
| 6 | INDEX FAST FULL SCAN | ACCN_PERIODS_U1 | 784 | 6272 | 3 |
| 7 | MERGE JOIN | | 77743 | 6605K| 4418 |
| 8 | SORT JOIN | | 2961K| 141M| 3254 |
| 9 | MERGE JOIN CARTESIAN | | 2961K| 141M| 3254 |
| 10 | NESTED LOOPS | | 26 | 1040 | 4 |
| 11 | TABLE ACCESS BY INDEX ROWID| ACCN_PROJECTS | 1 | 31 | 2 |
| 12 | INDEX UNIQUE SCAN | ACCN_PROJECTS_U1 | 121K| | 1 |
| 13 | SORT UNIQUE | | | | |
| 14 | INDEX RANGE SCAN | ACCN_COST_METRICS_BY_PERIOD_U2 | 26 | 234 | 2 |
| 15 | BUFFER SORT | | 115K| 1129K| 3252 |
| 16 | TABLE ACCESS FULL | ACCN_PROJECT_COSTS | 115K| 1129K| 125 |
| 17 | FILTER | | | | |
| 18 | SORT JOIN | | | | |
| 19 | TABLE ACCESS FULL | ACCN_PROJECTS | 60725 | 2194K| 737 |
-----------------------------------------------------------------------------------------------------


Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=5074 Card=468 Bytes=44460)
1 0 SORT (GROUP BY) (Cost=5074 Card=468 Bytes=44460)
2 1 HASH JOIN (Cost=4429 Card=77743 Bytes=7385585)
3 2 VIEW OF 'index$_join$_004' (Cost=9 Card=784 Bytes=6272)
4 3 HASH JOIN (Cost=4429 Card=77743 Bytes=7385585)
5 4 INDEX (RANGE SCAN) OF 'ACCN_PERIODS_N2' (NON-UNIQUE) (Cost=3 Card=784 Bytes=6272)
6 4 INDEX (FAST FULL SCAN) OF 'ACCN_PERIODS_U1' (UNIQUE) (Cost=3 Card=784 Bytes=6272)
7 2 MERGE JOIN (Cost=4418 Card=77743 Bytes=6763641)
8 7 SORT (JOIN) (Cost=3254 Card=2961366 Bytes=148068300)
9 8 MERGE JOIN (CARTESIAN) (Cost=3254 Card=2961366 Bytes=148068300)
10 9 NESTED LOOPS (Cost=4 Card=26 Bytes=1040)
11 10 TABLE ACCESS (BY INDEX ROWID) OF 'ACCN_PROJECTS' (Cost=2 Card=1 Bytes=31)
12 11 INDEX (UNIQUE SCAN) OF 'ACCN_PROJECTS_U1' (UNIQUE) (Cost=1 Card=121450)
13 10 SORT (UNIQUE)
14 13 INDEX (RANGE SCAN) OF 'ACCN_COST_METRICS_BY_PERIOD_U2' (UNIQUE) (Cost=2 Card=26 Bytes=234)
15 9 BUFFER (SORT) (Cost=3252 Card=115656 Bytes=1156560)
16 15 TABLE ACCESS (FULL) OF 'ACCN_PROJECT_COSTS' (Cost=125 Card=115656 Bytes=1156560)
17 7 FILTER
18 17 SORT (JOIN)
19 18 TABLE ACCESS (FULL) OF 'ACCN_PROJECTS' (Cost=737 Card=60725 Bytes=2246825)


Statistics
----------------------------------------------------------
2245 recursive calls
43 db block gets
12336 consistent gets
47510 physical reads
0 redo size
1886 bytes sent via SQL*Net to client
688 bytes received via SQL*Net from client
5 SQL*Net roundtrips to/from client
17 sorts (memory)
1 sorts (disk)
54 rows processed

Analysis -

Looking at the plan and statistics, the 'bad' keyphrases in this case are -

(1) 47510 physical reads (almost 4 times the 'Consistent Gets' or Logical I/O)
(2) 2 1 HASH JOIN (Cost=4429 Card=77743 Bytes=7385585)
(3) 9 8 MERGE JOIN (CARTESIAN) (Cost=3254 Card=2961366 Bytes=148068300)

One cartesian join (i.e., no join condition found between the two data source) producing 148MB of data and one HASH join on this data will certainly use a lot of "sorting" area as they've noted.

Solution / Logical Analysis -

Let's get our critical thinking rolling. I did not have access to this particular database. So firstly,
I tried to see if there's actually a table that's not joined with other tables - i.e., candidate for MERGE JOIN (CARTESIAN).

The query contains four tables and if you compare the joins you'll find that the table ACCN_PERIODS is not directly joined with other three tables -- though ACCN_PERIODS is supposed to be 'qualified' (joined well) since the IN-clause returns 'just a few rows' (got that information from the consultant).

(Probably?) They tried to print a report for some project for *each* period.

The other tables are, in fact, very well joined. In fact, ACCN_PROJECTS (TOP_PROJ) is supplied a value for its primary key - which then should join well with the other ACCN_PROJECTS (KP). KP and KPC join with PROJECT_ID which is primary key on KP and an index on KPC.

So - this is how I think these issues - * if I were the optimizer * -- I would do

(1) find row from TOP_PROJ (PRIMARY KEY Access by INDEX ROWID)

(2) join the row with KP (*probably* Nested LOOP - since the #rows from 1 is 1)

(3) assuming a few rows from KP returned, NESTED LOOP with KPC (a primary key - index join)

(4) find out the qualified rows from KPW by comparing it with the IN-list

(5) just a few rows from the datasource returned by #3 - doing a CARTESIAN JOIN (CROSS JOIN X * Y) with datasource returned by #4

Thus, CARTESIAN join is unavoidable -- but in the 'if I were optimizer' method - we make sure cartesian join takes place between two smallest data source possible. Only after all other filters and predicates have been applied to them.

What's wrong in reality -

Well, look at the plan. The optimizer somehow does confuse. Probably the IN-list is 'merged' with the main query block. So now, the query has Five tables to deal with. So the real plan by optimizer is like -

(1) TOP_PROJ access -- INDEX UNIQUE SCAN since it's a primary key

(2) ACCN_cost_metrics_by_period access - based on project_id

(3) Optimizer sees both tables TOP_PROJ and ACCN_COST_ using PROJECT_ID = :b1 join -- so it ends up joining those two instead.

(So, does it do the same only during a CARTESIAN join? I believe not. Optimizer tries to put as many joins as possible all the time)

(4) Dataset returned by #3 (26 rows) is then CARTESIAN joined with KPC (115K rows)

CARD of step 8 (7) should then be 115656 * 26 = 3007056. In reality, it's 2961366.

There goes the last hope for our query!

(5) Dataset returned by #4 is then joined with KP. But it's a MERGE JOIN - since the number of records returned by #4 is too high.

..and so on..

Fix -

So if we can convince Oracle to follow our path as mentioned in solution - it would not join TOP_PROJ and ACCN_cost_metrics_by_period using PROJECT_ID (this exactly screws up the plan!).

So I rewrote the query and added the ORDERED hint so that TOP_PROJ is earlier joined with other tables and ACCN_COST_...table is used only to join KPW.

The modified query looked like -

SELECT /*+ ORDERED */ top_proj.project_id as project_id,
kpw.period_id as period_id,
round(sum(kpc.actual_labor_cost* ACCN_EV_ANALYSIS_UTILS.GET_TASK_RATIO(kpw.period_id,kp.project_id)),2) as actual_labor_cost
from ACCN_projects top_proj,
ACCN_projects kp,
ACCN_project_costs kpc,
ACCN_periods kpw
-- note the ORDER
where top_proj.project_id = :b1
and kpc.project_id = kp.project_id
and kp.project_path_id_list like top_proj.project_path_id_list||'%'
and kp.project_type_code = 'TASK'
and kpw.period_type_id = 3
and kpw.period_id in (select period_id
from ACCN_cost_metrics_by_period where project_id = :b1)
group by kpw.period_id, top_proj.project_id;

The plan then looked like -

# Operation Options Object name
======== ================ ============== ==============================
0 SELECT STATEMENT
1 SORT GROUP BY
2 NESTED LOOPS
3 MERGE JOIN CARTESIAN
4 NESTED LOOPS
5 NESTED LOOPS
6 TABLE ACCESS BY INDEX ROWID KDRV_PROJECTS
7 INDEX UNIQUE SCAN KDRV_PROJECTS_U1
8 SORT UNIQUE
9 INDEX RANGE SCAN KDRV_COST_METRICS_BY_PERIOD_U2
10 TABLE ACCESS BY INDEX ROWID KNTA_PERIODS
11 INDEX UNIQUE SCAN KNTA_PERIODS_U1
12 BUFFER SORT
13 TABLE ACCESS FULL KDRV_PROJECT_COSTS
14 TABLE ACCESS BY INDEX ROWID KDRV_PROJECTS
15 INDEX UNIQUE SCAN KDRV_PROJECTS_U1

Look, the way the joins are "as intended" now. The query doesn't use any more MERGE or HASH joins - and executed well under 1 sec with less than 4000 Consistent Gets.

In future, I intend to discuss this optimizer "unnesting" part more with some more real life examples. Remind me :)

Dynamic SQL is a query which is not known fully when you're writing the code. In other words, it will be fully known only at runtime. In the words of Secretary of Defense Donald Rumsfeld, this could be termed "known unknowns". We use it in many cases where

There are two ways Dynamic SQL can be written -

(a) Using the "DBMS_SQL" API
(b) Using the keywords "EXECUTE IMMEDIATE" (Oracle calls this 'Native Dynamic SQL')

While using DBMS_SQL package, you need to OPEN a cursor assigned for that 'dynamic' SQL, bind it if you can, execute it and close the cursor when you're done.

In many of these cases, you'll also iterate through multiple values that will be fed to the Dyanamic SQL (possibly). I've seen many cases where the programmer just 'integrates' all the DBMS_SQL syntax within the loop. Thus, even though one single DBMS_SQL.OPEN_CURSOR call would suffice, since called within LOOP - one separate cursor is opened for each iteration of the loop.

The result?

(a) Much worse performance (demonstrated below)
(b) Your program could actually die throwing out "ORA-1000 : Max Open Cursors Exceeded" error if the number of iterations is near the value of "open_cursors" and other sessions are active too!

A testcase -

The more generic code I see most of the time -

create table t(x number, y date, z varchar2(255));

create or replace procedure p1
as
l_cursor int;
l_status int;
begin
for i in 1 .. 10000
loop
l_cursor := dbms_sql.open_cursor;
dbms_sql.parse( l_cursor,
'insert into t (x,y,z)
values (:x,:y,:z)',
dbms_sql.native );
dbms_sql.bind_variable( l_cursor, ':x', i );
dbms_sql.bind_variable( l_cursor, ':y', sysdate+i );
dbms_sql.bind_variable( l_cursor, ':z',
'this is row ' || i, 255 );
l_status := dbms_sql.execute( l_cursor );
dbms_sql.close_cursor(l_cursor);
end loop;
end;
/


Notice, the open_cursor, parse and close_cursor calls have been made *within* the Loop. Thereby executing them 9999 extra times for a 10,000 row insert. They could easily be placed outside the loop. The tuned code then looks like -

create or replace procedure p2
as
l_cursor int default dbms_sql.open_cursor;
l_status int;
begin
dbms_sql.parse( l_cursor,
'insert into t (x,y,z)
values (:x,:y,:z)',
dbms_sql.native );

for i in 1 .. 10000
loop
dbms_sql.bind_variable( l_cursor, ':x', i );
dbms_sql.bind_variable( l_cursor, ':y', sysdate+i );
dbms_sql.bind_variable( l_cursor, ':z',
'this is row ' || i, 255 );
l_status := dbms_sql.execute( l_cursor );
end loop;

dbms_sql.close_cursor(l_cursor);
end;
/


I've used two different sets of runs. First to insert 100 rows and second, to insert 10,000 rows. I've also set plsql_optimize_level to 0 (so that Oracle does not try to tune the PL/SQL code at all!).

Here's the result - the time is obtained by "set timing on" on SQL*Plus.

P1 - (open-parse-close calls within the LOOP)

Run 1 - 0.64 second
Run 2 - 0.20 second

P2 - (open-parse-close calls only ONCE outside the LOOP)

Run 1 - 5.88 second
Run 2 - 1.99 second

However, for a quick but effective comparison between two Database side code, I like to use runstats.

Using that the difference found between two approaches can be spread out over more stuff (like, latching!) -

Difference between P1 and P2 for run2 (inserting 10,000 records) --

Run1 ran in 3775 hsecs
Run2 ran in 2544 hsecs
run 1 ran in 148.39% of the time

Name Run1 Run2 Diff
STAT...Elapsed Time 3,778 2,546 -1,232
LATCH.active checkpoint queue 5,305 611 -4,694
LATCH.redo writing 5,417 695 -4,722
STAT...undo change vector size 739,464 733,440 -6,024
LATCH.messages 10,893 1,424 -9,469
STAT...session cursor cache hi 10,032 26 -10,006
STAT...parse count (total) 10,064 52 -10,012
STAT...opened cursors cumulati 10,065 49 -10,016
STAT...consistent gets 10,345 292 -10,053
STAT...consistent gets from ca 10,345 292 -10,053
STAT...session logical reads 21,754 11,581 -10,173
LATCH.checkpoint queue latch 21,952 2,856 -19,096
STAT...redo size 2,881,572 2,861,076 -20,496
STAT...recursive calls 70,941 40,639 -30,302
LATCH.cache buffers chains 88,471 57,053 -31,418
LATCH.object queue header oper 44,356 2,234 -42,122
LATCH.session allocation 49,204 536 -48,668
LATCH.library cache lock 103,449 139 -103,310
LATCH.shared pool 144,004 40,463 -103,541
LATCH.row cache objects 129,869 752 -129,117
LATCH.library cache pin 243,979 80,460 -163,519
LATCH.library cache 317,594 80,644 -236,950

Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
1,169,318 270,530 -898,788 432.23%

Look at the differences between P1 and P2 -- not only P2 runs much faster, but since P2 does 1 Parse call as opposed to 10,000 done by P1 -- the difference in latch resources is ENORMOUS.

That's (high latching) the real cost of re-parsing.

If we trace the runs for both P1 and P2 here's what we get --

For p1 --

insert into t (x,y,z)
values (:x,:y,:z)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10000 0.29 0.30 0 0 0 0
Execute 10000 1.00 0.90 0 10037 10503 10000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20000 1.29 1.20 0 10037 10503 10000

* Notice the 9999 extra PARSE calls for P1


For p2 --

insert into t (x,y,z)
values (:x,:y,:z)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 10000 0.63 0.55 0 48 10520 10000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10001 0.64 0.55 0 48 10520 10000

Though I don't like to put things under "Best practices" document - there're always exceptions, but this can probably be a good candidate to implement there.

The statement in there would look something like -

"If you are LOOPing over a dynamic SQL and are using DBMS_SQL for that -- keep the OPEN_CURSOR, PARSE and CLOSE_CURSOR out of the LOOP."

Got an issue yesterday, described as follows -

"A customer is recovering from a DB crash .. after restoring the data they see the following error -
java.io.IOException: ORA-01578: ORACLE data block corrupted (file # 6, block # 184017)
ORA-26040: Data block was loaded using the NOLOGGING option
ORA-01110: data file 6: '/u02/oradata/knta00/knta_data01.dbf'

Problem Analysis -

A quick "oerr ora 26040" printed -

26040, 00000, "Data block was loaded using the NOLOGGING option\n"
//* Cause: Trying to access data in block that was loaded without
//* redo generation using the NOLOGGING/UNRECOVERABLE option
//* Action: Drop the object containing the block.

As evident, some objects (table / index / lob) was in NOLOGGING mode, and thus, was not generating REDO log. So after the recovery - when everything else was recovered, Oracle did not have any data to roll forward / recover the
particular object.

We thus needed to know the following to solve -
(a) WHICH object(s)?
(b) Is it better to drop/ recreate or there's any other way to bypass?

A quick thinking - since Oracle points out some block and data file id - it's most definitely an index or a LOB. Since if it were a table, Oracle would probably print out the table name rather than bothering to print the subset of data blocks.

Diagnosis :

SQL> select table_name, column_name, logging from user_lobs order by logging

UPGRADE_LOGS MESSAGE NO

DEFAULT_HELP_CONTENTS HELP_CONTENTS NO

HELP_CONTENTS HELP_CONTENTS NO

As you can see there are two important tables with this DEFAULT_HELP_CONTENTS and HELP_CONTENTS. In my instance, none of the columns are set to NO logging. Is it OK to turn on logging for these columns? Eg.

alter table HELP_CONTENTS modify lob (HELP_CONTENTS) (nocache logging);
alter table DEFAULT_HELP_CONTENTS modify lob (HELP_CONTENTS) (nocache logging);"

I was emailed by support before they communicate the issue to the customer. Of course, updating them to LOGGING makes sense. I also added two possible ways they can resolve this issue quickly -

Solution - Method ONE - The "process" method

Query to find out the corrupt ROWIDs -

-- Identifying the LOB table

select owner, segment_name, segment_type  from   dba_extents
where  file_id = 6
and    148017 between block_id and block_id + blocks - 1;

-- Identify the LOB_COLUMN_NAME

select table_name, column_name
from   dba_lobs
where  segment_name = 'SYS_LOB029815C006$$'
-- segment_name returned from above query

-- Identify the corrupt ROWIDs
create table corrupt_data (corrupt_rowid rowid);

declare
error_1578 exception;
pragma exception_init(error_1578,-1578);
n number;
begin
 for cursor_lob in (select rowid r, &&lob_column from &table_owner.&table_with_lob) loop
   begin
     n:=dbms_lob.instr(cursor_lob.&&lob_column,hextoraw('8899')) ;
   exception
   when error_1578 then
      insert into corrupt_data values (cursor_lob.r);
   end;
 end loop;
end;
/   

-- Finally set the particular ROWIDs to EMPTY_BLOB() (or EMPTY_CLOB() if it were a CLOB) --

update &table_owner.&table_with_lob
    set &lob_column = empty_blob()
    where rowid in (select corrupt_rowid from corrupt_data);

Solution - Method TWO - The "out of the box" method

A quick glance through the table names indicate they could hold static data. Quickly querying the test database
confirmed it. So, I told the customer he can just drop the aforementioned tables and import them back from the
test / dev instance of him. As it turned out, this was less technical and since the tables contained 16 and 0 records
respectively was much faster to recover.

P.S.
I believe the mentioned column were modified to NOLOGGING assuming it would speed up the install process
(the client was running a third party software). But is NOLOGGING worth it?  We will discuss it soon. But let me say
this for now - NOLOGGING was actually called UNRECOVERABLE till some releases back.