I have a query who's DBMS_XPLAN output looks like this:
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 7 |00:00:00.17 | 310 | 7 | | | |
| 1 | HASH UNIQUE | | 1 | 17 | 7 |00:00:00.17 | 310 | 7 | 1394K| 1394K| 865K (0)|
|* 2 | HASH JOIN OUTER | | 1 | 17 | 7 |00:00:00.17 | 310 | 7 | 1055K| 1055K| 536K (0)|
| 3 | NESTED LOOPS OUTER | | 1 | 17 | 7 |00:00:00.16 | 300 | 7 | | | |
| 4 | NESTED LOOPS OUTER | | 1 | 17 | 7 |00:00:00.01 | 283 | 0 | | | |
| 5 | NESTED LOOPS | | 1 | 17 | 7 |00:00:00.01 | 267 | 0 | | | |
| 6 | NESTED LOOPS OUTER | | 1 | 90 | 7 |00:00:00.01 | 244 | 0 | | | |
| 7 | NESTED LOOPS OUTER | | 1 | 6 | 5 |00:00:00.01 | 237 | 0 | | | |
| 8 | MERGE JOIN CARTESIAN | | 1 | 6 | 5 |00:00:00.01 | 233 | 0 | | | |
| 9 | NESTED LOOPS | | 1 | 1 | 1 |00:00:00.01 | 229 | 0 | | | |
| 10 | TABLE ACCESS BY INDEX ROWID | VERP_OTM_STAGED_VONS | 1 | 1 | 1 |00:00:00.01 | 228 | 0 | | | |
|* 11 | INDEX UNIQUE SCAN | VERP_OTM_STAGED_VONS_U2 | 1 | 1 | 1 |00:00:00.01 | 2 | 0 | | | |
|* 12 | INDEX FULL SCAN | VERP_VPS_SUPPLY_MP_N1 | 1 | 1 | 1 |00:00:00.01 | 1 | 0 | | | |
| 13 | BUFFER SORT | | 1 | 6 | 5 |00:00:00.01 | 4 | 0 | 2048 | 2048 | 2048 (0)|
| 14 | VIEW | | 1 | 6 | 5 |00:00:00.01 | 4 | 0 | | | |
| 15 | UNION-ALL | | 1 | | 5 |00:00:00.01 | 4 | 0 | | | |
|* 16 | FILTER | | 1 | | 0 |00:00:00.01 | 0 | 0 | | | |
| 17 | TABLE ACCESS BY INDEX ROWID BATCHED| OE_ORDER_LINES_ALL | 0 | 28 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 18 | INDEX RANGE SCAN | VERP_OE_ORDER_LINES_N1 | 0 | 7 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 19 | TABLE ACCESS BY INDEX ROWID BATCHED | VERP_ORDER_STD_ACCY_LINES | 1 | 5 | 5 |00:00:00.01 | 4 | 0 | | | |
|* 20 | INDEX RANGE SCAN | VERP_ORDER_STD_ACCY_LINES_N1 | 1 | 5 | 5 |00:00:00.01 | 3 | 0 | | | |
| 21 | VIEW PUSHED PREDICATE | BOM_BILL_OF_MATERIALS | 5 | 1 | 1 |00:00:00.01 | 4 | 0 | | | |
|* 22 | FILTER | | 5 | | 1 |00:00:00.01 | 4 | 0 | | | |
|* 23 | TABLE ACCESS BY INDEX ROWID BATCHED | BOM_STRUCTURES_B | 1 | 1 | 1 |00:00:00.01 | 4 | 0 | | | |
|* 24 | INDEX RANGE SCAN | BOM_STRUCTURES_B_N2 | 1 | 1 | 1 |00:00:00.01 | 3 | 0 | | | |
|* 25 | TABLE ACCESS BY INDEX ROWID BATCHED | BOM_COMPONENTS_B | 5 | 15 | 3 |00:00:00.01 | 7 | 0 | | | |
|* 26 | INDEX RANGE SCAN | BOM_COMPONENTS_B_N2 | 5 | 15 | 5 |00:00:00.01 | 4 | 0 | | | |
| 27 | TABLE ACCESS BY INDEX ROWID | MTL_SYSTEM_ITEMS_B | 7 | 1 | 7 |00:00:00.01 | 23 | 0 | | | |
|* 28 | INDEX UNIQUE SCAN | MTL_SYSTEM_ITEMS_B_U1 | 7 | 1 | 7 |00:00:00.01 | 16 | 0 | | | |
| 29 | TABLE ACCESS BY INDEX ROWID BATCHED | BOM_STANDARD_OPERATIONS | 7 | 1 | 7 |00:00:00.01 | 16 | 0 | | | |
|* 30 | INDEX RANGE SCAN | BOM_STANDARD_OPERATIONS_U1 | 7 | 1 | 7 |00:00:00.01 | 9 | 0 | | | |
| 31 | TABLE ACCESS BY INDEX ROWID BATCHED | BOM_STD_OP_RESOURCES | 7 | 1 | 7 |00:00:00.16 | 17 | 7 | | | |
|* 32 | INDEX RANGE SCAN | BOM_STD_OP_RESOURCES_U1 | 7 | 1 | 7 |00:00:00.16 | 10 | 7 | | | |
|* 33 | VIEW | index$_join$_020 | 1 | 4 | 23 |00:00:00.01 | 10 | 0 | | | |
|* 34 | HASH JOIN | | 1 | | 23 |00:00:00.01 | 10 | 0 | 1393K| 1393K| 1455K (0)|
|* 35 | INDEX FAST FULL SCAN | BOM_RESOURCES_U1 | 1 | 4 | 23 |00:00:00.01 | 6 | 0 | | | |
| 36 | INDEX FAST FULL SCAN | BOM_RESOURCES_U2 | 1 | 4 | 378 |00:00:00.01 | 4 | 0 | | | |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("BR"."RESOURCE_ID"="BSOR"."RESOURCE_ID")
11 - access("V"."HEADER_ID"=:B1)
12 - access("MP"."ORGANIZATION_CODE"="V"."PORT")
filter("MP"."ORGANIZATION_CODE"="V"."PORT")
16 - filter(NULL IS NOT NULL)
18 - access("HEADER_ID"=:B1)
filter(("ITEM_TYPE_CODE"='CLASS' OR "ITEM_TYPE_CODE"='OPTION'))
19 - filter(("VOSAL"."ITEM_TYPE_CODE"='CLASS' OR "VOSAL"."ITEM_TYPE_CODE"='OPTION'))
20 - access("VOSAL"."HEADER_ID"=:B1)
22 - filter('CLASS'="OEL"."ITEM_TYPE_CODE")
23 - filter(((("FND_GLOBAL"."RESP_APPL_ID"()<>431 AND NVL("EFFECTIVITY_CONTROL",1)<=3) OR "FND_GLOBAL"."RESP_APPL_ID"()=431 OR "FND_GLOBAL"."RESP_APPL_ID"()=(-1))
AND "OBJ_NAME" IS NULL))
24 - access("ASSEMBLY_ITEM_ID"="OEL"."INVENTORY_ITEM_ID" AND "ORGANIZATION_ID"=92)
25 - filter((NVL("DISABLE_DATE",SYSDATE@!+1)>SYSDATE@! AND "OBJ_NAME" IS NULL AND "OVERLAPPING_CHANGES" IS NULL))
26 - access("BILL_SEQUENCE_ID"="BBOM"."BILL_SEQUENCE_ID")
28 - access("MSI"."INVENTORY_ITEM_ID"=NVL("COMPONENT_ITEM_ID","OEL"."INVENTORY_ITEM_ID") AND "MSI"."ORGANIZATION_ID"=92)
30 - access("BSO"."OPERATION_CODE"="MSI"."SEGMENT1" AND "BSO"."ORGANIZATION_ID"="MP"."ORGANIZATION_ID")
32 - access("BSOR"."STANDARD_OPERATION_ID"="BSO"."STANDARD_OPERATION_ID")
33 - filter(("BR"."RESOURCE_CODE"='Labor' OR "BR"."RESOURCE_CODE"='Std Labor'))
34 - access(ROWID=ROWID)
35 - filter(("BR"."RESOURCE_CODE"='Labor' OR "BR"."RESOURCE_CODE"='Std Labor'))
I am curious about lines 10 and 11...
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
...
| 10 | TABLE ACCESS BY INDEX ROWID | VERP_OTM_STAGED_VONS | 1 | 1 | 1 |00:00:00.01 | 228 | 0 | | | |
|* 11 | INDEX UNIQUE SCAN | VERP_OTM_STAGED_VONS_U2 | 1 | 1 | 1 |00:00:00.01 | 2 | 0 | | | |
....
As I read this, it is accessing a single row (INDEX UNIQUE SCAN) from VERP_OTM_STAGED_VONS_U2 and getting the (by definition) single row for that from VERP_OTM_STAGED_VONS.
How could that be requiring 228 buffer gets?
I ran this DBMS_XPLAN while the VERP_OTM_STAGED_VONS table was being updated heavily and have a vague theory that most of the 228 buffers are actually spent reading UNDO to construct the last-committed version of the row. Is that reasonable?
If so, could that sort of mechanism be affecting the performance of the program doing the heavy updates?
Specifically, I am wondering if something like this could happen:
1) Program starts a loop...
a) UPDATE TABLE x....
b) (no commits or anything)
c) SELECT FROM TABLE x....
If that loop updated block "B", say, in table X 100 times, what would each read have to do to get the current version of that block? Would all the uncommitted updates be creating more work for it in terms of creating more UNDO to sift through?
Thanks in advance!
Matt
Certainly operations along the lines of:
for i in ( select ... from my_table )
loop
update my_table -- ie, the same table as in the cursor
end loop;
can get into difficulty. Because its not about getting the *current* row, its about getting an *old* row. Because the logic of the code above (assuming it takes 1 second to update each row) is:
- its 9:00:00am, open a cursor on my_table
- fetch a row
- now update that row, its now stamped as being current as of 9:00:01am
- loop around
- fetch next row
- Oh! This *block* is marked as being at 9:00:01am (ie, the previous row update)
- Undo the change to get the block back to 9:00:00am
- Now the next row can be fetched
- now update that row, its now stamped as being current as of 9:00:02am
- loop around
- fetch next row
- Oh! This *block* is marked as being at 9:00:02am (ie, the previous row update)
- Undo the change to get the block back to 9:00:00am (two lots of undo)
- Now the next row can be fetched
etc etc etc
Here's a simple example
SQL> create table t ( x int, y int );
Table created.
SQL> insert into t values (1,1);
1 row created.
SQL> commit;
Commit complete.
SQL> exec dbms_stats.gather_table_stats('','T');
PL/SQL procedure successfully completed.
--
-- open a cursor at this point in time
--
SQL> variable rc refcursor
SQL> exec open :rc for select * from t;
PL/SQL procedure successfully completed.
--
-- now 1000 transactions on that table
--
SQL>
SQL> begin
2 for i in 1 .. 1000 loop
3 update t set y = y + 1;
4 commit;
5 end loop;
6 end;
7 /
PL/SQL procedure successfully completed.
--
-- here are my session stats BEFORE i fetch from that cursor
--
SQL> select
2 s.name, st.value
3 from v$statname s, v$mystat st
4 where st.statistic# = s.statistic#
5 and s.name in (
6 'session logical reads',
7 'consistent gets',
8 'data blocks consistent reads - undo records applied');
NAME VALUE
---------------------------------------------------------------- ----------
session logical reads 10088
consistent gets 7061
data blocks consistent reads - undo records applied 0
3 rows selected.
SQL> print rc
X Y
---------- ----------
1 1
1 row selected.
--
-- here are my session stats AFTER i fetch from that cursor
--
SQL> select
2 s.name, st.value
3 from v$statname s, v$mystat st
4 where st.statistic# = s.statistic#
5 and s.name in (
6 'session logical reads',
7 'consistent gets',
8 'data blocks consistent reads - undo records applied');
NAME VALUE
---------------------------------------------------------------- ----------
session logical reads 11090
consistent gets 8063
data blocks consistent reads - undo records applied 995
3 rows selected.
So to fetch one row, I did 11090 - 10088 = 1002 logical reads, and 995 undo operations.
There are other *potential* causes (delayed block cleanout etc).