Buggy overhead of SQL Plan Baseline Capture
March 1, 2011 4 Comments
There’s at least one bug related to the performance overhead of SQL Baseline Capture and ASH is less than clear with recursive SQL
First up – apologies, I’ve not got a reproducible test case because I flushed the shared pool between tests and the whole performance degradation scenario disappeared. I should have known when one of the Metalink notes talked about the problem disappearing when bouncing the instance that I shouldn’t have touched the shared pool. Now I can’t reproduce. I’m going to keep trying, but for now, let me tell you what I’ve got (I am trying to be more precise in my blogging but yet again it’s something woolly or nothing).
With that out the way, we’re in the initial stages of an upgrade from 9.2.0.8 on 32-bit Solaris to 11.2.0.2 on 64-bit Linux, a one-step all-or-nothing change-everything at once upgrade.
Plan was to run with optimizer_features_enable set to 9.2.0, various other parameters set to current production settings and to capture 9i plans into a baseline.
Initial runs of “The Batch” started, all processes reported as slow. The initial major contributor turns out to be recursive SQL related to SQL Plan Baseline Capture (see bug#11600319, also bug #11719151 and doc id 1295054.1 – thanks to Timur Akhmadeev for the pointers)
I haven’t yet raised this with Oracle Support because a) I can’t face the wait for a response and b) local red tape means that patches need to be approved by the DB Engineering team and approval for non-production environments is difficult (I’m not going there, not now).
Bug # 11719151 – “RECURSIVE MERGE WHEN optimizer_capture_sql_plan_baseline=true DOING FTS” – is certainly relevant.
The MERGE statement into SQLOBJ$AUXDATA does use a FULL TABLE SCAN. But if I were to show you the AWR reports then you’d see the MERGE statement into SQLOBJ$DATA was the bigger problem and the MERGE statement into SQLOBJ$ also not insignificant.
Pick a metric, any metric:
3 out of the top 10 by Elapsed Time, 2 out of the top 5, 1 of the top 1.
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
6,481.5 242,111 0.03 43.2 22.6 56.1 1vxm21mhmgy07
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE
2,403.4 242,108 0.01 16.0 95.4 3.9 44z7snw61qx9x
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,
898.7 242,111 0.00 6.0 98.6 .1 7xm5j53mxbtpn
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,
By CPU Time:
CPU CPU per Elapsed
Time (s) Executions Exec (s) %Total Time (s) %CPU %IO SQL Id
---------- ------------ ---------- ------ ---------- ------ ------ -------------
2,292.8 242,108 0.01 39.9 2,403.4 95.4 3.9 44z7snw61qx9x
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,
1,464.0 242,111 0.01 25.5 6,481.5 22.6 56.1 1vxm21mhmgy07
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE
885.7 242,111 0.00 15.4 898.7 98.6 .1 7xm5j53mxbtpn
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,
By Gets:
Buffer Gets Elapsed
Gets Executions per Exec %Total Time (s) %CPU %IO SQL Id
----------- ----------- ------------ ------ ---------- ------ ------ -----------
49,599,141 242,108 204.9 46.9 2,403.4 95.4 3.9 44z7snw61qx
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,
29,107,449 242,111 120.2 27.5 6,481.5 22.6 56.1 1vxm21mhmgy
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE
16,671,818 242,111 68.9 15.7 898.7 98.6 .1 7xm5j53mxbt
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,
By executions:
Executions Rows Processed Rows per Exec Time (s) %CPU %IO SQL Id
------------ --------------- -------------- ---------- ------ ------ -----------
242,111 242,111 1.0 6,481.5 22.6 56.1 1vxm21mhmgy
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE
242,111 242,111 1.0 898.7 98.6 .1 7xm5j53mxbt
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,
242,111 242,074 1.0 34.6 95.7 .2 9zr2sbbp1d4
SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category
FROM sqlobj$ WHERE name = :1 AND obj_type = :2
242,108 242,108 1.0 2,403.4 95.4 3.9 44z7snw61qx
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,
So, you get the message.
Furthermore, at the top of every Segment Statistic by X Metric, it’s either one of the LOBs or the LOB Index related to these three tables.
By the way, what’s in these SQLOBJ$ tables – no surprises it’s the baseline data.
See also:
Kerry Osborne – Do SQL Baselines Use Hints/
Christian Antognini – SQL Profiles in the Data Dictionary
Christian Antognini – Troubleshooting Oracle Performance
If I move over to the ASH data and give an example of what that was showing, then we can go and look at those SQLOBJ$ tables for the SQL concerned.
The ASH data – probably my most favorite feature of the last few years – I’m only displaying a little bit of in terms of height and width. But it illustrates the second point I wanted to highlight – that recursive SQL is not properly reported. Whilst the SQL_ID column differs from the TOP_LEVEL_SQL_ID (which I’ve omitted to keep it slim), this is still the SQL Id of a nested lookup, not the SQL Id of the recursive MERGE which you might have expected – I can see pros and cons of both I suppose.
1 select to_char(sample_time,'HH24:MI:SS') sample_time, session_id, sql_id 2 , sql_plan_operation, event 3 from v$active_session_history 4 where session_id = 1388 5 and session_serial# = 147 6 and sample_id between 14596749 and 14596800 7* order by sample_id SQL> / SAMPLE_T SESSION_ID SQL_ID SQL_PLAN_OPERATION EVENT -------- ---------- ------------- ------------------------------ ----------------------------------- 10:57:04 1388 d99anrdgbb4jf SELECT STATEMENT 10:57:05 1388 log file sync 10:57:06 1388 d99anrdgbb4jf 10:57:07 1388 d99anrdgbb4jf MERGE direct path write 10:57:08 1388 d99anrdgbb4jf MERGE flashback log file sync 10:57:09 1388 d99anrdgbb4jf direct path read 10:57:10 1388 d99anrdgbb4jf MERGE buffer busy waits 10:57:11 1388 d99anrdgbb4jf SELECT STATEMENT latch: shared pool 10:57:12 1388 d99anrdgbb4jf MERGE direct path read 10:57:13 1388 d99anrdgbb4jf TABLE ACCESS 10:57:14 1388 d99anrdgbb4jf INDEX 10:57:15 1388 d99anrdgbb4jf MERGE direct path write 10:57:16 1388 d99anrdgbb4jf TABLE ACCESS 10:57:17 1388 d99anrdgbb4jf TABLE ACCESS 10:57:18 1388 d99anrdgbb4jf direct path read 10:57:19 1388 d99anrdgbb4jf TABLE ACCESS 10:57:20 1388 d99anrdgbb4jf MERGE 10:57:21 1388 log file sync 10:57:22 1388 log file sync 10:57:23 1388 d99anrdgbb4jf MERGE direct path write 10:57:24 1388 d99anrdgbb4jf MERGE direct path write 10:57:25 1388 d99anrdgbb4jf TABLE ACCESS 10:57:26 1388 d99anrdgbb4jf direct path read 10:57:27 1388 d99anrdgbb4jf direct path read 10:57:28 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:29 1388 d99anrdgbb4jf MERGE 10:57:30 1388 log file sync 10:57:31 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:32 1388 d99anrdgbb4jf MERGE 10:57:33 1388 d99anrdgbb4jf INDEX 10:57:34 1388 d99anrdgbb4jf MERGE buffer busy waits 10:57:35 1388 d99anrdgbb4jf MERGE buffer busy waits 10:57:36 1388 d99anrdgbb4jf MERGE flashback log file sync 10:57:37 1388 d99anrdgbb4jf MERGE direct path write 10:57:38 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:39 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:40 1388 d99anrdgbb4jf MERGE buffer busy waits 10:57:41 1388 d99anrdgbb4jf MERGE enq: TX - index contention 10:57:42 1388 d99anrdgbb4jf MERGE buffer busy waits 10:57:43 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:44 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:45 1388 log file sync 10:57:46 1388 d99anrdgbb4jf TABLE ACCESS 10:57:47 1388 d99anrdgbb4jf MERGE flashback log file sync 10:57:48 1388 d99anrdgbb4jf MERGE JOIN 10:57:49 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:50 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:51 1388 d99anrdgbb4jf TABLE ACCESS 10:57:52 1388 d99anrdgbb4jf MERGE direct path write 10:57:53 1388 d99anrdgbb4jf TABLE ACCESS 10:57:54 1388 d99anrdgbb4jf MERGE db file sequential read 10:57:55 1388 d99anrdgbb4jf SELECT STATEMENT 52 rows selected. SQL>
By the way, I was also a little surprised to see the direct path read/write operations in the ASH data but these SQLOBJ$ tables that we’re constantly MERGING into recursively have LOBS and further investigation revealed these events to be associated with those LOB segments.
As you can see from above, lots of MERGE operations which have nothing directly to do with SQL_ID d99anrdgbb4jf which looks like the statement below. By the time I’ve got to some of this data for the purposes of this, it’s gone from V$SQL so I’m fetched it from AWR.
SQL> select * from table(dbms_xplan.display_awr('d99anrdgbb4jf'));
PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------
SQL_ID d99anrdgbb4jf
--------------------
SELECT XXXX_XXX FROM XXXX_XXXX WHERE XXXX_XXXX = 'MSD' AND XXXX_XXXX =:B1
Plan hash value: 878181930
-------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 |
| 1 | TABLE ACCESS BY INDEX ROWID| XXXX_XXXX | 1 | 18 | 2 |
| 2 | INDEX RANGE SCAN | XXXX_XXXX_IDX_1 | 1 | | 2 |
-------------------------------------------------------------------------------
Note
-----
- cpu costing is off (consider enabling it)
19 rows selected.
SQL>
Baselines are stored according to signature. SQL statements have hash_values, sql ids and also exact/force matching signatures. By the way, the latter can be translated from the text of the sql statement using DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE using the FORCE_MATCH parameter for either the exact or force matching signature.
In AWR, we’ve only got the FORCE_MATCHING_SIGNATURE of this sql statement sql_id ‘d99anrdgbb4jf’ but take it was the same as the EXACT_MATCHING_SIGNATURE.
SQL> select distinct sql_id, force_matching_signature, to_char(force_matching_signature) 2 from dba_hist_sqlstat 3 where sql_id = 'd99anrdgbb4jf'; SQL_ID FORCE_MATCHING_SIGNATURE TO_CHAR(FORCE_MATCHING_SIGNATURE) ------------- ------------------------ ---------------------------------------- d99anrdgbb4jf 3.9882E+17 398819076860959259 SQL>
I used this signature to see what was happening with the baseline data.
There’s not much point in me pasting the outputs of those tables. I could see that the SYS.SQLOBJ$.LAST_EXECUTED, SYS.SQLOBJ$AUXDATA.CREATED (!?!) and SYS.SQLOBJ$AUXDATA.LAST_MODIFIED were being updated although not the additional metrics like BUFFER_GETS, EXECUTIONS, etc in SYS.SQLOBJ$DATA.
But then I flushed the cache and like that … the performance degradation was gone and not reproducible… for now.
That’s all there is really.
Oh, by the way, I did trace one session while it was reproducing. Below are some of the relevant bits.
I was using a simple slow-by-slow lookup because I was then going to use concurrent sessions which initially were causing me problems with SMO rowcache lock contention – quite possibly related again to the baselines, but I never got that far into the investigation before we flashed it all back and turned off capture.
Also, looping lookups were relevant to one of the bug notes above and are very much representative of some of the legacy Pro*C codebase.
...
BEGIN
DBMS_OUTPUT.DISABLE;
FOR r IN (SELECT * FROM t1)
LOOP
FOR x IN (SELECT id FROM t1 WHERE code = r.code)
LOOP
DBMS_OUTPUT.PUT_LINE(x.id);
END LOOP;
END LOOP;
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 1.07 1.10 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1.08 1.11 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 4106
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net break/reset to client 2 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
log file sync 1 0.06 0.06
********************************************************************************
....
SQL ID: 0jjc60pmrntdv
Plan Hash: 3617692013
SELECT *
FROM
T1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 66 0.01 0.01 0 279 0 6600
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 68 0.01 0.02 0 279 1 6600
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 4106 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
6600 TABLE ACCESS FULL T1 (cr=279 pr=0 pw=0 time=13232 us cost=498 size=22700000 card=100000)
********************************************************************************
SQL ID: 33kddu0j5ykq6
Plan Hash: 2946553998
SELECT ID
FROM
T1 WHERE CODE = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6507 18.15 37.59 6504 54980 6523 0
Fetch 6506 0.28 0.28 0 26024 0 6506
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13014 18.43 37.88 6504 81004 6523 6506
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 4106 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T1 (cr=4 pr=0 pw=0 time=233 us cost=2 size=26 card=1)
1 INDEX UNIQUE SCAN I1 (cr=3 pr=0 pw=0 time=211 us cost=1 size=0 card=1)(object id 97386)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: cache buffers chains 22 0.00 0.00
library cache: mutex X 4 0.00 0.00
latch: shared pool 8 0.00 0.00
********************************************************************************
SQL ID: 9zr2sbbp1d4fs
Plan Hash: 2462756431
SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category
FROM
sqlobj$
WHERE name = :1
AND obj_type = :2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 435 0.01 0.01 0 0 0 0
Execute 435 0.06 0.06 0 0 0 0
Fetch 435 0.01 0.02 1 871 0 434
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1305 0.09 0.10 1 871 0 434
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
------- ---------------------------------------------------
0 INDEX RANGE SCAN I_SQLOBJ$NAME_TYPE (cr=3 pr=1 pw=0 time=10195 us cost=1 size=54 card=1)(object id 199)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
db file sequential read 1 0.00 0.00
********************************************************************************
SQL ID: 47y3mqvyhpkvs
Plan Hash: 1888265482
SELECT obj_type, plan_id, name, flags, last_executed
FROM
sqlobj$
WHERE signature = :1
AND category = :2
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 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 0
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
------- ---------------------------------------------------
0 INDEX RANGE SCAN SQLOBJ$_PKEY (cr=2 pr=0 pw=0 time=51 us cost=1 size=74 card=1)(object id 198)
********************************************************************************
....
SQL ID: 7xm5j53mxbtpn
Plan Hash: 2110601055
MERGE INTO sqlobj$
USING dual ON (:1 IS NULL)
WHEN MATCHED THEN
UPDATE SET name = :2,
flags = :3,
last_executed = :4
WHERE signature = :5
AND category = :6
AND obj_type = :7
AND plan_id = :8
WHEN NOT MATCHED THEN
INSERT (signature, category, obj_type, plan_id, name,
flags, last_executed)
VALUES (:9, :10, :11, :12, :13, :14, :15)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6505 0.35 0.37 0 0 0 0
Execute 6505 29.78 31.78 52 430259 13126 6505
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13010 30.13 32.16 52 430259 13126 6505
Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 MERGE SQLOBJ$ (cr=2 pr=0 pw=0 time=748 us)
1 VIEW (cr=2 pr=0 pw=0 time=202 us)
1 MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=198 us cost=7 size=162488 card=2138)
1 TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=169 us cost=2 size=2 card=1)
0 VIEW (cr=0 pr=0 pw=0 time=7 us cost=5 size=158212 card=2138)
0 FILTER (cr=0 pr=0 pw=0 time=3 us)
0 INDEX FAST FULL SCAN SQLOBJ$_PKEY (cr=0 pr=0 pw=0 time=0 us cost=9 size=158212 card=2138)(object id 198)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: cache buffers chains 23 0.00 0.00
db file sequential read 52 0.89 1.03
buffer busy waits 65 0.00 0.00
log file switch completion 4 0.24 0.44
library cache: mutex X 2 0.00 0.00
********************************************************************************
SQL ID: 44z7snw61qx9x
Plan Hash: 1133963577
MERGE INTO sqlobj$auxdata
USING dual ON (:1 IS NULL)
WHEN MATCHED THEN
UPDATE SET description = :2,
creator = nvl(:3, creator),
origin = :4,
version = :5,
created = :6,
last_modified = :7,
last_verified = nvl(:8, last_verified),
parse_cpu_time = null,
optimizer_cost = nvl(:9, optimizer_cost),
module = nvl(:10, module),
action = nvl(:11, action),
priority = nvl(:12, priority),
optimizer_env = nvl(:13,
optimizer_env), bind_data = nvl(:14,
bind_data),
parsing_schema_name = nvl(:15, parsing_schema_name),
executions = nvl(:16, executions),
elapsed_time = nvl(:17, elapsed_time),
cpu_time = nvl(:18, cpu_time),
buffer_gets = nvl(:19, buffer_gets),
disk_reads = nvl(:20, disk_reads),
direct_writes = nvl(:21, direct_writes),
rows_processed = nvl(:22, rows_processed),
fetches = nvl(:23, fetches),
end_of_fetch_count = nvl(:24, end_of_fetch_count),
task_id = nvl(:25, task_id),
task_exec_name = nvl(:26, task_exec_name),
task_obj_id = nvl(:27, task_obj_id),
task_fnd_id = nvl(:28, task_fnd_id),
task_rec_id = nvl(:29, task_rec_id),
flags = 0,
spare1 = null,
spare2 = null
WHERE signature = :30
AND category = :31
AND obj_type = :32
AND plan_id = :33
WHEN NOT MATCHED THEN
INSERT (signature, category, obj_type,
plan_id, description, creator, origin,
version, created, last_modified,
last_verified, parse_cpu_time, optimizer_cost,
module, action, priority, optimizer_env,
bind_data, parsing_schema_name, executions,
elapsed_time, cpu_time, buffer_gets, disk_reads,
direct_writes, rows_processed, fetches,end_of_fetch_count,
task_id, task_exec_name, task_obj_id, task_fnd_id,
task_rec_id, flags, spare1, spare2)
VALUES (:34, :35, :36, :37,
:38, :39, :40, :41,
:42, :43, null, null,
:44, :45, :46, :47,
:48, :49, :50, :51,
:52, :53, :54, :55,
:56, :57, :58, :59,
:60, :61, :62, :63,
:64, 0, null, null)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6504 0.47 0.49 0 0 0 0
Execute 6504 66.69 70.05 429 1631914 14302 6504
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13008 67.16 70.55 429 1631914 14302 6504
Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 MERGE SQLOBJ$AUXDATA (cr=3 pr=0 pw=0 time=810 us)
1 VIEW (cr=2 pr=0 pw=0 time=134 us)
1 MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=122 us cost=18 size=784646 card=2138)
1 TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=91 us cost=2 size=2 card=1)
0 VIEW (cr=0 pr=0 pw=0 time=15 us cost=16 size=780370 card=2138)
0 FILTER (cr=0 pr=0 pw=0 time=2 us)
0 TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=0 pr=0 pw=0 time=0 us cost=20 size=780370 card=2138)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 2 0.00 0.00
db file sequential read 429 0.29 2.56
buffer busy waits 58 0.00 0.00
latch: cache buffers chains 25 0.00 0.00
log file switch completion 1 0.05 0.05
latch: object queue header operation 1 0.00 0.00
library cache: mutex X 2 0.00 0.00
********************************************************************************
SQL ID: 1vxm21mhmgy07
Plan Hash: 984916430
MERGE INTO sqlobj$data
USING dual ON (:1 IS NULL)
WHEN MATCHED THEN
UPDATE SET comp_data = :2
WHERE signature = :3
AND category = :4
AND obj_type = :5
AND plan_id = :6
WHEN NOT MATCHED THEN
INSERT (signature, category, obj_type, plan_id, comp_data,
spare1, spare2)
VALUES (:7, :8, :9, :10, :11, null, null)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6053 0.35 0.36 0 0 0 0
Execute 6053 38.42 192.12 14420 500403 235414 6053
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12106 38.78 192.48 14420 500403 235414 6053
Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 MERGE SQLOBJ$DATA (cr=43 pr=2 pw=1 time=8478 us)
1 VIEW (cr=2 pr=0 pw=0 time=140 us)
1 MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=131 us cost=9 size=303596 card=2138)
1 TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=109 us cost=2 size=2 card=1)
0 VIEW (cr=0 pr=0 pw=0 time=5 us cost=7 size=299320 card=2138)
0 FILTER (cr=0 pr=0 pw=0 time=3 us)
0 INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=0 pr=0 pw=0 time=0 us cost=6 size=299320 card=2138)(object id 205)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 8367 1.04 43.76
flashback log file sync 7828 0.26 25.34
direct path write 6052 0.47 36.62
direct path read 6045 0.42 16.34
enq: HW - contention 1138 0.89 24.42
Disk file operations I/O 12 0.00 0.00
latch: cache buffers chains 860 0.00 0.03
buffer busy waits 764 1.00 6.00
read by other session 24 0.03 0.34
latch: enqueue hash chains 2 0.00 0.00
enq: TX - index contention 57 0.05 0.21
buffer deadlock 11 0.00 0.00
latch free 2 0.00 0.00
library cache: mutex X 8 0.00 0.00
latch: cache buffers lru chain 4 0.00 0.00
log file switch (checkpoint incomplete) 3 0.14 0.28
enq: TX - allocate ITL entry 1 0.00 0.00
latch: undo global data 1 0.00 0.00
.....
SQL ID: 1zatw56z32vcg
Plan Hash: 1469453527
SELECT obj_type, plan_id, description, creator, origin,
created, last_modified
FROM
sqlobj$auxdata
WHERE signature = :1
AND category = :2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6505 0.10 0.12 0 0 0 0
Execute 6505 0.91 0.96 0 0 0 0
Fetch 13010 0.30 0.29 0 26020 0 6505
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 26020 1.32 1.38 0 26020 0 6505
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 TABLE ACCESS BY INDEX ROWID SQLOBJ$AUXDATA (cr=4 pr=0 pw=0 time=87 us cost=2 size=315 card=1)
1 INDEX RANGE SCAN I_SQLOBJ$AUXDATA_PKEY (cr=3 pr=0 pw=0 time=51 us cost=1 size=0 card=1)(object id 209)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: cache buffers chains 5 0.00 0.00
********************************************************************************
SQL ID: bt51szvfrcdpn
Plan Hash: 1876815449
SELECT obj_type, plan_id, comp_data
FROM
sqlobj$data
WHERE signature = :1
AND category = :2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6504 0.13 0.12 0 0 0 0
Execute 6504 0.82 0.82 0 0 0 0
Fetch 13008 0.28 0.32 0 19516 0 6504
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 26016 1.24 1.27 0 19516 0 6504
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 INDEX RANGE SCAN SQLOBJ$DATA_PKEY (cr=3 pr=0 pw=0 time=89 us cost=1 size=140 card=1)(object id 205)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: cache buffers chains 17 0.00 0.00
********************************************************************************
SQL ID: 1vxm21mhmgy07
Plan Hash: 2462756431
MERGE INTO sqlobj$data
USING dual ON (:1 IS NULL)
WHEN MATCHED THEN
UPDATE SET comp_data = :2
WHERE signature = :3
AND category = :4
AND obj_type = :5
AND plan_id = :6
WHEN NOT MATCHED THEN
INSERT (signature, category, obj_type, plan_id, comp_data,
spare1, spare2)
VALUES (:7, :8, :9, :10, :11, null, null)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6523 0.18 0.19 0 0 0 0
Execute 6523 3.15 8.90 1059 34474 17486 452
Fetch 6071 0.22 0.20 0 12142 0 6071
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19117 3.55 9.30 1059 46616 17486 6523
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 MERGE SQLOBJ$DATA (cr=79 pr=3 pw=1 time=16359 us)
2440 VIEW (cr=43 pr=0 pw=0 time=15141 us)
2440 MERGE JOIN OUTER (cr=43 pr=0 pw=0 time=13065 us cost=9 size=303596 card=2138)
1 TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=59 us cost=2 size=2 card=1)
2440 VIEW (cr=41 pr=0 pw=0 time=7394 us cost=7 size=299320 card=2138)
2440 FILTER (cr=41 pr=0 pw=0 time=6050 us)
2440 INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=41 pr=0 pw=0 time=3971 us cost=6 size=299320 card=2138)(object id 205)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 607 0.09 1.96
direct path read 450 0.03 0.51
flashback log file sync 592 0.01 1.51
direct path write 452 0.02 1.02
latch: cache buffers chains 72 0.00 0.00
buffer busy waits 54 0.00 0.01
enq: HW - contention 70 0.04 0.61
enq: TX - index contention 8 0.00 0.00
read by other session 1 0.01 0.01
********************************************************************************
SQL ID: 44z7snw61qx9x
Plan Hash: 1133963577
*** 2011-03-01 11:38:27.933
MERGE INTO sqlobj$auxdata
USING dual ON (:1 IS NULL)
WHEN MATCHED THEN
UPDATE SET description = :2,
creator = nvl(:3, creator),
origin = :4,
version = :5,
created = :6,
last_modified = :7,
last_verified =
nvl(:8, last_verified),
parse_cpu_time = null,
optimizer_cost = nvl(:9, optimizer_cost),
module = nvl(:10, module),
action = nvl(:11, action),
priority = nvl(:12, priority),
optimizer_env = nvl(:13, optimizer_env),
bind_data = nvl(:14, bind_data),
parsing_schema_name = nvl(:15, parsing_schema_name),
executions = nvl(:16, executions),
elapsed_time = nvl(:17, elapsed_time),
cpu_time = nvl(:18, cpu_time),
buffer_gets = nvl(:19, buffer_gets),
disk_reads = nvl(:20, disk_reads),
direct_writes = nvl(:21, direct_writes),
rows_processed = nvl(:22, rows_processed),
fetches = nvl(:23, fetches),
end_of_fetch_count = nvl(:24,
end_of_fetch_count), task_id = nvl(:25, task_id),
task_exec_name = nvl(:26,
task_exec_name), task_obj_id = nvl(:27,
task_obj_id), task_fnd_id =
nvl(:28, task_fnd_id), task_rec_id
= nvl(:29, task_rec_id), flags = 0,
spare1 =
null,
spare2 = null WHERE
signature = :30
AND category = :31
AND obj_type = :32
AND plan_id = :33
WHEN NOT MATCHED THEN
INSERT (signature, category, obj_type, plan_id,
description, creator, origin, version,
created, last_modified, last_verified, parse_cpu_time,
optimizer_cost, module, action, priority,
optimizer_env, bind_data, parsing_schema_name,
executions, elapsed_time, cpu_time, buffer_gets,
disk_reads, direct_writes, rows_processed,
fetches,end_of_fetch_count, task_id, task_exec_name,
task_obj_id, task_fnd_id, task_rec_id, flags,
spare1, spare2) VALUES (:34, :35, :36,
:37, :38, :39,
:40, :41, :42,
:43, null, null,
:44, :45, :46, :47,
:48, :49, :50, :51,
:52, :53, :54, :55,
:56, :57, :58, :59,
:60, :61, :62, :63,
:64
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 252 2 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 252 2 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 MERGE SQLOBJ$AUXDATA (cr=252 pr=0 pw=0 time=4892 us)
2440 VIEW (cr=252 pr=0 pw=0 time=7181 us)
2440 MERGE JOIN OUTER (cr=252 pr=0 pw=0 time=5835 us cost=18 size=784646 card=2138)
1 TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=71 us cost=2 size=2 card=1)
2440 VIEW (cr=250 pr=0 pw=0 time=4912 us cost=16 size=780370 card=2138)
2440 FILTER (cr=250 pr=0 pw=0 time=3808 us)
2440 TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=250 pr=0 pw=0 time=2953 us cost=20 size=780370 card=2138)
********************************************************************************
SQL ID: bsa0wjtftg3uw
Plan Hash: 2020579421
select file#
from
file$ where ts#=: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 15 0.00 0.00 0 29 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17 0.00 0.00 0 29 0 14
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Rows Row Source Operation
------- ---------------------------------------------------
14 TABLE ACCESS BY INDEX ROWID FILE$ (cr=29 pr=0 pw=0 time=88 us cost=1 size=35 card=5)
14 INDEX RANGE SCAN I_FILE2 (cr=15 pr=0 pw=0 time=151 us cost=1 size=0 card=5)(object id 44)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.01 0 0 0 0
Execute 2 1.08 1.14 0 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.09 1.15 0 0 1 0
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file sync 3 0.06 0.07
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 27.68 47.53
reliable message 1 0.00 0.00
Disk file operations I/O 3 0.00 0.00
Parameter File I/O 8 0.01 0.02
SQL*Net break/reset to client 2 0.00 0.00
direct path read 6503 0.75 18.96
latch: cache buffers chains 78 0.00 0.00
buffer busy waits 103 0.00 0.00
library cache: mutex X 17 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 39047 1.64 1.70 0 0 1 0
Execute 45549 158.03 342.53 22465 2652285 286877 19521
Fetch 39115 1.12 1.16 1 84889 0 32634
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 123711 160.80 345.40 22466 2737174 286878 52155
Misses in library cache during parse: 21
Misses in library cache during execute: 17
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 15 0.00 0.00
db file sequential read 9457 1.04 49.35
flashback log file sync 8420 0.26 26.86
direct path write 6504 0.47 37.64
direct path read 6495 0.42 16.86
enq: HW - contention 1208 0.89 25.03
latch: cache buffers chains 1024 0.00 0.04
buffer busy waits 941 1.00 6.02
read by other session 25 0.03 0.36
latch: enqueue hash chains 2 0.00 0.00
library cache: mutex X 16 0.00 0.00
enq: TX - index contention 65 0.05 0.21
buffer deadlock 11 0.00 0.00
log file switch completion 5 0.24 0.50
latch free 2 0.00 0.00
latch: shared pool 8 0.00 0.00
latch: object queue header operation 1 0.00 0.00
latch: cache buffers lru chain 4 0.00 0.00
log file switch (checkpoint incomplete) 3 0.14 0.28
enq: TX - allocate ITL entry 1 0.00 0.00
latch: undo global data 1 0.00 0.00
4 user SQL statements in session.
19540 internal SQL statements in session.
19544 SQL statements in session.
********************************************************************************
....
1 session in tracefile.
4 user SQL statements in trace file.
19540 internal SQL statements in trace file.
19544 SQL statements in trace file.
20 unique SQL statements in trace file.
3288358 lines in trace file.
394 elapsed seconds in trace file.
OraStory 
Hi,
Excellent analysis. We just discovered this bug after pulling our hair out for the last 6 months.
Question – is it enough to just turn of the optimizer_capture_sql_plan_baselines=false parameter to make this problem go away?
There is an opatch (11719151) that seems to fix this. But it is too close to quarter end for us to apply patches to production. We could do it next month.
Thanks,
Alan
Hi Alan,
Until I patched this, I ran with both parameters set to FALSE and any pre-existing baselines deleted and performance was ok.
Once the patch (11719151) was approved internally and applied, it fixed the problem
Hope this helps.
Cheers,
Dominic
Hi Dominic,
Last November we upgraded our Oracle Apps 11.5.10.2 system from RDBMS 9.2.0.8 to 11.2.0.2. It has been something of a nightmare. Granted the fault was ours. We didn’t test the upgrade enough. Several other emergencies slammed us at the same time and database testing fell through the cracks. My bad. But here is a quick summary of what happened:
In a nutshell – the peformance of the entire system was terrible. Everything was sluggish. It seemed to be systemic rather than isolated to any single process or set of processes.
The first problem we noticed involved reading the data dictionary. When we started up development tools like Sql Navigator or Toad they tried to pre-load parts of the schema. This took minutes to open the tools. Also, searching for objects within the database seemed to take forever. We found a bug in the ALL_SYNONYMS view. We ran the fix in note: Selects Against ALL_SYNONYMS Very Slow in 11.2.0.1. and 11.2.0.2. [ID 1242844.1] and this seemed to help.
But the system was still slow.
Next, having nothing to do with overall performance, we found an optimizer bug that was causing certain where clauses with OR’s and repeating column names to return incorrect (generally nothing) results. This was breaking a couple forms that couldn’t query. We fixed this with bug 9776940 and a hidden parameter “_projection_pushdown” = FALSE.
But the system was still slow.
Next, we noticed that the server was doing an incredible amount of virtual memory page-in’s. At the rate of 4000 to 6000 pages per second. There was no apparent reason for this since the servers seemed to have plenty of free RAM and swap space. After much looking by several people we discovered that the ASO_ORDER_FEEDBACK_T queue had grown very large and the new 11g database was doing full table scans on it at an alarming pace – basically continues FTS again and again and again. Since they were full table scans it was causing the table to be read in from the database everytime and as it was read into the SGA it was also being read into the swap space. We cleaned up the table with How to Purge the ASO_ORDER_FEEDBACK_T Table In Minimum time Using Asoqueue Script ? (Doc ID 740305.1). and the page-in rate dropped to a very small number.
This greatly improved the situation. But the system was still slow.
Then we started investigating one process – Journal Import. On our old 9i database a particular test ran in about 2 minutes. On the new 11g database it took 50 minutes. Oracle support said that nothing was wrong. We disagreed. After lots of back and forth, I was looking at the trace file and noticed 3 different MERGE INTO SQLOBJ$DATA and SQLOBJ$AUXDATA. I didn’t know what these tables were. But a quick google search found that they were part of the SQL Plan Management Capture process. When I added up the times for these three MERGE INTO’s it came to 46 minutes. Adding that to the 2 minutes that the process should have taken gave me almost exactly the actual run time of 50 minutes. Once I found this it was trivial to find out that SQL Plan Capture has a bug in it – Bug 11719151: MERGE STATEMENT USED WHEN SPM CAPTURE CAUSING PERFORMANCE ISSUE . We turned off capture by setting optimizer_capture_sql_plan_baselines=FALSE and performance dramatically improved. We are working on the opatch to repair this problem but it will have to wait until after quarter end processing.
The moral of the story – there is a good reason why they say to test your upgrades before going into production 🙂
Cheers,
Alan
Pingback: Outline, SQL profile and SQL Plan Management(SPM) « Oracle Explorer: Standing on the shoulders of giants