Archive
Archive for October, 2010
Performance After Streams Disabling
October 30, 2010
1 comment
Yesterday, user running report called and told that his report is taking too much time. Previously it do completed in 10-15 Minutes approximately but today it ran for almost 1hr 30 minutes. Before going further a brief history on this database.
We were using bi-directional streams for replication but for few reasons to test we had drop stream’s configuration. We didn’t drop entirely just disabled apply and capture process. So, this was the only change we made nothing else was changed for this and reports started running slow.
Meanwhile asked user to run report again and saw some sequential reads nothing much. But, read time was high then it used to be. Other thing i though let’s see what’s happening with all other session
USERX@XXXXXX > @sw 196
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
196 WORKING On CPU / runqueue 994 629680 file#= 59 block#= 9591 blocks= 1
USERX@XXXXXX > @sw 196
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
196 WORKING On CPU / runqueue 994 629682 file#= 59 block#= 9591 blocks= 1
USERX@XXXXXX > @sw 196
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
196 WORKING On CPU / runqueue 994 629729 file#= 59 block#= 9591 blocks= 1
USERX@XXXXXX > @sw 196
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
196 WORKING On CPU / runqueue 994 629925 file#= 59 block#= 9591 blocks= 1
Strange, May be something is wrong. Let’s Look at all session (Mostly All connected User)
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
117 WORKING On CPU / runqueue 397 531751 file#= 59 block#= 9591 blocks= 1
96 WORKING On CPU / runqueue 685 191592 file#= 59 block#= 9591 blocks= 1
251 WORKING On CPU / runqueue 989 22991 file#= 59 block#= 9591 blocks= 1
105 WORKING On CPU / runqueue 966 197314 file#= 59 block#= 9591 blocks= 1
113 WORKING On CPU / runqueue 494 539386 file#= 59 block#= 9591 blocks= 1
115 WORKING On CPU / runqueue 427 189900 file#= 59 block#= 9591 blocks= 1
117 WORKING On CPU / runqueue 397 531763 file#= 59 block#= 9591 blocks= 1
119 WORKING On CPU / runqueue 547 520586 file#= 59 block#= 9591 blocks= 1
126 WORKING On CPU / runqueue 586 7956 file#= 59 block#= 9591 blocks= 1
127 WORKING On CPU / runqueue 348 710021 file#= 59 block#= 9591 blocks= 1
132 WORKING On CPU / runqueue 1087 18968 file#= 59 block#= 9591 blocks= 1
104 WORKING On CPU / runqueue 583 454268 file#= 59 block#= 9591 blocks= 1
245 WORKING On CPU / runqueue 669 454299 file#= 59 block#= 9591 blocks= 1
237 WORKING On CPU / runqueue 1085 438102 file#= 59 block#= 9591 blocks= 1
236 WORKING On CPU / runqueue 1168 453030 file#= 59 block#= 9591 blocks= 1
231 WORKING On CPU / runqueue 548 454175 file#= 59 block#= 9591 blocks= 1
227 WORKING On CPU / runqueue 600 526299 file#= 59 block#= 9591 blocks= 1
215 WORKING On CPU / runqueue 378 515927 file#= 59 block#= 9591 blocks= 1
211 WORKING On CPU / runqueue 265 7486 file#= 59 block#= 9591 blocks= 1
198 WORKING On CPU / runqueue 1186 21824 file#= 59 block#= 9591 blocks= 1
196 WORKING On CPU / runqueue 994 630006 file#= 59 block#= 9591 blocks= 1
184 WORKING On CPU / runqueue 1077 449734 file#= 59 block#= 9591 blocks= 1
182 WORKING On CPU / runqueue 372 713555 file#= 59 block#= 9591 blocks= 1
178 WORKING On CPU / runqueue 1206 454466 file#= 59 block#= 9591 blocks= 1
175 WORKING On CPU / runqueue 988 543158 file#= 59 block#= 9591 blocks= 1
150 WORKING On CPU / runqueue 595 452974 file#= 59 block#= 9591 blocks= 1
151 WORKING On CPU / runqueue 957 22541 file#= 59 block#= 9591 blocks= 1
157 WORKING On CPU / runqueue 234 3261 file#= 59 block#= 9591 blocks= 1
163 WORKING On CPU / runqueue 582 452932 file#= 59 block#= 9591 blocks= 1
170 WORKING On CPU / runqueue 650 449652 file#= 59 block#= 9591 blocks= 1
202 WORKING On CPU / runqueue 1093 716105 file#= 59 block#= 9592 blocks= 5
This is Strange. Something must be going on. Also, tried to see what other stats are there picking up any one session but no luck. Nothing was happening. But Yes CPU usage was much high. It’s time to look more
Start dump data blocks tsn: 101 file#: 59 minblk 9591 maxblk 9591 buffer tsn: 101 rdba: 0x0ec02577 (59/9591) scn: 0x057c.82828596 seq: 0x02 flg: 0x04 tail: 0x85962302 frmt: 0x02 chkval: 0x56c5 type: 0x23=PAGETABLE SEGMENT HEADER Hex dump of block: st=0, typ_found=1 USERX@XXXXXX > @oid 114474 owner object_name object_type CREATED LAST_DDL_T status DATA_OBJECT_ID ------------------------- ------------------------------ ------------------ ---------- ---------- --------- -------------- XDB XDB$SCHEMA TABLE 11/23/2006 11/23/2006 VALID 114474 USERX@XXXXXX > select segment_name,header_file, header_block from dba_segments where owner='XDB' and segment_name='XDB$SCHEMA'; SEGMENT_NAME HEADER_FILE HEADER_BLOCK --------------------------------------------------------------------------------- ----------- ------------ XDB$SCHEMA 59 9591
And this object is nothing but table of xmltype. Looking at this it seems like a corruption issue. Verified and this is not the case. Hmmm let’s see what sessions are doing.
USERX@XXXXXX > @usql 117
HASH_VALUE CH# PLAN_HASH SQL_TEXT
---------- ----- ---------- --------------------------------------------------------------------------------------------------------------
3767872888 0 677615252 select s.synonym_name object_name, o.object_type from all_synonyms s, sys.all_objects o where s.owner in
('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')
3767872888 1 677615252 select s.synonym_name object_name, o.object_type from all_synonyms s, sys.all_objects o where s.owner in
('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')
Tried to run this query manually.
USERX@XXXXXX > select s.synonym_name object_name, o.object_type
2 from all_synonyms s, sys.all_objects o
3 where s.owner in ('PUBLIC', 'USERX') <<-- This Bind Variable is Replaced
4 and o.owner = s.table_owner
5 and o.object_name = s.table_name
6 and o.object_type in ('TABLE',
7 'VIEW',
8 'PACKAGE',
9 'TYPE',
10 'PROCEDURE',
11 'FUNCTION',
12 'SEQUENCE');
It hangs And session spins on CPU
USERX@XXXXXX > @sw 176
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
176 WORKING On CPU / runqueue 1049 66 file#= 59 block#= 9591 blocks= 1
And here is the actual Query which is hanging
select count(*) from user$ u, xdb.xdb$schema s where u.user# = :1 and u.name = s.xmldata.schema_owner and
(xdb.xdb$Extname2Intname(s.xmldata.schema_url, s.xmldata.schema_owner) = :2)
We are not getting anywhere and still our original problem regarding reports still we haven’t touch itself. Let’s see what our report is doing. The reason why we are leaving this alone is just to solve first user issue and investigate this latter. Also, the report session is not experiencing this thing. I let the system as it is for 1.5 hrs till report complete. Here is the one SQL from report which is running slow and many more.
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 335 0.85 0.81 0 0 0 0 Fetch 335 222.43 2452.93 608516 10434554 0 335 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 670 223.28 2453.75 608516 10434554 0 335 Misses in library cache during parse: 0 Optimizer mode: CHOOSE Parsing user id: 1094 (recursive depth: 1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 607989 0.37 2272.88 gc cr grant 2-way 7435 0.04 4.63 latch: cache buffers chains 21 0.00 0.00 latch: library cache 2 0.00 0.00 latch: gcs resource hash 17 0.00 0.00
So, Sequential read is the culprit. This what this says. May be we can rewrite or throw some more better index to resolve this. Also, Let’s see statspack report also as we are having other problem too.
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file scattered read 1,834,168 3,321 2 167.2 User I/O
db file sequential read 383,394 1,443 4 72.7 User I/O
CPU time 370 18.6
gc current block 2-way 166,656 122 1 6.2 Cluster
os thread startup 1,375 79 58 4.0 Concurrenc
cache buffer handles 2,746 0.0 N/A 0 0 N/A
cache buffers chains 77,966,867 0.0 0.0 0 28,852,899 0.0
cache buffers lru chain 10,382 0.5 0.0 0 30,691,321 0.1
cache table scan latch 0 N/A N/A 0 1,833,334 0.0
channel handle pool latc 2,934 0.0 N/A 0 0 N/A
channel operations paren 326,804 0.0 0.0 0 0 N/A
checkpoint queue latch 105,819 0.0 N/A 0 2,036 0.0
Tablespace Subobject Obj. Physical
Owner Name Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
STRM USERS AQ$_CAPTURE_SDOLTS01 TABLE 14,149,682 92.99
xxxxx DATA_ AF TABLE 726,962 4.78
What wait’s are showing and statspack is showing are somehow different. After looking many other things found that streams’s propagation was still enable and there were lot’s of failed attempt to ping remote server.
So, Disabled and dropped that propagation. Voila, wait on that block was gone and CPU came down instantly. So, called user to try and run report again without changing anything. Same SQL took very less time.
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 636 1.79 1.67 0 0 0 0 Fetch 636 185.53 386.00 264380 18954114 0 636 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 1273 187.32 387.67 264380 18954114 0 636 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: 1094 (recursive depth: 1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 1 0.00 0.00 gc cr grant 2-way 6449 0.00 2.88 db file sequential read 264013 0.13 178.93 gc cr multi block request 1 0.00 0.00 db file scattered read 1 0.00 0.00 gc current block 2-way 51453 0.64 39.90
And, report ran in 12 Minutes. Good Lesson learn.
Categories: Troubleshooting
Oracle Index Monitoring
October 20, 2010
Leave a comment
Today someone asked how to Monitor Index usage. It’s simple to turn on monitoring on index. Oracle support told there is no easy way to do it and in some term that is right too.
But the funny thing is, object usage report might be wrong while you rebuild or gather statistics on index and some other things. Well, Sometimes monitoring is not the right way to identify index usage. Mostly, this whole exercise is done for some space gain or for performance. For example in warehouse for each load they disable index and then rebuild after load and at this point of time performance degradation takes place while rebuilding indexes. This is not the part of discussion but we will include this also little bit today.
Here are some examples of this.
Let’s start with how v$object_usage columns are.
TEST1@taral > @desc sys.v$object_usage;
Col# SEG_COL_ID Column Name Null? Type
---- ---------- ------------------------------ ---------- -------------------------
1 1 INDEX_NAME NOT NULL VARCHAR2(30)
2 2 TABLE_NAME NOT NULL VARCHAR2(30)
3 3 MONITORING VARCHAR2(3)
4 4 USED VARCHAR2(3)
5 5 START_MONITORING VARCHAR2(19)
6 6 END_MONITORING VARCHAR2(19)
6 rows selected.
TEST1@taral > @view sys.v$object_usage;
Owner VIEW_NAME View Text
---------- ------------------------------ ----------------------------------------------------------------
SYS V$OBJECT_USAGE select io.name, t.name,
decode(bitand(i.flags, 65536), 0, 'NO', 'YES'),
decode(bitand(ou.flags, 1), 0, 'NO', 'YES'),
ou.start_monitoring,
ou.end_monitoring
from sys.obj$ io, sys.obj$ t, sys.ind$ i, sys.object_usage ou
where io.owner# = userenv('SCHEMAID')
and i.obj# = ou.obj#
and io.obj# = ou.obj#
and t.obj# = i.bo#
First Test Case With Two Different Users
=========================================
drop table test1.xx purge;
create table test1.xx as select object_id,object_name from dba_objects;
create index test1.xx_idx on test1.xx(object_id);
select * from v$object_usage;
TEST1@taral > select * from v$object_usage;
no rows selected
TEST1@taral > alter index test1.xx_idx MONITORING USAGE;
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XX_IDX XX YES NO 10/20/2010 10:57:15
TEST1@taral > select * from test1.xx; --Lines Not Displayed
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XX_IDX XX YES NO 10/20/2010 10:57:15
select * from test1.xx where object_id=41;
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XX_IDX XX YES YES 10/20/2010 10:57:15
But if i tried from different User (Because o.owner# = userenv('SCHEMAID'))
TEST2@taral > select * from v$object_usage;
no rows selected
Second Test Case With Explain Plan ========================================= set autotrace off; drop table test1.xx purge; create table test1.xx as select object_id,object_name from dba_objects; create index test1.xx_idx on test1.xx(object_id); select * from v$object_usage; alter index test1.xx_idx MONITORING USAGE; select * from v$object_usage; SET AUTOTRACE TRACEONLY EXPLAIN; select * from test1.xx where object_id=41; set autotrace off; select * from v$object_usage; TEST1@taral > select * from v$object_usage; INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING ------------------------------ ------------------------------ --- --- ------------------- ------------------- XX_IDX XX YES NO 10/20/2010 15:32:32 TEST1@taral > SET AUTOTRACE TRACEONLY EXPLAIN; TEST1@taral > select * from test1.xx where object_id=41; Execution Plan ---------------------------------------------------------- Plan hash value: 2275028263 -------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 79 | 2 (0)| 00:00:01 | | 1 | TABLE ACCESS BY INDEX ROWID| XX | 1 | 79 | 2 (0)| 00:00:01 | |* 2 | INDEX RANGE SCAN | XX_IDX | 1 | | 1 (0)| 00:00:01 | -------------------------------------------------------------------------------------- TEST1@taral > set autotrace off; TEST1@taral > select * from v$object_usage; INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING ------------------------------ ------------------------------ --- --- ------------------- ------------------- XX_IDX XX YES YES 10/20/2010 15:32:32
Third Test Case With Index Rebuild ----------------------------------- set autotrace off; drop table test1.xx purge; create table test1.xx as select object_id,object_name from dba_objects; create index test1.xx_idx on test1.xx(object_id); select * from v$object_usage; alter index test1.xx_idx MONITORING USAGE; select * from v$object_usage; alter index test1.xx_idx rebuild; select * from v$object_usage; ALTER INDEX test1.xx_idx NOMONITORING USAGE; TEST1@taral > select * from v$object_usage; INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING ------------------------------ ------------------------------ --- --- ------------------- ------------------- XX_IDX XX YES NO 10/20/2010 15:38:58 TEST1@taral > alter index test1.xx_idx rebuild; Index altered. TEST1@taral > select * from v$object_usage; INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING ------------------------------ ------------------------------ --- --- ------------------- ------------------- XX_IDX XX NO YES 10/20/2010 15:38:58 TEST1@taral > alter index test1.xx_idx MONITORING USAGE; Index altered. TEST1@taral > select * from v$object_usage; INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING ------------------------------ ------------------------------ --- --- ------------------- ------------------- XX_IDX XX YES NO 10/20/2010 15:39:50 So, this query will solve this issue SELECT * FROM v$object_usage WHERE (monitoring='YES' AND used='YES') OR (used='YES' AND end_monitoring IS NOT NULL) ;
As, in starting i said we will see some examples of how this can’t be useful.
Let’s say there are 5-6 indexes on one table and i had turned on monitoring for all this indexes. Some query only hit this index once and that change the status of index. So, my report from v$object_usage will say i have to keep this index even though it has been used only once. So, this won’t say how many times this index has been really used. Also, there is other danger involved with this is you might end up deleting some index which you might need as monitoring may not give you whole picture.
set autotrace off;
drop table test1.xxf purge;
drop table test1.xx purge;
create table test1.xx (object_id number constraint xx_pk primary key, object_name varchar2(128)) ;
insert into test1.xx select rownum,object_name from dba_objects where rownum < 2001; commit; select * from v$object_usage; alter index test1.xx_pk MONITORING USAGE; set autotrace on; select * from test1.xx where object_id=41; select * from test1.xx where object_id=100; set autotrace off; select * from v$object_usage; TEST1@taral > set autotrace off;
TEST1@taral > drop table test1.xxf purge;
Table dropped.
TEST1@taral > drop table test1.xx purge;
Table dropped.
TEST1@taral > create table test1.xx (object_id number constraint xx_pk primary key, object_name varchar2(128)) ;
Table created.
TEST1@taral > insert into test1.xx select rownum,object_name from dba_objects where rownum < 2001; 2000 rows created. TEST1@taral > commit;
Commit complete.
TEST1@taral > select * from v$object_usage;
no rows selected
TEST1@taral > alter index test1.xx_pk MONITORING USAGE;
Index altered.
TEST1@taral > set autotrace on;
TEST1@taral > select * from test1.xx where object_id=41;
OBJECT_ID OBJECT_NAME
---------- --------------------------------------------------------------------------------------------------------------------------------
41 FET$
Execution Plan
----------------------------------------------------------
Plan hash value: 266797879
-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 79 | 2 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| XX | 1 | 79 | 2 (0)| 00:00:01 |
|* 2 | INDEX UNIQUE SCAN | XX_PK | 1 | | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------------
TEST1@taral > select * from test1.xx where object_id=100;
OBJECT_ID OBJECT_NAME
---------- --------------------------------------------------------------------------------------------------------------------------------
100 FIXED_OBJ$
Execution Plan
----------------------------------------------------------
Plan hash value: 266797879
-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 79 | 2 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| XX | 1 | 79 | 2 (0)| 00:00:01 |
|* 2 | INDEX UNIQUE SCAN | XX_PK | 1 | | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------------
TEST1@taral > set autotrace off;
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XX_PK XX YES YES 10/20/2010 16:50:20
So, this is not telling you how many times this index has been used.
create table test1.xxf (object_id number, object_type varchar2(128) , constraint xxf_fk foreign key(object_id ) references xx(object_id));
insert into test1.xxf select decode(mod(rownum,1000),0,1,mod(rownum,1000)) object_id, stage.object_type from dba_objects stage;
commit;
create index test1.xxf_fk on test1.xxf(object_id);
exec dbms_stats.gather_table_stats(user,'XX');
exec dbms_stats.gather_table_stats(user,'XXF');
alter index test1.xxf_fk monitoring usage;
select * from v$object_usage;
set autotrace on;
delete test1.xx where object_id = 2000;
commit;
set autotrace off;
select * from v$object_usage;
TEST1@taral > create table test1.xxf (object_id number, object_type varchar2(128) , constraint xxf_fk foreign key(object_id ) references xx(object_id))
Table created.
TEST1@taral > insert into test1.xxf select decode(mod(rownum,1000),0,1,mod(rownum,1000)) object_id, stage.object_type from dba_objects stage;
72302 rows created.
TEST1@taral > commit;
Commit complete.
TEST1@taral > create index test1.xxf_fk on test1.xxf(object_id);
Index created.
TEST1@taral > exec dbms_stats.gather_table_stats(user,'XX');
PL/SQL procedure successfully completed.
TEST1@taral > exec dbms_stats.gather_table_stats(user,'XXF');
PL/SQL procedure successfully completed.
TEST1@taral > alter index test1.xxf_fk monitoring usage;
Index altered.
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XXF_FK XXF YES NO 10/20/2010 16:50:23
XX_PK XX YES YES 10/20/2010 16:50:20
TEST1@taral > set autotrace on;
TEST1@taral > delete test1.xx where object_id = 2000;
1 row deleted.
Execution Plan
----------------------------------------------------------
Plan hash value: 203824999
----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------
| 0 | DELETE STATEMENT | | 1 | 4 | 1 (0)| 00:00:01 |
| 1 | DELETE | XX | | | | |
|* 2 | INDEX UNIQUE SCAN| XX_PK | 1 | 4 | 1 (0)| 00:00:01 |
----------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("OBJECT_ID"=2000)
Statistics
----------------------------------------------------------
178 recursive calls
7 db block gets
35 consistent gets
0 physical reads
116 redo size
679 bytes sent via SQL*Net to client
611 bytes received via SQL*Net from client
3 SQL*Net roundtrips to/from client
6 sorts (memory)
0 sorts (disk)
1 rows processed
TEST1@taral > commit;
Commit complete.
TEST1@taral > set autotrace off;
TEST1@taral > select * from v$object_usage;
INDEX_NAME TABLE_NAME MON USE START_MONITORING END_MONITORING
------------------------------ ------------------------------ --- --- ------------------- -------------------
XXF_FK XXF YES NO 10/20/2010 16:50:23
XX_PK XX YES YES 10/20/2010 16:50:20
If you see now foreign key index is not been used from v$object_usage. So, it’s safe to delete it.
TEST1@taral > drop index test1.xxf_fk;
Index dropped.
TEST1@taral > set autotrace on;
TEST1@taral > delete test1.xx where object_id = 1999;
1 row deleted.
Execution Plan
----------------------------------------------------------
Plan hash value: 203824999
----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------
| 0 | DELETE STATEMENT | | 1 | 4 | 1 (0)| 00:00:01 |
| 1 | DELETE | XX | | | | |
|* 2 | INDEX UNIQUE SCAN| XX_PK | 1 | 4 | 1 (0)| 00:00:01 |
----------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("OBJECT_ID"=1999)
Statistics
----------------------------------------------------------
190 recursive calls
7 db block gets
217 consistent gets
0 physical reads
732 redo size
679 bytes sent via SQL*Net to client
611 bytes received via SQL*Net from client
3 SQL*Net roundtrips to/from client
6 sorts (memory)
0 sorts (disk)
1 rows processed
TEST1@taral > commit;
Commit complete.
TEST1@taral >
See how much now more work we have to do after removing index which was useful. So, don’t rely on v$object_usage. It’s not a metric.
Reference:
Categories: Index, Performance
TKPROF in 11gR2 – New Rows Columns
October 15, 2010
Leave a comment
In one of OTN thread I asked information about new columns in rowsource operation and Charles Hooper and Tom Kyte give some insight on this. I didn’t got chance to run test case provided by charles.
In my previous post I had mention same thing and here are some more things which i tried today.
I am using 11.2.0.1.0 Version and will update this page if i find something different in 11.2.0.2. Also, using windows 32 bit environment and Charles test case. Let’s get started.
Here is the test setup
drop table t1 purge; drop table t2 purge; CREATE TABLE T1(C1 NUMBER NOT NULL,C2 NUMBER NOT NULL,C3 VARCHAR2(100)); CREATE TABLE T2(C1 NUMBER NOT NULL,C2 NUMBER NOT NULL,C3 VARCHAR2(100)); INSERT INTO T1 SELECT ROWNUM C1,V2.RN C2,RPAD(TO_CHAR(ROWNUM),10,'A') C3 FROM (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL<=1000) V1, (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL<=1000) V2 WHERE MOD(V1.RN,1000)>=V2.RN; INSERT INTO T2 SELECT * FROM T1; COMMIT; CREATE INDEX IND_T1_C1_C2 ON T1(C1,C2); CREATE INDEX IND_T2_C1_C2 ON T2(C1,C2); EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE); EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE);
This is test script
VARIABLE N1 NUMBER EXEC :N1:=1 ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SQL_10046_ROW_TEST'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 16'; SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); EXEC :N1:=5 SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); EXEC :N1:=95 SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); EXEC :N1:=995 SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
This is the output
TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
COUNT(*)
----------
998001
TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8ygbsrkt6sqd9, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
T1.C2=T2.C2 AND T1.C2= :N1
Plan hash value: 765688747
------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Use
------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.34 | 2780 | 4 | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.34 | 2780 | 4 | | |
|* 2 | HASH JOIN | | 1 | 250K| 998K|00:00:00.66 | 2780 | 4 | 1066K| 1066K| 42
|* 3 | INDEX FAST FULL SCAN| IND_T1_C1_C2 | 1 | 500 | 999 |00:00:00.04 | 1390 | 2 | | |
|* 4 | INDEX FAST FULL SCAN| IND_T2_C1_C2 | 1 | 500 | 999 |00:00:00.04 | 1390 | 2 | | |
------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T1"."C2"="T2"."C2")
3 - filter("T1"."C2"=:N1)
4 - filter("T2"."C2"=:N1)
24 rows selected.
TARAL@taral >
TARAL@taral > EXEC :N1:=5
PL/SQL procedure successfully completed.
TARAL@taral >
TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
COUNT(*)
----------
990025
TARAL@taral >
TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8ygbsrkt6sqd9, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
T1.C2=T2.C2 AND T1.C2= :N1
Plan hash value: 765688747
----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.30 | 2780 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.30 | 2780 | | | |
|* 2 | HASH JOIN | | 1 | 250K| 990K|00:00:00.65 | 2780 | 1066K| 1066K| 395K (0)|
|* 3 | INDEX FAST FULL SCAN| IND_T1_C1_C2 | 1 | 500 | 995 |00:00:00.04 | 1390 | | | |
|* 4 | INDEX FAST FULL SCAN| IND_T2_C1_C2 | 1 | 500 | 995 |00:00:00.04 | 1390 | | | |
----------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T1"."C2"="T2"."C2")
3 - filter("T1"."C2"=:N1)
4 - filter("T2"."C2"=:N1)
24 rows selected.
TARAL@taral >
TARAL@taral > EXEC :N1:=95
PL/SQL procedure successfully completed.
TARAL@taral >
TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
COUNT(*)
----------
819025
TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8ygbsrkt6sqd9, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
T1.C2=T2.C2 AND T1.C2= :N1
Plan hash value: 765688747
----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.28 | 2780 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.28 | 2780 | | | |
|* 2 | HASH JOIN | | 1 | 250K| 819K|00:00:00.57 | 2780 | 1066K| 1066K| 379K (0)|
|* 3 | INDEX FAST FULL SCAN| IND_T1_C1_C2 | 1 | 500 | 905 |00:00:00.05 | 1390 | | | |
|* 4 | INDEX FAST FULL SCAN| IND_T2_C1_C2 | 1 | 500 | 905 |00:00:00.05 | 1390 | | | |
----------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T1"."C2"="T2"."C2")
3 - filter("T1"."C2"=:N1)
4 - filter("T2"."C2"=:N1)
24 rows selected.
TARAL@taral >
TARAL@taral > EXEC :N1:=995
PL/SQL procedure successfully completed.
TARAL@taral >
TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
COUNT(*)
----------
25
TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8ygbsrkt6sqd9, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
T1.C2=T2.C2 AND T1.C2= :N1
Plan hash value: 765688747
----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.10 | 2780 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.10 | 2780 | | | |
|* 2 | HASH JOIN | | 1 | 250K| 25 |00:00:00.10 | 2780 | 1036K| 1036K| 351K (0)|
|* 3 | INDEX FAST FULL SCAN| IND_T1_C1_C2 | 1 | 500 | 5 |00:00:00.05 | 1390 | | | |
|* 4 | INDEX FAST FULL SCAN| IND_T2_C1_C2 | 1 | 500 | 5 |00:00:00.06 | 1390 | | | |
----------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T1"."C2"="T2"."C2")
3 - filter("T1"."C2"=:N1)
4 - filter("T2"."C2"=:N1)
24 rows selected.
So, from tkprof output here are the results which perfectely shows average rows as it had captured 4 occurences of the statement.
SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
FROM
T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.01 0 0 0 0
Fetch 8 0.98 1.02 4 11120 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 16 0.98 1.03 4 11120 0 4
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 4
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2780 pr=1 pw=0 time=0 us)
998001 701769 998001 HASH JOIN (cr=2780 pr=1 pw=0 time=429843 us cost=761 size=2000000 card=250000)
999 726 999 INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=33406 us cost=380 size=2000 card=500)(object id 74359)
999 726 999 INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=33505 us cost=380 size=2000 card=500)(object id 74360)
As, default aggregation is turned on if we make it off and then see tkprof output it display all 4 execution
SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
FROM
T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 2 0.31 0.33 4 2780 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.31 0.35 4 2780 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2780 pr=4 pw=0 time=0 us)
998001 998001 998001 HASH JOIN (cr=2780 pr=4 pw=0 time=596598 us cost=761 size=2000000 card=250000)
999 999 999 INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=2 pw=0 time=42664 us cost=380 size=2000 card=500)(object id 74359)
999 999 999 INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=2 pw=0 time=42415 us cost=380 size=2000 card=500)(object id 74360)
SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
FROM
T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
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 2 0.29 0.30 0 2780 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.29 0.30 0 2780 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
990025 990025 990025 HASH JOIN (cr=2780 pr=0 pw=0 time=596958 us cost=761 size=2000000 card=250000)
995 995 995 INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74359)
995 995 995 INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74360)
SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
FROM
T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
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 2 0.26 0.27 0 2780 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.26 0.27 0 2780 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
819025 819025 819025 HASH JOIN (cr=2780 pr=0 pw=0 time=525793 us cost=761 size=2000000 card=250000)
905 905 905 INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=47686 us cost=380 size=2000 card=500)(object id 74359)
905 905 905 INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=48364 us cost=380 size=2000 card=500)(object id 74360)
SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
FROM
T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
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 2 0.10 0.10 0 2780 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.10 0.10 0 2780 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
25 25 25 HASH JOIN (cr=2780 pr=0 pw=0 time=24 us cost=761 size=2000000 card=250000)
5 5 5 INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=408 us cost=380 size=2000 card=500)(object id 74359)
5 5 5 INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=376 us cost=380 size=2000 card=500)(object id 74360)
Categories: Utilities
