Sunday, January 18, 2009

An experience of tunning a SQL with EXISTS and NOT EXISTS subqueries

Our team was requested to run a SQL on Saturday aternoon. The time window was from 4PM to midnight. Since from midnight a maintenance job was scheduled and the database won't be available, we promised to deliver the results by midnight. However, the DBA responsible for carring out the task had no idea how long this SQl would take. So he would do a dry run on Friday afternoon. I was called to help him.

The SQL has the following structure (actual table names, column name were modified of course):


SELECT *
FROM a,
bi,
bm
WHERE bm.bsc = 3
AND bm.bsci = 'S'
AND a.bid = bi.bid
AND a.bid = bm.vp_bid
AND
NOT EXISTS (
SELECT 1
FROM bm bm1
WHERE bm.vp_bid = bm1.vp_bid
AND bm1.bsci = 'S'
AND bm1.bsc NOT IN (3, 4));
union
SELECT *
FROM a,
bi,
bm
WHERE bm.bsc = 3
AND bm.bsci = 'S'
AND a.bid = bi.bid
AND a.bid = bm.vp_bid
AND
EXISTS (
SELECT 1
FROM bm bm1
WHERE bm.vp_bid = bm1.vp_bid
AND bm1.bsci = 'S'
AND bm1.bsc NOT IN (3, 4));



The DBA initially tried to do a dry run using hint parallel 5 for all the three tables. He said using parallel hint he got smaller cost value from the explain plan. I told him if he used parallel 10, he would get even smaller cost value, but this did not mean the SQL would run faster. I told him just start the SQL without any hint and see how long it would take.

The number of rows of the table involved are as follows:



TABLE_NAME NUM_ROWS LAST_ANALYZED
----------------- ---------- -------------------
BM 309688610 2009-01-03 07:22:04
A 15837920 2009-01-03 10:54:31
BI 15840300 2009-01-03 11:08:33


Our databae is Oracle 9.2.0.8.



It turned out the SQL did not finish after 5.5 hours running. The execution plan looked like:


 
------------------------------------------------------------------------
|Id | Operation | Name | Rows| Bytes |Temp |
Spc |Cost |
------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 11M|
| 1 | SORT UNIQUE | | 110M| 9017M| 19G| 11M|
| 2 | UNION-ALL | | | | | |
| 3 | FILTER | | | | | |
| 4 | HASH JOIN | |1124K| 79M| 61M| 334K|
| 5 | HASH JOIN | |1124K| 48M| 38M| 305K|
| 6 | TABLE ACCESS FULL | BM |1124K| 25M| | 271K|
| 7 | TABLE ACCESS FULL | A | 15M| 319M| |24889|
| 8 | TABLE ACCESS FULL | BI | 15M| 440M| |17719|
| 9 | TABLE ACCESS BY INDEX ROWID| BM | 5 | 60 | | 8 |
|10 | INDEX RANGE SCAN | BM_FK5| 13 | | | 4 |
|11 | HASH JOIN | | 108M| 8937M|1844M| 703K|
|12 | HASH JOIN | | 22M| 1587M| 772M| 359K|
|13 | TABLE ACCESS FULL | BM | 22M| 514M| | 71K|
|14 | HASH JOIN | | 15M| 759M| 501M|60525|
|15 | TABLE ACCESS FULL | A | 15M| 319M| |24889|
|16 | TABLE ACCESS FULL | BI | 15M| 440M| |17719|
|17 | TABLE ACCESS FULL | BM | 115M| 1323M| | 271K|
------------------------------------------------------------------------



We were worried about this SQL, our manager set up a call with developers at about 7PM. I learned from them that we can use inion all instead of union since there are no possible dulpicate rows from the two parts. Finally we agreed with runing the two parts of the SQL separatly and load the results to two separate temp table. And DBA team only need diliver these two temp talbe to the devlopers.

I took over the task. I started a new test and using the nested loop hint for the first part:

 

SELECT /*+ use_nl(bm, a) use_nl(a, bi) */
*
FROM a,
bi,
bm
WHERE bm.bsc = 3
AND bm.bsci = 'S'
AND a.bid = bi.bid
AND a.bid = bm.vp_bid
AND
NOT EXISTS (
SELECT 1
FROM bm bm1
WHERE bm.vp_bid = bm1.vp_bid
AND bm1.bsci = 'S'
AND bm1.bsc NOT IN (3, 4));


The execution plan for this part is as follows:




------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 14M|
| 1 | FILTER | | | | |
| 2 | TABLE ACCESS BY INDEX ROWID | BI | 1 | 29 | 3 |
| 3 | NESTED LOOPS | | 1106K| 78M| 5797K|
| 4 | NESTED LOOPS | | 1106K| 47M| 2479K|
| 5 | TABLE ACCESS FULL | BM | 1106K| 25M| 267K|
| 6 | TABLE ACCESS BY INDEX ROWID| A | 1 | 21 | 2 |
| 7 | INDEX UNIQUE SCAN | A_PK | 1 | | 1 |
| 8 | INDEX RANGE SCAN | BI_PK | 1 | | 2 |
| 9 | TABLE ACCESS BY INDEX ROWID | BM | 5 | 60 | 8 |
| 10 | INDEX RANGE SCAN | BM_FK5| 13 | | 4 |
------------------------------------------------------------------------


I used parallel hint for the second part:




 
SELECT /*+ parallel (bm, 4) */
*
FROM a,
bi,
bm
WHERE bm.bsc = 3
AND bm.bsci = 'S'
AND a.bid = bi.bid
AND a.bid = bm.vp_bid
AND
EXISTS (
SELECT 1
FROM bm bm1
WHERE bm.vp_bid = bm1.vp_bid
AND bm1.bsci = 'S'
AND bm1.bsc NOT IN (3, 4));



And the execution plan looks like:




----------------------------------------------------------------------------
Id | Operation | Name|Rows|Bytes|Temp|Cost | TQ |IN-OUT|PQ
|Spc | | | |Distrib
----------------------------------------------------------------------------
0 | SELECT STATEMENT | | | | | 404K| | |
1 | HASH JOIN | | 22M|1814M|154M| 404K|98,00| P->S |QC(RAND)
2 | TABLE ACCESS FULL | BI | 15M| 438M| |17565|98,00| S->P | HASH
3 | HASH JOIN | | 22M|1202M|124M| 378K|98,00| PCWP |
4 | TABLE ACCESS FULL | A | 15M| 317M| |24624|98,00| S->P | HASH
5 | HASH JOIN SEMI | | 22M| 759M|189M| 348K|98,00| PCWP |
6 | TABLE ACCESS FULL| BM | 22M| 506M| |66931|98,00| P->P | HASH
7 | TABLE ACCESS FULL| BM |113M|1301M| | 267K|98,00| S->P | HASH
----------------------------------------------------------------------------


Good news was the first part finished in 3 hours, and the second part took 2 h 40 min. On Saturday afternoon, I did the real run and it took a little longer but finished in 4 hours.

At this point, I am not sure I chose the best way to accomplish this task. I just ensured that we deliverd as we promised. I don't know if it could be better if we just adopt the approach of using parallel hint 5 for all the three tables. It was too late for DBA to having sufficient time to find the best way to execute this SQL.

I will re-visit this SQL if I have time. Acutally I already invest some time to understand anti-join this evening - the first part of this SQL is acutally anti-join, but I have not seen Oracle choose anti-join access path in the current execution plan.

Wednesday, January 14, 2009

Obtain bind variable values in a SQL

I searched the internet and learned that sql trace can be used to obtain actual bind variable values in a SQL. The value will appear in the raw trace file, not available in the formatted reprot by TKPROF. I don't always remember the meaning of trace levels, usually just do 10046 with level 12 - highest level.

In 10 g, there is a view called v$sql_bind_capture that can be used for this purpose. See a post here.

Below is a test about using sql trace to find the bind varialbe values.

Once execute the followoing code, I check the trace file:




drop table t1;
create table t1 (v1 varchar2(20), n1 number);

alter session set events '10046 trace name context forever, level 12';

variable b1 varchar2(5);
variable b2 number;

exec :b1 := 'abc5'; :b2 := 123;
insert into t1 values (:b1, :b2);
commit;

exec :b1 := 'efg'; :b2 := 456;
insert into t1 values (:b1, :b2);
commit;

alter session set events '10046 trace name context off';

exit;


Here are the results




******** Observiation in the trace 10.2.0.1:

Only can find the following related to that sql statment. Note the bind variable values for the
first time execution are not shown in the trace file:


=====================
PARSING IN CURSOR #7 len=32 dep=0 uid=62 oct=2 lid=62 tim=98152339039 hv=1961723033 ad='69629204'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #7:c=0,e=434,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=98152339027

=====================
PARSING IN CURSOR #3 len=32 dep=0 uid=62 oct=2 lid=62 tim=98152761378 hv=1961723033 ad='69629204'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #3:c=0,e=164,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=98152761367
BINDS #3:
kkscoacd
Bind#0
oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=178 siz=56 off=0
kxsbbbfp=07c125b4 bln=32 avl=03 flg=05
value="efg"
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
kxsbbbfp=07c125d4 bln=22 avl=03 flg=01
value=456
EXEC #3:c=0,e=841,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=98152762535
WAIT #3: nam='SQL*Net message to client' ela= 7 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=98152762774
WAIT #3: nam='SQL*Net message from client' ela= 375 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=98152763291


********************************************************************************

TKPROF

insert into t1
values
(:b1, :b2)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.12 0.11 0 2 26 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.12 0.11 0 2 26 2

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 62

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.00 0.00








******** Observiation in the trace 9.2.0.8: we can see values for the two executions

=====================
PARSING IN CURSOR #1 len=32 dep=0 uid=178 oct=2 lid=178 tim=10450665631029 hv=340431440 ad='b8241108'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #1:c=0,e=2540,p=0,cr=5,cu=0,mis=1,r=0,dep=0,og=0,tim=10450665631025
BINDS #1:
bind 0: dty=1 mxl=32(05) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=56 offset=0
bfp=ffffffff7c95fb70 bln=32 avl=04 flg=05
value="abc5"
bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=32
bfp=ffffffff7c95fb90 bln=22 avl=03 flg=01
value=123
EXEC #1:c=0,e=1043,p=0,cr=1,cu=20,mis=0,r=1,dep=0,og=4,tim=10450665632203
WAIT #1: nam='SQL*Net message to client' ela= 9 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 145321 p1=1413697536 p2=1 p3=0

=====================
PARSING IN CURSOR #1 len=32 dep=0 uid=178 oct=2 lid=178 tim=10450667390749 hv=340431440 ad='b8241108'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #1:c=0,e=156,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=10450667390743
BINDS #1:
bind 0: dty=1 mxl=32(05) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=56 offset=0
bfp=ffffffff7c95fb60 bln=32 avl=03 flg=05
value="efg"
bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=32
bfp=ffffffff7c95fb80 bln=22 avl=03 flg=01
value=456
EXEC #1:c=0,e=554,p=0,cr=1,cu=4,mis=0,r=1,dep=0,og=4,tim=10450667391444
WAIT #1: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 144598 p1=1413697536 p2=1 p3=0

Reference: Dealing with hang situation

When I opened a SR with Oracle about a slow performance problem due to blocking sessions, the support guy gave me an action plan about how to deal with hanging sql. It makes no sense to implement this action plan since problem has already gone. So I blog these commands here for furture reference. Hopefully when needed I can quickly find these commands.


ACTION PLAN
============
When the SQL appears to be hanging, Please generate system state and hanganalyze (should do hanganlyze first?):

$ sqlplus /nolog
connect / as sysdba
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 266
wait 90 seconds
oradebug dump systemstate 266
wait 90 seconds
oradebug dump systemstate 266

In another session, generate hanganalyze:

1-Using SQL*Plus connect as "/ AS SYSDBA"
2- Execute: oradebug hanganalyze 3
3- Wait 1 minute....
4- Execute: oradebug hanganalyze 3


Feb 5, 2010 Updated:

Kyle Hailey mentioned: 

If you have such an instance hang you can use a preliminary connection (which starts the process and attaches to SGA, but doesn't initialize SGA structs nor allocate any state objects):

sqlplus -prelim "/as sysdba"
oradebug dump latches 1
oradebug dump hanganalyze 4

Anup Nanda described a real case hung scenario here.

Related MOS notes:

1. Interpreting HANGANALYZE trace files to diagnose hanging and performance problems [ID 215858.1]
2. Steps to generate HANGANALYZE trace files [ID 175006.1]
3. Systemstate dump when connection to the instance is not possible [ID 359536.1]

Saturday, January 10, 2009

Recursive SQL statement: update seq$

Last Friday, one of our production database experienced slowness in about 1 hours time period. During that period of time, there were 60+ blocking sessions. One of the blocking session was issuing the following statment:


update seq$ set
increment$=:2,minvalue=:3,maxvalue=:4,cycle#=
:5,order$=:6,cache=:7,highwater=:8,audit$=:9,
flags=:10 where obj#=:1

 

This looks like having somthing to do with the sequences. Our team leader suggested that we should increase the cache size for two relevant sequences to proactively avoid the problem. I acutally opened a SR with Oracle, asking what this statment is doing. But they did not give direct answer to this specific question so far. On the other hand, the guy suggested we should increase the log file size to reduce "log file sync" wait event, which appears at the top of the wait event in our statspack report. His suggestions is obviously nonsense. He must have no idea about what "log file sync" wait event is. I am disappointed with the support.

To understand this update statment, I did a test today. I created a table T and a sequence T_SEQ:



labadmin@DB10G> desc t;
Name Null? Type
------------------------- -------- ------------------------------------
ID NUMBER
VALUE VARCHAR2(20)

labadmin@DB10G> select * from user_sequences;

SEQUENCE_NAME MIN_VALUE MAX_VALUE INCREMENT_BY C O CACHE_SIZE LAST_NUMBER
--------------------- ---------- ---------- ------------ - - ---------- -----------
T_SEQ 1 1.0000E+27 1 N N 20 904821



 

Then I have 20 sessions repeatedly executing the following insert statment simutaneouly:

isnert into t values(t_seq.nextval, 'xxxx');

I can observe there is one blocking sessions from time to time, for example:


Lock Time Held
SID Lock Type Requested Lock Held (minutes) Block
------ --------- --------- --------- --------- -----
126 SQ None Exclusive 0 Yes
99 SQ Exclusive None 0 No
124 SQ Exclusive None 0 No
123 SQ Exclusive None 0 No
128 SQ Exclusive None 0 No
158 SQ Exclusive None 0 No
109 SQ Exclusive None 0 No
159 SQ Exclusive None 0 No
130 SQ Exclusive None 0 No
114 SQ Exclusive None 0 No
131 SQ Exclusive None 0 No
....k



I traced one of the 20 sessions, found that:



update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,
cache=:7,highwater=:8,audit$=:9,flags=:10
where
obj#=:1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 561 0.03 0.05 0 0 0 0
Execute 561 2.04 8.81 0 561 1132 561
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1122 2.07 8.87 0 561 1132 561

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

Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE SEQ$ (cr=1 pr=0 pw=0 time=339 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=40 us)(object id 102)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: undo global data 2 0.00 0.00
latch: library cache 1 0.01 0.01
log buffer space 8 1.00 6.39
latch: library cache pin 2 0.10 0.10
********************************************************************************

INSERT INTO T
VALUES
(T_SEQ.NEXTVAL, :B1 )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 9026 8.51 351.24 0 211 21192 9026
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9026 8.51 351.24 0 211 21192 9026

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 102 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: SQ - contention 775 3.07 258.38
latch: enqueue hash chains 6 0.03 0.06
log buffer space 38 1.36 21.72
latch: library cache pin 3 0.01 0.01
latch free 12 0.40 1.52
free buffer waits 1717 0.08 25.67
latch: library cache 10 0.15 0.62
latch: In memory undo latch 8 1.27 2.56
latch: redo copy 6 0.33 0.41
buffer busy waits 19 0.98 4.37
latch: undo global data 4 0.07 0.09
enq: FB - contention 2 0.82 0.98
enq: TX - contention 2 0.22 0.22
enq: HW - contention 2 0.45 0.45
latch: session allocation 1 0.00 0.00
********************************************************************************



 

So it can be seen that the "update seq$ ..." statement is a recursive sql issued by Oracle sys user to update dictionary table about sequence.

I did a further test:

I set the cache of t_seq to be 20, and I trace the session when executing following statement:

insert into t
select t_seq.nextval, 'qqq' from all_objects where rownum <=100;

I found the 'update seq$' statment executed 5 times.

Then I set the cache of t_seq to be 50, I found the 'update seq$' executed 2 time.

Thus, it looks like that every time that the cached sequence number is used up, Oracle should do the caching again and issue this statment to update dictionary table.

Thursday, January 08, 2009

Hierachical SQL used to combine multiple rows

A user asked a question about how to combine rows that have same key value into one rows on the Boobooke Oracle forum.
For example, for the table:

SQL> select * from t;

KEY VALUE
---------- --------------------
1 a
1 b
1 c

How to write a sql to give the output looks like:

KEY VALUE
--- -----
1 a/b/c

He actually gave the answer. Based on his input, I did a test. First I created the following table:



SQL> create table uavsub (num_prod number,
2 summary number,
3 cod_dep varchar2(20)
4 );

Table created.

SQ>
SQL> insert into uavsub values (3, 3, 'a');

1 row created.

SQL> insert into uavsub values (2, 9, 'b');

1 row created.

SQL> insert into uavsub values (1, 1, 'a');

1 row created.

SQL> insert into uavsub values (1, 3, 'a');

1 row created.

SQL> insert into uavsub values (3, 4, 'a');

1 row created.

SQL> insert into uavsub values (2, 1, 'a');

1 row created.

SQL> insert into uavsub values (3, 1, 'a');

1 row created.

SQL> insert into uavsub values (3, 2, 'a');

1 row created.

SQL> insert into uavsub values (1, 2, 'b');

1 row created.

SQL> insert into uavsub values (3, 3, 'a');

1 row created.

SQL> commit;

Commit complete.

SQ>
SQL> col summary format 999
SQL> select * from uavsub;

NUM_PROD SUMMARY COD_DEP
-------- ------- ---------
3 3 a
2 9 b
1 1 a
1 3 a
3 4 a
2 1 a
3 1 a
3 2 a
1 2 b
3 3 a

10 rows selected.



Then I executed the following sql, which only gave ouput for the case of num_prod=3:



SQL>
SQL> select t.num_prod num_prod,
2 max(substr(sys_connect_by_path(t.summary, '/'), 2)) summary
3 from (
4 select num_prod,
5 summary,
6 row_number() over (partition by num_prod order by summary ) rn
7 from uavsub
8 where num_prod=3
9 and cod_dep is not null
10 ) t
11 start with rn = 1
12 connect by rn = prior rn + 1
13 and num_prod = prior num_prod
14 group by t.num_prod;

NUM_PROD SUMMARY
-------- ------
3 1/2/3/3/4



The below sql lift the constraint: num_prod=3



SQL>
SQL>
SQL> col summary format a20
SQL>
SQL> select t.num_prod num_prod,
2 max(substr(sys_connect_by_path(t.summary, '/'), 2)) summary
3 from (
4 select num_prod,
5 summary,
6 row_number() over (partition by num_prod order by summary ) rn
7 from uavsub
8 where cod_dep is not null
9 ) t
10 start with rn = 1
11 connect by rn = prior rn + 1
12 and num_prod = prior num_prod
13 group by t.num_prod;


NUM_PROD SUMMARY
-------- --------------------
1 1/2/3
2 1/9
3 1/2/3/3/4



  

However, I did not fully understand the "connect by" sql at that time. I don't know if this is the best way to solve the problem, but this did urge me to understand hierarchical sql better. So I did a few more tests as follows:

For brevity, I create a view first

SQL> create view t_vw as
2 select key, value, row_number() over (partition by key order by value) rn from t;

View created.

SQL> select * from t_vw;

KEY VALUE RN
---------- --------- ----------
1 a 1
1 b 2
1 c 3

Then, I tested the meaning of sys_connect_by_path,

SQL>;
1 select key, value, sys_connect_by_path(value, '/') path from t_vw
2 start with rn = 1
3* connect by rn = prior rn + 1

SQL>

KEY VALUE PATH
---------- -------------------- ----------
1 a /a
1 b /a/b
1 c /a/b/c

Then:

SQL> ;
1 select key, max(sys_connect_by_path(value, '/')) path from t_vw
2 start with rn = 1
3 connect by rn = prior rn + 1
4* group by key
SQL> /

KEY PATH
---------- ------------------------------
1 /a/b/c


Finally,

1 select key, substr(max(sys_connect_by_path(value, '/')),2) path from t_vw
2 start with rn = 1
3 connect by rn = prior rn + 1
4* group by key
SQL> /

KEY PATH
---------- ------------------------------
1 a/b/c