Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> RE: Tkprof output

RE: Tkprof output

From: Robertson Lee - lerobe <lerobe_at_acxiom.co.uk>
Date: Fri, 31 Aug 2001 02:18:04 -0700
Message-ID: <F001.0037E925.20010831002618@fatcity.com>

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

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US