| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> RE: Tkprof output
A huge
thanks for all those who took the time out to respond to my problem. The query
ran to completion yesterday and (as I said to Lisa) I was later told that I was
not to worry as it was a one off migration (well that only wasted about 1- 2
hours of my time investigating and whatever it took you guys to help me
out).
<SPAN
class=281042407-31082001>
<SPAN
class=281042407-31082001>Grrrrrrrrr
<SPAN
class=281042407-31082001>
<SPAN
class=281042407-31082001>Lee
<SPAN
class=281042407-31082001>
<FONT face=Tahoma
size=2>-----Original Message-----From: Paul Baumgartel
[mailto:pbaumgartel_at_mortgagesight.com]Sent: 30 August 2001
19:31To: Multiple recipients of list ORACLE-LSubject:
RE: Tkprof output
Also note the
very high "query" number (i.e. buffers gotten for consistent read).
That could account for a lot of the i/o, which is the proximate cause of the
loooong elapsed time. From the (to use one of Lisa's favorite terms)
doco (for 9i):
Read
Consistency
Your system might spend excessive time rolling
back changes to blocks in order to maintain a consistent view. Consider the
following scenarios:
If there are
many small transactions and an active long-running query is running in the
background on the same table where the changes are happening, then the query
might need to roll back those changes often, in order to obtain a
read-consistent image of the table. Compare the following
V$SYSSTAT statistics to determine whether this is happening:
consistent
changes statistic indicates the number of times a database block has
rollback entries applied to perform a consistent read on the block.
Workloads that produce a great deal of consistent changes can consume a
great deal of resources.
consistent
gets statistic counts the number of logical reads in consistent mode.
If there are
few very, large rollback segments, then your system could be spending a lot
of time rolling back the transaction table during delayed block cleanout in
order to find out exactly which SCN a transaction was committed. The ratio
of the following V$SYSSTAT statistics should be close to 1:
ratio = transaction tables consistent reads undo records applied /
transaction tables consistent read rollbacks
A solution is to create more, smaller rollback segments, or to use automatic undo management.
Paul Baumgartel MortgageSight
Holdings, LLC pbaumgartel_at_mortgagesight.com
<FONT face=Tahoma
size=2>-----Original Message-----From: Koivu, Lisa
[mailto:lisa.koivu_at_efairfield.com]Sent: Thursday, August 30, 2001
12:47 PMTo: Multiple recipients of list
ORACLE-LSubject: RE: Tkprof output
Lee,
This query seems suspect
UPDATE VM_LIVE.SINGLE_CUSTOMER_HISTORY SCH SET
VISIBLE=1WHERE ACXIOM_CUSTOMER_KEY = :b1 AND VERSION_NO =
:b2
because of this
call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 39562
4.55
7.22 10897
118687
1
1Fetch
0 0.00
0.00
0
0
0 0-------
------ -------- ---------- ---------- ---------- ----------
----------total 39562
4.55
7.22 10897
118687
1 1
It's reading a ton of blocks to operate on ONE
record. What's the table structure here? What's the index
structure? Cardinality?
The buffer gets in the other queries are
suspect too. What's your blocksize? It's reading a ton of blocks
to arrive at the result.
-----Original Message----- <FONT
face=Arial size=1>From: <FONT face=Arial
size=1>Robertson Lee - lerobe [SMTP:lerobe_at_acxiom.co.uk]
Sent: <FONT
face=Arial size=1>Thursday, August 30, 2001 11:56 AM <FONT
face=Arial size=1>To: <FONT face=Arial
size=1>Multiple recipients of list ORACLE-L <FONT face=Arial
size=1>Subject: <FONT
face=Arial size=1>Tkprof output
Apologies for the length of the mail.
This query
is running for a mad amount of time, anyone any ideas. <FONT
face=Arial> Code and tkprof out
put shown below. <FONT
face=Arial size=2>Huge TIA
Lee (who must learn more about such things
!!!) <FONT face=Courier
size=1>DECLARE CURSOR TEMP_CDS ISSELECT
ACXIOM_CUSTOMER_KEY,
VERSION_NO,
ADDRESS_OCCUPANCY_KEYFROM
CUSTOMER_DETAIL_SOURCEWHERE VISIBLE=1; <FONT
face=Arial> COUNTER
NUMBER(8); <FONT
face=Courier size=1>BEGIN COUNTER:=0; FOR
I IN TEMP_CDS LOOP <FONT
face=Arial> <FONT face=Courier
size=1> UPDATE &SCHEMA..SINGLE_CUSTOMER
SC
SET VISIBLE =
1
WHERE
ACXIOM_CUSTOMER_KEY=I.ACXIOM_CUSTOMER_KEY
AND VERSION_NO
=I.VERSION_NO; <FONT
face=Courier size=1> UPDATE
&SCHEMA..SINGLE_CUSTOMER_HISTORY
SCH
SET VISIBLE =
1
WHERE
ACXIOM_CUSTOMER_KEY=I.ACXIOM_CUSTOMER_KEY
AND VERSION_NO
=I.VERSION_NO; <FONT
face=Courier size=1> UPDATE
&SCHEMA..ADDRESS_OCCUPANCY
AO
SET VISIBLE =
1
WHERE ADDRESS_OCCUPANCY_KEY = I.ADDRESS_OCCUPANCY_KEY; <FONT
face=Arial> <FONT face=Courier
size=1> COUNTER := COUNTER +
1; IF (COUNTER =
50000)
THEN
COUNTER:=0;
COMMIT; END IF; END
LOOP; COMMIT;
Sort options: prsela exeela
fchela ********************************************************************************count
= number of times OCI procedure was
executedcpu = cpu time in seconds
executingelapsed = elapsed time in seconds
executingdisk = number of physical reads of
buffers from diskquery = number of buffers gotten
for consistent readcurrent = number of buffers gotten in current
mode (usually for update)rows = number of rows
processed by the fetch or execute
call********************************************************************************
UPDATE
VM_LIVE.SINGLE_CUSTOMER SC SET
VISIBLE=1WHERE ACXIOM_CUSTOMER_KEY = :b1 AND VERSION_NO
= :b2 <FONT face=Courier
size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 39562
15.51 398.98
56555 181085
40672
39562Fetch
0 0.00
0.00
0
0
0 0-------
------ -------- ---------- ---------- ---------- ----------
----------total 39562
15.51 398.98
56555 181085
40672 39562 <FONT
face=Arial> Misses in library
cache during parse: 0Misses in library cache during execute:
1Optimizer goal: CHOOSEParsing user id: 39
(VM_LIVE) (recursive depth: 1) <FONT
face=Arial> <FONT face=Courier
size=1>Rows Execution Plan-------
---------------------------------------------------
0 UPDATE STATEMENT GOAL:
CHOOSE 0 UPDATE OF
'SINGLE_CUSTOMER' 0
TABLE ACCESS (BY INDEX ROWID) OF
'SINGLE_CUSTOMER'
0 INDEX (UNIQUE SCAN) OF 'SINGLE_CUSTOMER_PK'
(UNIQUE) <FONT face=Courier
size=1>********************************************************************************
UPDATE
VM_LIVE.ADDRESS_OCCUPANCY AO SET
VISIBLE=1WHERE ADDRESS_OCCUPANCY_KEY = :b1 <FONT
face=Arial> <FONT face=Courier
size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 39562
12.57 186.88
57285 124038
40726
39562Fetch
0 0.00
0.00
0
0
0 0-------
------ -------- ---------- ---------- ---------- ----------
----------total 39562
12.57 186.88
57285 124038
40726 39562 <FONT
face=Arial> Misses in library
cache during parse: 0Optimizer goal: CHOOSEParsing user id:
39 (VM_LIVE) (recursive depth: 1) <FONT
face=Arial> <FONT face=Courier
size=1>Rows Execution Plan-------
---------------------------------------------------
0 UPDATE STATEMENT GOAL:
CHOOSE 0 UPDATE OF
'ADDRESS_OCCUPANCY' 0
INDEX (UNIQUE SCAN) OF 'I_ADDRESS_OCCUPANCY_I4' (UNIQUE) <FONT
face=Arial> <FONT face=Courier
size=1>********************************************************************************
UPDATE
VM_LIVE.SINGLE_CUSTOMER_HISTORY SCH SET
VISIBLE=1WHERE ACXIOM_CUSTOMER_KEY = :b1 AND VERSION_NO
= :b2 <FONT face=Courier
size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 39562
4.55
7.22 10897
118687
1
1Fetch
0 0.00
0.00
0
0
0 0-------
------ -------- ---------- ---------- ---------- ----------
----------total 39562
4.55
7.22 10897
118687
1 1
Misses in
library cache during parse: 0Optimizer goal: CHOOSEParsing user
id: 39 (VM_LIVE) (recursive depth: 1) <FONT
face=Arial> <FONT face=Courier
size=1>Rows Execution Plan-------
---------------------------------------------------
0 UPDATE STATEMENT GOAL:
CHOOSE 0 UPDATE OF
'SINGLE_CUSTOMER_HISTORY'
0 INDEX (UNIQUE SCAN) OF 'SINGLE_CUSTOMER_HISTORY_PK'
(UNIQUE) <FONT face=Courier
size=1>********************************************************************************
SELECT
ACXIOM_CUSTOMER_KEY,VERSION_NO,ADDRESS_OCCUPANCY_KEY FROM CUSTOMER_DETAIL_SOURCE
WHERE VISIBLE = 1 <FONT
face=Courier size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 0
0.00
0.00
0
0
0
0Fetch 39562
1.51
2.04
392
39618
0 39562------- ------
-------- ---------- ---------- ---------- ----------
----------total 39562
1.51
2.04
392
39618
0 39562 <FONT
face=Arial> Misses in library
cache during parse: 0Parsing user id: 39 (VM_LIVE)
(recursive depth: 1) <FONT
face=Arial> <FONT
face=Courier
size=1>********************************************************************************
OVERALL
TOTALS FOR ALL NON-RECURSIVE STATEMENTS <FONT
face=Arial> <FONT face=Courier
size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0
0Execute 0
0.00
0.00
0
0
0
0Fetch
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
OVERALL TOTALS FOR ALL RECURSIVE
STATEMENTS <FONT
face=Courier size=1>call
count cpu
elapsed
disk query
current rows-------
------ -------- ---------- ---------- ---------- ----------
----------Parse
0 0.00
0.00
0
0
0 0Execute
118686 32.63
593.08 124737
423810
81399 79125Fetch
39562
1.51
2.04
392
39618
0 39562------- ------
-------- ---------- ---------- ---------- ----------
----------total 158248
34.14 595.12
125129 463428
81399 118687 <FONT
face=Arial> Misses in library
cache during parse: 0Misses in library cache during execute: 1
<FONT face=Courier
size=1> 4 user SQL statements in
session. 0 internal SQL statements in
session. 4 SQL statements in
session. 3 statements EXPLAINed in this
session.********************************************************************************Trace
file: ora_349778.trcTrace file compatibility: 7.03.02Sort options:
prsela exeela
fchela 1 session in
tracefile. 4 user SQL
statements in trace file. 0
internal SQL statements in trace
file. 4 SQL statements in
trace file. 4 unique SQL
statements in trace file. 3
SQL statements EXPLAINed using
schema:
VM_LIVE.prof$plan_table
Default table was
used.
Table was
created.
Table was dropped. 158286 lines in trace file.
The information contained in this
communication isconfidential, is intended only for the use of the
recipientnamed above, and may be legally privileged. If the
readerof this message is not the intended recipient, you arehereby
notified that any dissemination, distribution orcopying of this
communication is strictly prohibited.If you have received this
communication in error, pleasere-send this communication to the sender
and delete theoriginal message or any copy of it from your
computersystem.
Received on Fri Aug 31 2001 - 04:18:04 CDT
 |
 |