6 Replies Latest reply on Dec 18, 2012 5:35 PM by user12066030

    Elapsed time from wait events is higher than "elapsed" in tkprof output

    905989
      Hi

      This is Oracle11g R2 on 8K block

      I am running the following simple OLTP type tests. SElecting 1.7 million rows into an associateive array and updating another table where object_id match (via index key)
      EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true, plan_stat=>'ALL_EXECUTIONS' );
      DECLARE
              type ObjIdArray is table of tdash.object_id%TYPE index by binary_integer;
              l_ids objIdArray;
              CURSOR c IS SELECT object_id FROM tdash;
      BEGIN
              OPEN c;
              LOOP
                      BEGIN
                              FETCH c BULK COLLECT INTO l_ids LIMIT 100;
      
                              FORALL rs in 1 .. l_ids.COUNT
                                      UPDATE testwrites
                                        SET PADDING1 =  RPAD('y',4000,'y')
                                      WHERE object_id = l_ids(rs);
                              commit;
                              FORALL rs in 1 .. l_ids.COUNT
                                      DELETE FROM testwrites
                                      WHERE object_id = l_ids(rs);
                              commit;
                              FORALL rs in 1 .. l_ids.COUNT
                                      INSERT INTO testwrites
                                      SELECT * FROM tdash t WHERE t.object_id = l_ids(rs);
                              commit;
                              EXIT WHEN C%NOTFOUND;
                      EXCEPTION
                        WHEN NO_DATA_FOUND THEN
                          NULL;
                        WHEN OTHERS THEN
                          DBMS_OUTPUT.PUT_LINE('Transaction failed');
                      END;
              END LOOP;
              CLOSE c;
      END;
      TKPROF output for update only
      UPDATE TESTWRITES SET PADDING1 = RPAD('y',4000,'y')
      WHERE
      OBJECT_ID = :B1
      
      
      call     count       cpu    elapsed       disk      query    current        rows
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      Parse        4      0.00       0.00          0          0          0           0
      Execute  17293     21.62    1245.41    1064667    2411398    6280588     1000000
      Fetch        0      0.00       0.00          0          0          0           0
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      total    17297     21.62    1245.41    1064667    2411398    6280588     1000000
      
      Misses in library cache during parse: 1
      Misses in library cache during execute: 1
      Optimizer mode: ALL_ROWS
      Parsing user id: 93     (recursive depth: 1)
      
      Rows     Row Source Operation
      -------  ---------------------------------------------------
            0  UPDATE  TESTWRITES (cr=214 pr=427 pw=0 time=0 us)
          100   INDEX UNIQUE SCAN TESTWRITES_PK (cr=110 pr=3 pw=0 time=0 us cost=2 size=4007 card=1)(object id 92380)
      
      
      Elapsed times include waiting on following events:
        Event waited on                             Times   Max. Wait  Total Waited
        ----------------------------------------   Waited  ----------  ------------
        Disk file operations I/O                        2        0.00          0.00
        db file sequential read                   2160263        1.57       2304.22
        db file scattered read                      27769        0.26         99.78
        
      *******************************************************************************
      
      SQL ID: 8ggw94h7mvxd7
      Plan Hash: 0
      COMMIT
      
      
      call     count       cpu    elapsed       disk      query    current        rows
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      Parse    51879      0.16       0.35          0          0          0           0
      Execute  51879      1.82       6.29          0          0      37301           0
      Fetch        0      0.00       0.00          0          0          0           0
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      total   103758      1.98       6.65          0          0      37301           0
      
      Misses in library cache during parse: 0
      Parsing user id: 93     (recursive depth: 1)
      
      Elapsed times include waiting on following events:
        Event waited on                             Times   Max. Wait  Total Waited
        ----------------------------------------   Waited  ----------  ------------
        log file switch completion                      1        0.05          0.05
        db file sequential read                    121686        1.39        162.95
        log buffer space                                2        0.98          0.99
        log file switch (private strand flush incomplete)
                                                        1        1.47          1.47
      ********************************************************************************
      Now why my elapsed times for updates from wait events 2304.22+ 99.78 = 2404 sec is HIGHER than my elapsed time of 1245.21 sec? I don't think it can be explained purely due to different clock granularities

      Thanks