Home » RDBMS Server » Performance Tuning » TKPROF Output Understanding (Oracle 10g,10.2.0.3.0,AIX)
| TKPROF Output Understanding [message #460063] |
Wed, 09 June 2010 08:08  |
rajatratewal
Messages: 507
Registered: March 2008
Location: INDIA
|
Senior Member |
|
|
Dear All,
Hope you are doing great.
I need your help in understanding the TKPROF output for the
session that was executing an insert statement(inserting 70
lakh data) on which a row level trigger get fired and select
from following table.The trace was run for 1 hour.
Table name - > GS_MAP_RCC_CCIT
This table is having 37 rows as in on single block and having
primary key index on RCC_NUM that is also contained
on single block.We are getting maximum wait events on
db_file_sequential_read.
As per my understanding this is due to the contention for
the same block because for each row these queries get fired.
Kindly guide me if my understanding is wrong as my DBA says
this is not the issue.
Kindly guide me what i am missing here.
Regards,
Rajat
|
|
|
|
| Re: TKPROF Output Understanding [message #460082 is a reply to message #460063] |
Wed, 09 June 2010 09:05  |
cookiemonster
Messages: 13922
Registered: September 2008
Location: Rainy Manchester
|
Senior Member |
|
|
You're missing a trace that actually includes the triggering insert statement for starters.
db_file_sequential_read is an index read, I'm not sure if it means there is contention on block necessarily.
You might want to have a read of this ask tom thread.
|
|
|
|
|
|
| Re: TKPROF Output Understanding [message #460104 is a reply to message #460083] |
Wed, 09 June 2010 11:48 |
rajatratewal
Messages: 507
Registered: March 2008
Location: INDIA
|
Senior Member |
|
|
Quote:>We are getting maximum wait events on db_file_sequential_read.
too bad you did not use COPY & PASTE so we could see for ourselves & then make our own conclusion.
I am unaware of any Oracle utility that reports "maximum wait events".
BlackSwan i was interested in knowing the conclusion that we can get by looking at TKPROF output.That's why i have attached the TKPROF text file in my post and given a brief overview about the table and operation that was happening.I understand that the information is not sufficient for analysis.
Background
1) Trace file time 1 hour
2) Operation the SQL was performing is insert into tab1 select * from tab2 [70 lacs records]
3) Thier is a row level trigger on tab1 that populates column CCIT_CODE in table based on RCC_NUM
by firing following select
SELECT CCIT_CODE
FROM
GS_MAP_RCC_CCIT WHERE RCC_NUM=:B1
There is a
GS_MAP_RCC_CCIT is a very small table having only 37 rows that are contained on a single block.
It has RCC_NUM as primary key and have a index that is also contained on a single block.
Issue in following part in TKPROF
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 635909 0.57 3546.72
gc current grant 2-way 337544 0.10 118.41
gc cr multi block request 166 0.00 0.07
db file scattered read 321 0.01 0.82
row cache lock 368 0.00 0.03
library cache lock 2 0.00 0.00
gc current grant busy 1 0.00 0.00
gc current multi block request 1164 0.00 0.21
enq: FB - contention 117 0.00 0.04
gc cr grant 2-way 7 0.00 0.00
log file switch completion 8 0.39 0.53
enq: HW - contention 14 0.04 0.05
enq: TT - contention 1 0.00 0.00
latch: KCL gc element parent latch 1 0.00 0.00
The trace file is for 1 hour duration and Total Waited for db file sequential read is 3546 seconds almost 59 minutes.
As we check the very first statement thier are exactly 2 times consistent gets for each execute.Means one for
index block and then for table block leading to contention.The difference between cpu and elapsed shows physical I/O.
SELECT CCIT_CODE
FROM
GS_MAP_RCC_CCIT WHERE RCC_NUM=:B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 152132 17.10 139.27 0 0 0 0
Fetch 152132 0.61 3.03 0 304264 0 152132
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 304264 17.71 142.30 0 304264 0 152132
This is the issue i got last month the operation took 3 days to complete for inserting 70 lacs records in a table
that was a simple insert into tab1 select * from tab2.
When i asked for a trace then in session only these statements came.As i studied TKPROF i am not getting anywhere.
Because when i look at stats thier i found no reason other then contention
for 1 hour execution the waiting time is 3546.72 seconds i.e around 59 minutes and i.e db_file_sequential_read and the only table
having index is GS_MAP_RCC_CCIT on RCC_NUM.
Hope that clarifies and you can guide me in the same.
Complete TKPROF text
TKPROF: Release 10.2.0.3.0 - Production on Thu May 27 15:41:56 2010
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: rcc1_ora_10207954.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SELECT CCIT_CODE
FROM
GS_MAP_RCC_CCIT WHERE RCC_NUM=:B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 152132 17.10 139.27 0 0 0 0
Fetch 152132 0.61 3.03 0 304264 0 152132
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 304264 17.71 142.30 0 304264 0 152132
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 58 (recursive depth: 2)
********************************************************************************
SELECT USER
FROM
SYS.DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 152132 19.19 101.36 0 0 0 0
Fetch 152132 0.34 0.68 0 0 0 152132
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 304264 19.53 102.05 0 0 0 152132
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 62 (recursive depth: 2)
********************************************************************************
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
ist.logicalread
from
ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 2 9 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 2 9 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.00 0.00
gc current block 2-way 1 0.00 0.00
********************************************************************************
select pos#,intcol#,col#,spare1,bo#,spare2
from
icol$ where obj#=: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 2 0.00 0.00 1 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 1 4 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=4 pr=1 pw=0 time=393 us)
1 INDEX RANGE SCAN I_ICOL1 (cr=3 pr=1 pw=0 time=388 us)(object id 40)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache lock 1 0.00 0.00
db file sequential read 1 0.00 0.00
********************************************************************************
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
nvl(spare3,0)
from
col$ where obj#=:1 order by intcol#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 11 0.00 0.00 0 3 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.00 0.00 0 3 0 10
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
********************************************************************************
select con#,obj#,rcon#,enabled,nvl(defer,0)
from
cdef$ where robj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 1 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
library cache lock 1 0.00 0.00
********************************************************************************
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),
rowid,cols,nvl(defer,0),mtime,nvl(spare1,0)
from
cdef$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 25 0.00 0.00 0 30 0 23
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 27 0.00 0.00 0 30 0 23
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
********************************************************************************
select intcol#,nvl(pos#,0),col#,nvl(spare1,0)
from
ccol$ where con#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 23 0.00 0.00 0 0 0 0
Fetch 46 0.00 0.00 1 115 0 23
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 70 0.00 0.00 1 115 0 23
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID CCOL$ (cr=5 pr=1 pw=0 time=6027 us)
1 INDEX RANGE SCAN I_CCOL1 (cr=4 pr=1 pw=0 time=6019 us)(object id 54)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 and col# is not null group by privilege#, col#,
grantee# order by col#, grantee#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 1 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by
grantee#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
********************************************************************************
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,
cache=:7,highwater=:8,audit$=:9,flags=:10
where
obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 304 0.01 0.01 0 0 0 0
Execute 304 0.05 0.21 0 304 608 304
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 608 0.06 0.23 0 304 608 304
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE SEQ$ (cr=1 pr=0 pw=0 time=162 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=11 us)(object id 102)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache lock 3 0.00 0.00
row cache lock 10 0.00 0.00
gc current block 2-way 1 0.00 0.00
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 22 0.00 0.00 0 0 0 0
Fetch 22 0.00 0.01 2 66 0 22
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 45 0.00 0.01 2 66 0 22
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 3)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=2 pw=0 time=15583 us)
1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=1 pw=0 time=9219 us)(object id 257)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.00 0.01
********************************************************************************
select file#
from
file$ where ts#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 9 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 90 0.00 0.00 0 171 0 81
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 108 0.00 0.00 0 171 0 81
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
8 TABLE ACCESS BY INDEX ROWID FILE$ (cr=17 pr=0 pw=0 time=35 us)
8 INDEX RANGE SCAN I_FILE2 (cr=9 pr=0 pw=0 time=47 us)(object id 42)
********************************************************************************
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=
:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),
groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=
DECODE(:17,0,NULL,:17),scanhint=:18
where
ts#=:1 and file#=:2 and block#=:3
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.02 0.00 0 0 0 0
Execute 5 0.00 0.03 4 66 5 5
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.02 0.04 4 66 5 5
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 UPDATE SEG$ (cr=6 pr=2 pw=0 time=13276 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=6 pr=2 pw=0 time=13135 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=3 pr=1 pw=0 time=5688 us)(object id 9)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 12 0.00 0.00
gc cr grant 2-way 2 0.00 0.00
db file sequential read 4 0.00 0.01
gc current block 2-way 1 0.00 0.00
gc current grant busy 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 635909 0.57 3546.72
gc current grant 2-way 337544 0.10 118.41
gc cr multi block request 166 0.00 0.07
db file scattered read 321 0.01 0.82
row cache lock 368 0.00 0.03
library cache lock 2 0.00 0.00
gc current grant busy 1 0.00 0.00
gc current multi block request 1164 0.00 0.21
enq: FB - contention 117 0.00 0.04
gc cr grant 2-way 7 0.00 0.00
log file switch completion 8 0.39 0.53
enq: HW - contention 14 0.04 0.05
enq: TT - contention 1 0.00 0.00
latch: KCL gc element parent latch 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 321 0.03 0.02 0 0 0 0
Execute 304638 36.34 240.89 4 370 613 309
Fetch 304468 0.95 3.75 8 304674 0 304425
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 609427 37.32 244.68 12 305044 613 304734
Misses in library cache during parse: 2
Misses in library cache during execute: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 12 0.00 0.05
row cache lock 22 0.00 0.00
library cache lock 3 0.00 0.00
gc current block 2-way 3 0.00 0.00
gc current grant busy 1 0.00 0.00
gc cr grant 2-way 2 0.00 0.00
2 user SQL statements in session.
374 internal SQL statements in session.
376 SQL statements in session.
********************************************************************************
Trace file: rcc1_ora_10207954.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
374 internal SQL statements in trace file.
376 SQL statements in trace file.
14 unique SQL statements in trace file.
2821692 lines in trace file.
4087 elapsed seconds in trace file.
|
|
|
|
|
|
| Re: TKPROF Output Understanding [message #460109 is a reply to message #460107] |
Wed, 09 June 2010 12:39 |
rajatratewal
Messages: 507
Registered: March 2008
Location: INDIA
|
Senior Member |
|
|
Dear Blackswan,
Thanks for the inputs.I have to check with the DBA for the same.And i am afraid that he might not be having that also as it was last month issue and at that time i also don't have any good explanation for the same.And that trace file was also large in size so the DBA only given the TKPROF.Somehow the process RAN for 3 days and completed but i don't want the same thing to be repeated again and just for the curiosity i asked this question to you guys so that someone might give some idea by looking at TKPROF.
One thing i need to ask as you are saying that these might be some other session stats but is that possible as normally DBA run trace for a single session.
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid,serial#,false);
So how it will include stats for some other session.
Sorry i missed one point in previous post about this table.
GS_MAP_RCC_CCIT
This table is used by 10 modules each having it's own schema in a single database and virtually every table is having a trigger that uses this table i.e same select in trace provided.So single point of contention in system.
Anyways thanks for the help and support.
Regards,
Rajat
|
|
|
|
|
|
| Re: TKPROF Output Understanding [message #460116 is a reply to message #460111] |
Wed, 09 June 2010 14:27 |
cookiemonster
Messages: 13922
Registered: September 2008
Location: Rainy Manchester
|
Senior Member |
|
|
The db file sequential reads could be coming from the insert/select itself which isn't recorded in the tkprof.
You need to run another trace and this time start the trace before executing the insert statement.
|
|
|
|
| Re: TKPROF Output Understanding [message #460147 is a reply to message #460116] |
Wed, 09 June 2010 21:26 |
rajatratewal
Messages: 507
Registered: March 2008
Location: INDIA
|
Senior Member |
|
|
Dear BlackSwan and Cookiemonster,
Thanks for the inputs and help.I will try to get the trace from the DBA if he has not deleted the same.If not possible i will try to simulate the same and share the trace and TKPROF.
Quote:The db file sequential reads could be coming from the insert/select itself which isn't recorded in the tkprof.
You need to run another trace and this time start the trace before executing the insert statement.
This can't be done as this is not running right now.After the insert was taking time then only trace was run.One confusion is there if suppose i am doing
insert into tab1 select * from tab2
where there is lot of data in tab2 70 lac and their are many indexes on tab1 suppose 7 composite indexes that is obviously a very bad design then can we have db file sequential read because of the indexes created on tab1.
Anyways i will try to get that trace and get back with the same
or try some simulation.Thanks for the help once again.
Regards,
Rajat Ratewal
|
|
|
|
|
|
| Re: TKPROF Output Understanding [message #460355 is a reply to message #460151] |
Thu, 10 June 2010 13:16 |
rajatratewal
Messages: 507
Registered: March 2008
Location: INDIA
|
Senior Member |
|
|
Hi BlackSwan,
I discussed with the DBA he has already deleted the trace.Anyways i thought to try some trace myself on my development machine.
I ran the trace for just 10 minutes for a very small set of data to understand RAW trace and TKPROF in a better way.
I Executed the insert 7 times before commiting while trace was enabled for the session.
Never mind i will post the results once i prepare the data for testing and run a trace again on realistic data.
Sorry i am asking questions without providing any proper test cases.But i will revert back soon with all the details.
Table structures,triggers,indexes etc.
But as it will take time to simulate.Here we go.
Here are some new findings on a very small set 204092 rows to insert and executed statement for 7 times.
1) The current field value in explain plan in TKPROF for insert is quite high.This shows some update is happening.
only then we see values in current.Below is the snippet from RAW trace showing insert activity.
RAW Trace Snippet
PARSING IN CURSOR #3 len=1373 dep=0 uid=62 oct=2 lid=62 tim=2051952555132 hv=1772895516 ad='3d2b7848'
INSERT INTO ES_TXN_ITS(
TXN_SEQ_NO,
ITS_POP_DATE,
FIN_YEAR,
RRR_NO,
RRR_DATE,
JNT_TXN_PTY_CNT,
TXN_DATE,
TXN_PTY_PAN,
TXN_PTY_NAME,
PAN_NAME_AIS,
NAME_MATCH_FLAG,
TXN_PTY_ADDR_FLAT,
TXN_PTY_ADDR_FLOOR,
TXN_PTY_ADDR_BUILDING,
TXN_PTY_ADDR_BLOCK_SECTOR,
TXN_PTY_ADDR_COLONY,
TXN_PTY_ADDR_CITY,
TXN_PTY_ADDR_STATE_CODE,
TXN_PTY_ADDR_PIN,
TXN_TYPE,
TXN_CODE,
TXN_AMOUNT,
TXN_FILER_TAN,
RETAINED_PAN,
RCC_NUM,
TDS_26AS_TXN_CNT
)
SELECT
EQ_ITS_TXN_NO.NEXTVAL,
SYSDATE,
FINANCIAL_YEAR,
999999999,
TO_DATE('31/03/2009','DD/MM/YYYY'),
'1',TO_DATE('31/03/2009','DD/MM/YYYY'),
TAN_PAN,
NAME,
NAME_AS_AIS,
'N',
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,1,8),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,9,3),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,13,25),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,39,4),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,44,60),
ADD_LINE5,
ADD_STATE,
ADD_PIN,
TXN_TYPE,
TXN_ID,
CHALLAN_TOTAL,
'OT001',
TAN_PAN,
RCC_NUM_AS_FORM49A,
TXN_TOTAL
FROM es_oltas_its_grp_tab2009 LOG ERRORS INTO ERROR_LOG_GRP_TAB_ITS REJECT LIMIT UNLIMITED
END OF STMT
PARSE #3:c=30000,e=253974,p=34,cr=227,cu=6,mis=1,r=0,dep=0,og=1,tim=2051952555129
=====================
PARSING IN CURSOR #5 len=102 dep=1 uid=0 oct=3 lid=0 tim=2051952559494 hv=3967354608 ad='6e7974f0'
select increment$,minvalue,maxvalue,cycle#,order$,cache,highwater,audit$,flags from seq$ where obj#=:1
END OF STMT
PARSE #5:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952559492
EXEC #5:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952559621
FETCH #5:c=0,e=26,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2051952559667
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=68 op='TABLE ACCESS BY INDEX ROWID SEQ$ (cr=2 pr=0 pw=0 time=24 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=9 us)'
=====================
PARSING IN CURSOR #5 len=129 dep=1 uid=0 oct=6 lid=0 tim=2051952559774 hv=2635489469 ad='6e8eef68'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952559772
EXEC #5:c=0,e=164,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=2051952560042
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=139 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=6 us)'
=====================
PARSING IN CURSOR #5 len=56 dep=1 uid=58 oct=3 lid=58 tim=2051952560349 hv=3979607393 ad='6e944370'
SELECT CCIT_CODE FROM GS_MAP_RCC_CCIT WHERE RCC_NUM=:B1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952560347
EXEC #5:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952560457
FETCH #5:c=0,e=20,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952560495
EXEC #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952560596
FETCH #4:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952560615
=====================
PARSING IN CURSOR #6 len=129 dep=1 uid=0 oct=6 lid=0 tim=2051952636666 hv=2635489469 ad='6e8eef68'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1
END OF STMT
PARSE #6:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952636663
EXEC #6:c=0,e=155,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=2051952636943
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=127 us)'
STAT #6 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=10 us)'
EXEC #5:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952637128
FETCH #5:c=0,e=16,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952637162
EXEC #4:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952637222
FETCH #4:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952637239
Maximum part of trace contains these lines
=====================
PARSING IN CURSOR #6 len=129 dep=1 uid=0 oct=6 lid=0 tim=2051952640610 hv=2635489469 ad='6e8eef68'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1
END OF STMT
PARSE #6:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952640607
EXEC #6:c=0,e=141,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=2051952640864
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=117 us)'
STAT #6 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=7 us)'
EXEC #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952641031
FETCH #5:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952641062
EXEC #4:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2051952641120
FETCH #4:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=2051952641138
=====================
Quote: Now i might have heard it somewhere the issue can be slow select of sequence due to poor cache value for sequence.
Cache value is low for the sequence 500 only.Is this the slow select for the sequence can be a reason for poor running of query.
PARSING IN CURSOR #5 len=129 dep=1 uid=0 oct=6 lid=0 tim=2051952559774 hv=2635489469 ad='6e8eef68'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2051952559772
EXEC #5:c=0,e=164,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=2051952560042
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=139 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=6 us)'
TKPROF Snippet
INSERT INTO ES_TXN_ITS(
TXN_SEQ_NO,
ITS_POP_DATE,
FIN_YEAR,
RRR_NO,
RRR_DATE,
JNT_TXN_PTY_CNT,
TXN_DATE,
TXN_PTY_PAN,
TXN_PTY_NAME,
PAN_NAME_AIS,
NAME_MATCH_FLAG,
TXN_PTY_ADDR_FLAT,
TXN_PTY_ADDR_FLOOR,
TXN_PTY_ADDR_BUILDING,
TXN_PTY_ADDR_BLOCK_SECTOR,
TXN_PTY_ADDR_COLONY,
TXN_PTY_ADDR_CITY,
TXN_PTY_ADDR_STATE_CODE,
TXN_PTY_ADDR_PIN,
TXN_TYPE,
TXN_CODE,
TXN_AMOUNT,
TXN_FILER_TAN,
RETAINED_PAN,
RCC_NUM,
TDS_26AS_TXN_CNT
)
SELECT
EQ_ITS_TXN_NO.NEXTVAL,
SYSDATE,
FINANCIAL_YEAR,
999999999,
TO_DATE('31/03/2009','DD/MM/YYYY'),
'1',TO_DATE('31/03/2009','DD/MM/YYYY'),
TAN_PAN,
NAME,
NAME_AS_AIS,
'N',
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,1,8),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,9,3),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,13,25),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,39,4),
SUBSTR(ADD_LINE1||ADD_LINE2||ADD_LINE3||ADD_LINE4,44,60),
ADD_LINE5,
ADD_STATE,
ADD_PIN,
TXN_TYPE,
TXN_ID,
CHALLAN_TOTAL,
'OT001',
TAN_PAN,
RCC_NUM_AS_FORM49A,
TXN_TOTAL
FROM es_oltas_its_grp_tab2009 LOG ERRORS INTO ERROR_LOG_GRP_TAB_ITS REJECT LIMIT UNLIMITED
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.01 0.06 0 0 2 0
Execute 7 136.82 226.72 25259 58548 6167025 204092
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 136.83 226.78 25259 58548 6167027 204092
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 62 (EFS)
Rows Row Source Operation
------- ---------------------------------------------------
29156 SEQUENCE EQ_ITS_TXN_NO (cr=29638 pr=459 pw=0 time=11258383 us)
29156 TABLE ACCESS FULL ET_OLTAS_ITS_GRP_TAB2009 (cr=476 pr=459 pw=0 time=58360 us)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT MODE: ALL_ROWS
29156 SEQUENCE OF 'EQ_ITS_TXN_NO' (SEQUENCE)
29156 TABLE ACCESS MODE: ANALYZED (FULL) OF
'ET_OLTAS_ITS_GRP_TAB2009' (TABLE)
********************************************************************************
SELECT CCIT_CODE
FROM
GS_MAP_RCC_CCIT WHERE RCC_NUM=:B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 204092 6.37 7.93 0 0 0 0
Fetch 204092 2.36 2.51 0 408184 0 204092
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 408185 8.73 10.44 0 408184 0 204092
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 58 (ITDBA) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'T_MAP_RCC_CCIT' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'PKG_GB_MAP_CCIT_RCC'
(INDEX (UNIQUE))
********************************************************************************
Regards,
Rajat Ratewal
|
|
|
|
|
|
|
|
|
|
| Re: TKPROF Output Understanding [message #460994 is a reply to message #460063] |
Wed, 16 June 2010 00:44 |
michael_bialik
Messages: 621
Registered: July 2006
|
Senior Member |
|
|
1. Is it possible to change the insert statement and to disable the trigger?
INSERT INTO ES_TXN_ITS( ..., CCIT_CODE
SELECT ...,
CCIT_CODE
FROM es_oltas_its_grp_tab2009
JOIN GS_MAP_RCC_CCIT CCIT ON CCIT.RCC_NUM = es_oltas_its_grp_tab2009.<column_name>
LOG ERRORS INTO ERROR_LOG_GRP_TAB_ITS REJECT LIMIT UNLIMITED
2. Can you do the same with
statement as well?
3. As Cookiemonster already mentioned: probably the waits are caused by insert statement itself. So can you drop the indexes
before insert and recreate them afterwards?
HTH.
|
|
|
|
Goto Forum:
Current Time: Mon May 13 14:01:05 CDT 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
