Hi Reader,
Inserting on a table with a lot of indexes could cause the wait event db file sequential read. For every row to be inserted the index must be scanned and updated when an indexed column was specified in the DML statement. With about 150 rows a second the insert operation was very slow. I enabled extended trace 10046 event and reviewed the generated raw trace file;
The traditionaly way - trace files
In the 10046 event trace file you will find the Cursor definiton section of the insert statement:
=====================
PARSING IN CURSOR #8 len=693 dep=1 uid=50 oct=2 lid=50 tim=226692485 hv=1579689243 ad=’396bb604‘
INSERT INTO COMPANY (…) VALUES (:B18 , NULL, 0, NULL, NULL, SYS_GUID(), :B17 , NULL, NULL, :B16 , NULL, NULL, NULL, :B15 , NULL, NULL, :B14 , NULL, NULL, NULL, :B13 , :B12 , NULL, :B11 , :B10 , :B9 , :B8 , NULL, NULL, :B7 , :B6 , :B5 , :B4 , :B3 , :B2 , :B1 )
END OF STMT
Corresponding to the Cursor number #8 wait events are collected line by line;
WAIT #8: nam=’db file sequential read’ ela= 23606 file#=11 block#=169935 blocks=1 obj#=73317 tim=251852023
WAIT #8: nam=’db file sequential read’ ela= 21557 file#=15 block#=201225 blocks=1 obj#=84340 tim=251873687
WAIT #8: nam=’db file sequential read’ ela= 9502 file#=5 block#=112658 blocks=1 obj#=73317 tim=251885511
WAIT #8: nam=’db file sequential read’ ela= 8457 file#=5 block#=119421 blocks=1 obj#=73317 tim=251906307
WAIT #8: nam=’db file sequential read’ ela= 9933 file#=11 block#=181310 blocks=1 obj#=73320 tim=251920477
The insert Statement is waiting on ‘db file sequential read’; This means index blocks need to be updated for every inserted row. An update operation always causes a read operation. Then you see the elapsed time waited on the event and the corresponding Oracle Block :
ela= 23606 file#=11 block#=169935 blocks=1
The last columns of the wait event line show the object on which the wait occurred. In this case it identifies the index object. It’s the object id defined/visible in the DBA_OBJECTS view;
obj#=73317
Now it would be interesting to know on which index segments the highest amount of Waits is. First i thought to parse the trace file and aggregate the wait event timings dependent on the objects id of the index. But this is a lot of work!
The work is done - already
And that’s the point i want to address : this work is already done with Oracle 10.2. The new Active Session History holds a wait history for all events in a static V$ table. So you need not to parse a raw 10046 trace file but you can use simply SQL to create your stats summary.
Before we take a look on the Active Session History it would be helpful to identify the SQL Statement. For this Oracle 10 introduces the SQL_ID; this id presented as raw value is unique for a SQL statement and stored to identify the SQL in the AWR Repository. So let’s query the most I/O related SQL :
SELECT *
FROM (SELECT Sql_Text,
Sql_Id,
Elapsed_Time,
Cpu_Time,
User_Io_Wait_Time
FROM Sys.v_$sqlarea
ORDER BY 5 DESC)
WHERE Rownum <= 10
;
SQL>
SQL> SELECT *
2 FROM (SELECT Sql_Text,
3 Sql_Id,
4 Elapsed_Time,
5 Cpu_Time,
6 User_Io_Wait_Time
7 FROM Sys.v_$sqlarea
8 ORDER BY 5 DESC)
9 WHERE Rownum <= 10
10 ;
SQL_TEXT SQL_ID ELAPSED_TIME CPU_TIME USER_IO_WAIT_TIME
——————————————————————————– ————- ———— ———- —————–
DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN : ghd7756swyr57 8086056419 2354027440 5646498847
insert into wri$_adv_objspace_trend_data select timepoint, space_usage, space_a 8szmwam7fysa3 5349309477 34476481 5328638621
call ISIS.JOB_SAMPLE_STATS ( :0 ) 2zqxbb6vcczc5 6272593702 2342870666 3860113334
DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN : 6gvch1xu9ca3g 2745079215 290436248 2092929799
CALL MGMT_ADMIN_DATA.EVALUATE_MGMT_METRICS(:tguid, :mguid, :result) abtp0uqvdb1d3 2014214236 50339448 1920152264
INSERT INTO COMPANY (COKISSTREET, LEGAL, ISIS_PREFERED, INDUSTRYSUBTYPEKEY, MAIN 9kn5h8xg2h98v 1457505383 163517071 1327894552
BEGIN – Call the procedure Eventlogmgr.Begintask; Util_Session.Work_Area_ 9z93xgg5anujn 1437976040 200453636 1238418231
select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor_sharing_exact u 82bks68vck6b8 2517148726 1375255579 1053152419
select /*+ no_parallel_index(t,"COMPANY_FX01") dbms_stats cursor_sharing_exact u f5g9fzrg3zcky 1005457671 18158338 985640727
select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor_sharing_exact u 4jjhy9autcxu6 1133956193 186810975 933561254
10 rows selected
SQL>
With the SQL_ID it is possible to query against the Active Session History. Following SQL summarized all waiting times of an SQL dependent on the object on which the wait event occurred.
SELECT Vash.Event,
SUM(Vash.Time_Waited) AS Total_Time_Waited,
Do.Object_Id,
Do.Owner,
Do.Object_Name
FROM Sys.v_$active_Session_History Vash,
Sys.Dba_Objects Do
WHERE Vash.Sql_Id = ‘9kn5h8xg2h98v’
AND Vash.Current_Obj# = Do.Object_Id
AND Time_Waited <> 0
GROUP BY Vash.Event,
Do.Object_Id,
Do.Owner,
Do.Object_Name
;
SQL>
SQL> SELECT Vash.Event,
2 SUM(Vash.Time_Waited) AS Total_Time_Waited,
3 Do.Object_Id,
4 Do.Owner,
5 Do.Object_Name
6 FROM Sys.v_$active_Session_History Vash,
7 Sys.Dba_Objects Do
8 WHERE Vash.Sql_Id = ‘9kn5h8xg2h98v’
9 AND Vash.Current_Obj# = Do.Object_Id
10 AND Time_Waited <> 0
11 GROUP BY Vash.Event,
12 Do.Object_Id,
13 Do.Owner,
14 Do.Object_Name
15 ;
EVENT TOTAL_TIME_WAITED OBJECT_ID OWNER OBJECT_NAME
—————————————————————- —————– ———- —————————— ——————————————————————————–
db file sequential read 135909921 73317 ISIS COMPANY_FX02
db file sequential read 5174869 72587 ISIS COMPANY
db file sequential read 79492328 73316 ISIS COMPANY_FX01
db file sequential read 38163394 84340 ISIS COMPANY_UK02
db file sequential read 83892 73315
ISIS COMPANY_IX01
db file sequential read 28944084 73320 ISIS COMPANY_FX05
log file switch completion 295991 84340 ISIS COMPANY_UK02
db file sequential read 45375422 72588 ISIS COMPANY_PK
8 rows selected
SQL>
You clearly can see on which indexes the insert statement opration has to wait and which indexes causes the largest amount of waits. In this case the COMPANY_FX02 index consumes about 30% of all waits.
Why still in need of the old 10046 traces
- The detailed Active Session History exists only in memory
Few minutes later after the events are recorded dependent on database load and SGA size the sampled wait events details could be gone. Before deletion they are stored in the AWR in aggregated format.
- You see not the whole picture
Tracing the INSERT Statement gives you stats about all secondary activities the INSERT statement causes due to triggers or materialized views and replication. These SQL are the so called recursive SQL statements. In the current example the table COMPANY had a Materialized View Log defined which caused a lot of elapsed time too (a section in the tkprof prepared file of the raw 10046 trace):
SELECT DISTINCT LOG$."ID"
FROM
(SELECT MLOG$."ID" FROM "ISIS"."MLOG$_COMPANY1" MLOG$ WHERE "SNAPTIME$$" >
:1 AND ("DMLTYPE$$" != ‘I’)) LOG$ WHERE (LOG$."ID") NOT IN (SELECT
MAS_TAB$."ID" FROM "ISIS"."COMPANY" "MAS_TAB$" WHERE
("MAS_TAB$"."ISIS_PREFERED"=1) AND LOG$."ID" = MAS_TAB$."ID")
call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 31 0.00 0.00 0 0 0 0
Execute 31 0.03 0.00 0 0 0 0
Fetch 31 0.85 55.76 4077 18835 0 4417
——- —— ——– ———- ———- ———- ———- ———-
total 93 0.89 55.77 4077 18835 0 4417
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50 (recursive depth: 2)
Rows Row Source Operation
——- —————————————————
200 HASH UNIQUE (cr=837 pr=198 pw=0 time=2888263 us)
200 FILTER (cr=837 pr=198 pw=0 time=2879283 us)
200 TABLE ACCESS FULL MLOG$_COMPANY1 (cr=37 pr=0 pw=0 time=743 us)
0 TABLE ACCESS BY INDEX ROWID COMPANY (cr=800 pr=198 pw=0 time=2877308 us)
200 INDEX UNIQUE SCAN COMPANY_PK (cr=600 pr=198 pw=0 time=2875219 us)(object id 72588)
Conclusion
With the Active Session History Oracle gives you an instrument for ad hoc tuning. An easy interface querying Statement statistics via SQL. For the whole picture and further statement dependencies the 10046 trace is still the choice.
HTH
Karl