1 2 3 4 Previous Next 46 Replies Latest reply on Jan 10, 2018 6:22 PM by Bob Bryla

    Insert is running long with more waits on DB FILE SEQUENTIAL READS.

    3204324

      DB version 12.1.0.2.0

       

      One of the insert is running long with lot of DB file sequential reads.

       

      Below is SQL TEXT.

       

      INSERT INTO Atrtw.EMprte_rty(EMP_SEQ_ID,ARC_DT,ARC_B

      ATCH_NM,EMP_INTRL_ID,DATA_DUMP_DT,TAX_ID_NB,COST_C

      TR_ID,FIRST_NM,LAST_NM,MIDL_NM,TITL_NM,EMP_STAT_CD

      ,EMP_CMPY_NM,PART_FULL_TM_CD,FULL_NM,JOB_DESC_TX,E

      MP_HIRE_DT,EMP_TERM_DT,EMP_TYPE_CD,SRC_SYS_CD,TRDR

      _RGSTN_ID,TRDR_REP_ROLE_CD,LINE_ORG_NM,LINE_ORG_IN

      TRL_ID,OFC_ID,OFC_ADDR_LINE1_TX,OFC_ADDR_LINE2_TX,

      SUPVSR_EMP_INTRL_ID,CSTM_1_TX,CSTM_2_TX,CSTM_3_TX,

      CSTM_4_TX,CSTM_5_TX,CSTM_1_DT,CSTM_2_DT,CSTM_3_DT,

      CSTM_1_RL,CSTM_2_RL,CSTM_3_RL,PRCSNG_BATCH_NM,JRSD

      CN_CD,BUS_DMN_LIST_TX,TAX_ID_FRMT_CD,SPRVSRY_ORG_I

      NTRL_ID,SRVC_TEAM_INTRL_ID,NTWK_LOGON_ID,SPRVSN_CD

      ,BRNCH_OFFC_MGR_FL)  VALUES ( :1, :2, :3, :4, :5,

      :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16,

      :17, :18, :19, :20, :21, :22, :23, :24, :25, :26,

      :27, :28, :29, :30, :31, :32, :33, :34, :35, :36,

      :37, :38, :39, :40, :41, :42, :43, :44, :45, :46,

      :47, :48

      Below are wait events.

       

      UNDEFINE SE.SID

      select se.sid, se.event, se.total_waits, se.time_waited/100 time_waitedseconds,

      se.average_wait/100 average_waitseconds,max_wait/100 max_waitsec

      from gv$session_event se, gv$session ss

      where time_waited > 0

      and se.sid=ss.sid

      and ss.username is not NULL

      and ss.sid='&SID'

      and ss.serial#='&serial'

      order by 4;

       

       

       

        SID EVENT                                                                  TOTAL_WAITS TIME_WAITEDSECONDS AVERAGE_WAITSECONDS MAX_WAITSEC

      ----- ---------------------------------------------------------------------- ----------- ------------------ ------------------- -----------

      8890 gc buffer busy release                                                          1                .01               .0055         .01

      8890 gc current grant busy                                                           16                .01               .0007           0

      8890 resmgr:internal state change                                                     2                 .2               .1001          .1

      8890 events in waitclass Other                                                      323                .21               .0006          .2

      8890 SQL*Net more data from client                                                 2130                .33               .0002         .06

      8890 gc current block lost                                                            3               1.14               .3787         .64

      8890 SQL*Net message from client                                                    735               1.26               .0017         .06

      8890 log file switch (checkpoint incomplete)                                         29               2.36               .0814          .5

      8890 log file switch completion                                                      58                2.5               .0431         .15

      8890 resmgr:cpu quantum                                                             130               3.83               .0294         .52

      8890 events in waitclass Other                                                    52207               4.52               .0001         .33

      8890 gc current grant 2-way                                                       14373               14.7                .001         .94

      8890 gc current multi block request                                               14005               15.6               .0011         .54

       

      8890 db file scattered read                                                        324427             1196.27             .0037        1.03           

      8890 db file sequential read                                                       5583096            11150.93             .002        1.63                                                                                                                                      

       

      The table doesn't have any indexes and it is not partitioned .below is the snapper output.

       

      @snapper ash,stats 5 1 8890

      Sampling SID 8890 with interval 5 seconds, taking 1 snapshots...

       

       

      -- Session Snapper v4.25 - by Tanel Poder ( http://blog.tanelpoder.com/snapper ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet!

       

       

      ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

      SID @INST, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES

      ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

        8890  @2, APP_INST  , STAT, session logical reads                                     ,          8310,      1.23k,         ,             ,          ,           ,      8.31k total buffer visits

        8890  @2, APP_INST  , STAT, user I/O wait time                                        ,           655,      96.93,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, non-idle wait time                                        ,           655,      96.93,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, non-idle wait count                                       ,          3754,     555.55,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, physical read total IO requests                           ,          3747,     554.52,         ,             ,          ,           ,      8.19k bytes per request

        8890  @2, APP_INST  , STAT, physical read total bytes                                 ,      30679040,      4.54M,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, cell physical IO interconnect bytes                       ,      30662656,      4.54M,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, db block gets                                             ,          8187,      1.21k,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, db block gets from cache                                  ,          8185,      1.21k,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, db block gets from cache (fastpath)                       ,           765,     113.21,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets                                           ,            15,       2.22,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets from cache                                ,            15,       2.22,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets pin                                       ,            10,       1.48,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets pin (fastpath)                            ,            10,       1.48,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets examination                               ,             5,        .74,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, consistent gets examination (fastpath)                    ,             5,        .74,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, logical read bytes from cache                             ,      67043328,      9.92M,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, physical reads                                            ,          3698,     547.26,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, physical reads cache                                      ,          3697,     547.12,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, physical read IO requests                                 ,          3696,     546.97,         ,             ,          ,           ,      8.19k bytes per request

        8890  @2, APP_INST  , STAT, physical read bytes                                       ,      30277632,      4.48M,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, db block changes                                          ,          7397,      1.09k,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, change write time                                         ,             3,        .44,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, free buffer requested                                     ,          3638,     538.38,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, free buffer inspected                                     ,          3843,     568.72,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, shared hash latch upgrades - no wait                      ,             1,        .15,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, calls to kcmgcs                                           ,          3658,     541.34,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, redo entries                                              ,          7219,      1.07k,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, redo size                                                 ,        567560,     83.99k,         ,             ,          ,           ,          ~ bytes per user commit

        8890  @2, APP_INST  , STAT, redo subscn max counts                                    ,          3603,     533.21,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, file io service time                                      ,        498197,     73.73k,         ,             ,          ,           ,   132.96us bad guess of IO service time per IO request

        8890  @2, APP_INST  , STAT, file io wait time                                         ,       5959332,    881.92k,         ,             ,          ,           ,     1.59ms bad guess of IO wait time per IO request

        8890  @2, APP_INST  , STAT, gc local grants                                           ,          3571,     528.47,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, undo change vector size                                   ,           384,      56.83,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, deferred (CURRENT) block cleanout applications            ,          3258,     482.15,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, active txn count during cleanout                          ,             5,        .74,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, cleanout - number of ktugct calls                         ,             5,        .74,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, HSC Heap Segment Block Changes                            ,             6,        .89,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , STAT, Heap Segment Array Inserts                                ,             6,        .89,         ,             ,          ,           ,          ~ per execution

        8890  @2, APP_INST  , WAIT, db file sequential read                                   ,       6442817,   953.47ms,    95.3%, [WWWWWWWWWW],      3608,     533.95,     1.79ms average wait

       

       

      --  End of Stats snap 1, end=2018-01-07 02:55:53, seconds=6.8

       

       

       

       

      ---------------------------------------------------------------------------------------------------------------

        ActSes   %Thread | INST | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS

      ---------------------------------------------------------------------------------------------------------------

           .93     (93%) |    2 | 3yw4qmag0f6nu   | 0         | db file sequential read             | User I/O

           .07      (7%) |    2 | 3yw4qmag0f6nu   | 0         | ON CPU                              | ON CPU

       

       

      --  End of ASH snap 1, end=2018-01-07 02:55:53, seconds=5, samples_taken=45, AAS=1

       

       

       

       

      PL/SQL procedure successfully completed.

       

      Here are the table details from dba_tables

       

      OWNER           TABLE_NAME        NUM_ROWS     BLOCKS STATUS   DEGREE     LOG LAST_ANALYZED      PAR COMPRESS COMPRESS_FOR

      --------------- ---------- --------------- ---------- -------- ---------- --- ------------------ --- -------- ------------------------------

      Atrtw          EMprte_rty          828520879   34539406 VALID             1 YES 16-DEC-17 19:09:13 NO  DISABLED

       

       

      Please help

        • 1. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
          3189350

          Do you have sequences on this table???

          • 2. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
            Andrew Sayer

            Hard to tell what’s relevent with the v$session_event as we just Have one snapshot, it’s the total events for that session so we would want to see the before picture and the after picture.

             

            Whats the scope of the snapper session?

            What else has this session run during this time?

            How many times did it fire this insert statement in the time? Was it using bulk binds or just one row each time?

             

            I would enable extended sql trace (event 10047), Run the statement, and then confirm it’s This statement that it spends its time on (could be triggers or recursive sql from parsing), then have a look at the raw trace data. Feel free to share the entire thing here in a fixed width font. But make sure you answer our questions too.

            • 3. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
              3204324

              I would enable extended sql trace (event 10047)?

               

              Do you mean 10046?  Please let me know

              • 4. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                John Brady - UK

                As already suggested, I would also suggest running the INSERT with SQL Trace enabled (event 10046) and looking at the individual "db file sequential read"s captured in the trace file.  As well as the event and its elapsed time three parameter values are also captured - the file number, the block number, and the number of blocks read.  Using the first two parameters you can work out which database objects are being accessed.  Are these blocks within your target table, an index on it, or something else entirely?  You can use DBA_EXTENTS to see which database object contains the referenced blocks - the block being read is between the first and last one of an extent of a database object.

                 

                Also make sure that the "db file sequential read"s are directly a result of the INSERT itself and not something else executed by that session while SQL Trace was enabled.

                 

                Logically the INSERT should only touch the existing table and it's indexes, but there could be other factors at play.  That might include things like insert triggers, referential integrity constraints, check constraints, undo segments due to other DML on the same table.  Using the information from the SQL trace file will help identify which database objects are actually being accessed during your INSERT.

                • 5. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                  John Thorton

                  Post same statistics TWICE; once from immediately before the INSERT and once immediately after INSERT.

                  I seriously doubt that the DB Sequential Reads are from INSERT itself.

                  • 6. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                    3204324

                    There are no Indexes on the table. I just collected the 10046 trace level 12 but I am having hard time to paste the contents of it and the editor is hanging for long time if I post entire trace file I also don't see the option of attaching the file .trace file size is 22 mb.Please help

                    • 7. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                      John Brady - UK

                      You can run "tkprof" on the trace file, which will summarise the SQL statements executed, their elapsed times, and the wait events they experienced.  That summary should show how long your INSERT took and what wait events it experienced.

                      • 8. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                        3204324

                        Please find the tkprof output

                         

                        TKPROF: Release 12.1.0.2.0 - Development on Sun Jan 7 11:54:47 2018

                         

                         

                        Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

                         

                         

                        Trace file: gtdcsw2_ora_35258964.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

                        ********************************************************************************

                         

                         

                        SQL ID: 3yw4qmag0f6nu Plan Hash: 0

                         

                         

                        INSERT INTO rtyet.frdfre(EMP_SEQ_ID,ARC_DT,ARC_BATCH_NM,EMP_INTRL_ID,

                          DATA_DUMP_DT,TAX_ID_NB,COST_CTR_ID,FIRST_NM,LAST_NM,MIDL_NM,TITL_NM,

                          EMP_STAT_CD,EMP_CMPY_NM,PART_FULL_TM_CD,FULL_NM,JOB_DESC_TX,EMP_HIRE_DT,

                          EMP_TERM_DT,EMP_TYPE_CD,SRC_SYS_CD,TRDR_RGSTN_ID,TRDR_REP_ROLE_CD,

                          LINE_ORG_NM,LINE_ORG_INTRL_ID,OFC_ID,OFC_ADDR_LINE1_TX,OFC_ADDR_LINE2_TX,

                          SUPVSR_EMP_INTRL_ID,CSTM_1_TX,CSTM_2_TX,CSTM_3_TX,CSTM_4_TX,CSTM_5_TX,

                          CSTM_1_DT,CSTM_2_DT,CSTM_3_DT,CSTM_1_RL,CSTM_2_RL,CSTM_3_RL,PRCSNG_BATCH_NM,

                          JRSDCN_CD,BUS_DMN_LIST_TX,TAX_ID_FRMT_CD,SPRVSRY_ORG_INTRL_ID,

                          SRVC_TEAM_INTRL_ID,NTWK_LOGON_ID,SPRVSN_CD,BRNCH_OFFC_MGR_FL)

                        VALUES

                        ( :1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17,

                           :18, :19, :20, :21, :22, :23, :24, :25, :26, :27, :28, :29, :30, :31, :32,

                          :33, :34, :35, :36, :37, :38, :39, :40, :41, :42, :43, :44, :45, :46, :47,

                          :48)

                         

                         

                         

                         

                        call     count       cpu    elapsed       disk      query    current        rows

                        ------- ------  -------- ---------- ---------- ---------- ----------  ----------

                        Parse        0      0.00       0.00          0          0          0           0

                        Execute    158     15.83     512.72     250731       3882     560880       15800

                        Fetch        0      0.00       0.00          0          0          0           0

                        ------- ------  -------- ---------- ---------- ---------- ----------  ----------

                        total      158     15.83     512.72     250731       3882     560880       15800

                         

                         

                        Misses in library cache during parse: 0

                        Misses in library cache during execute: 1

                        Optimizer mode: ALL_ROWS

                        Parsing user id: 145

                         

                         

                        Elapsed times include waiting on following events:

                          Event waited on                             Times   Max. Wait  Total Waited

                          ----------------------------------------   Waited  ----------  ------------

                          db file sequential read                    185424        0.49        392.99

                          latch: gc element                               1        0.00          0.00

                          SQL*Net more data from client                 470        0.00          0.01

                          SQL*Net message to client                     157        0.00          0.00

                          SQL*Net message from client                   157        0.04          0.17

                          log file switch completion                      1        0.07          0.07

                          gc current grant busy                          61        0.00          0.09

                          enq: FB - contention                           20        0.00          0.02

                          KJC: Wait for msg sends to complete             3        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    158     15.83     512.72     250731       3882     560880       15800

                        Fetch        0      0.00       0.00          0          0          0           0

                        ------- ------  -------- ---------- ---------- ---------- ----------  ----------

                        total      158     15.83     512.72     250731       3882     560880       15800

                         

                         

                        Misses in library cache during parse: 0

                        Misses in library cache during execute: 1

                         

                         

                        Elapsed times include waiting on following events:

                          Event waited on                             Times   Max. Wait  Total Waited

                          ----------------------------------------   Waited  ----------  ------------

                          db file sequential read                    185424        0.49        392.99

                          latch: gc element                               1        0.00          0.00

                          SQL*Net more data from client                 470        0.00          0.01

                          SQL*Net message to client                     159        0.00          0.00

                          SQL*Net message from client                   159        0.04          0.17

                          log file switch completion                      1        0.07          0.07

                          gc current grant busy                          61        0.00          0.09

                          enq: FB - contention                           20        0.00          0.02

                          KJC: Wait for msg sends to complete             3        0.00          0.00

                          log file sync                                   1        0.00          0.00

                         

                         

                         

                         

                        OVERALL TOTALS FOR ALL 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

                         

                         

                            1  user  SQL statements in session.

                            0  internal SQL statements in session.

                            1  SQL statements in session.

                        ********************************************************************************

                        Trace file: frefgtrd_ora_35258964.trc

                        Trace file compatibility: 11.1.0.7

                        Sort options: default

                         

                         

                               1  session in tracefile.

                               1  user  SQL statements in trace file.

                               0  internal SQL statements in trace file.

                               1  SQL statements in trace file.

                               1  unique SQL statements in trace file.

                          223378  lines in trace file.

                             477  elapsed seconds in trace file.

                        • 9. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                          3204324

                          Whats the scope of the snapper session? it was for 5 sec's What else has this session run during this time? only problematic insert How many times did it fire this insert statement in the time? Was it using bulk binds or just one row each time? I am not sure.I 'll check with Dev team

                          • 10. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                            John Brady - UK

                            3204324 wrote:

                             

                            Please find the tkprof output

                             

                            TKPROF: Release 12.1.0.2.0 - Development on Sun Jan 7 11:54:47 2018

                             

                            Trace file: gtdcsw2_ora_35258964.trc

                            Sort options: default

                             

                            SQL ID: 3yw4qmag0f6nu Plan Hash: 0

                             

                            INSERT INTO rtyet.frdfre(EMP_SEQ_ID,ARC_DT,ARC_BATCH_NM,EMP_INTRL_ID,

                            DATA_DUMP_DT,TAX_ID_NB,COST_CTR_ID,FIRST_NM,LAST_NM,MIDL_NM,TITL_NM,

                            EMP_STAT_CD,EMP_CMPY_NM,PART_FULL_TM_CD,FULL_NM,JOB_DESC_TX,EMP_HIRE_DT,

                            EMP_TERM_DT,EMP_TYPE_CD,SRC_SYS_CD,TRDR_RGSTN_ID,TRDR_REP_ROLE_CD,

                            LINE_ORG_NM,LINE_ORG_INTRL_ID,OFC_ID,OFC_ADDR_LINE1_TX,OFC_ADDR_LINE2_TX,

                            SUPVSR_EMP_INTRL_ID,CSTM_1_TX,CSTM_2_TX,CSTM_3_TX,CSTM_4_TX,CSTM_5_TX,

                            CSTM_1_DT,CSTM_2_DT,CSTM_3_DT,CSTM_1_RL,CSTM_2_RL,CSTM_3_RL,PRCSNG_BATCH_NM,

                            JRSDCN_CD,BUS_DMN_LIST_TX,TAX_ID_FRMT_CD,SPRVSRY_ORG_INTRL_ID,

                            SRVC_TEAM_INTRL_ID,NTWK_LOGON_ID,SPRVSN_CD,BRNCH_OFFC_MGR_FL)

                            VALUES

                            ( :1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17,

                            :18, :19, :20, :21, :22, :23, :24, :25, :26, :27, :28, :29, :30, :31, :32,

                            :33, :34, :35, :36, :37, :38, :39, :40, :41, :42, :43, :44, :45, :46, :47,

                            :48)

                             

                             

                            call count cpu elapsed disk query current rows

                            ------- ------ -------- ---------- ---------- ---------- ---------- ----------

                            Parse 0 0.00 0.00 0 0 0 0

                            Execute 158 15.83 512.72 250731 3882 560880 15800

                            Fetch 0 0.00 0.00 0 0 0 0

                            ------- ------ -------- ---------- ---------- ---------- ---------- ----------

                            total 158 15.83 512.72 250731 3882 560880 15800

                             

                             

                            Elapsed times include waiting on following events:

                            Event waited on Times Max. Wait Total Waited

                            ---------------------------------------- Waited ---------- ------------

                            db file sequential read 185424 0.49 392.99

                             

                             

                            Okay, so it looks like you are experiencing "db file sequential read"s during the execution of this INSERT.  If you open the trace file in an editor you can then search for individual cases of "db file sequential read".  You should see things like the following:

                             

                            WAIT #1: nam='db file sequential read' ela= 3686 p1=3 p2=320403 p3=1

                             

                            This says that a "db file sequential read" occurred to read one block (p3) from file 3 (p1) at block id 320403 (p2).

                             

                            If you look at DBA_EXTENTS for your table - rtyet.frdfre - you should be able to see its extent map and the ranges of blocks it has.  Between the two sets of information you can work out whether the "db file sequential reads" are to blocks within this table, or to blocks in other database objects.

                             

                            Yes, it is time consuming to do this, but that is how you work out what database object has the blocks being read.  Potentially you could automate some of this, but you would need to write the scripts etc. to do the work for you.  I'd consider something like extracting only the "db file sequential read" WAIT lines to a separate file, then exposing that as an external table in Oracle, and then querying that to find out which objects the reads are accessing.  It won't necessarily be easy, because you will need to use a mix of separators to break out just the values of the parameters (p1, p2, p3), and then join to DBA_EXTENTS and group to get counts of reads against each referenced database object.  But it could be done if you wanted to do it.

                             

                            Otherwise, I'd pick some random examples from those "db file sequential reads" and see what blocks they referenced and which object they were in.  Because extents cover sequential ranges of blocks, it is possible to spot when block numbers change significantly and might be for different database objects.

                            • 11. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                              3204324

                              Thank you for your help. I opened the trace file and found out db file sequential read events and they look like below

                               

                              WAIT #4856904432: nam='db file sequential read' ela= 308 file#=687 block#=1371163 blocks=1 obj#=202939 tim=45355143777311

                              WAIT #4856904432: nam='db file sequential read' ela= 366 file#=687 block#=1371227 blocks=1 obj#=202939 tim=45355143777731

                              WAIT #4856904432: nam='db file sequential read' ela= 342 file#=687 block#=1371291 blocks=1 obj#=202939 tim=45355143778122

                              WAIT #4856904432: nam='db file sequential read' ela= 289 file#=687 block#=1371355 blocks=1 obj#=202939 tim=45355143778514

                               

                               

                              I think the OBJ# is the object id and i can find the object from the dba_objects right ?I already did that it is pointing to me the table and in the entire trace file I dont see any other Object_id's other than 202939 which is my table,

                               

                              bhdhulip@cdb01prdx2:ACTPRD>select

                                2      owner o_owner,

                                3      object_name o_object_name,

                                4      object_type o_object_type,

                                5      created,

                                6      last_ddl_time,

                                7      status o_status,

                                8      data_object_id

                                9  from

                              10      dba_objects

                              11  where

                              12      object_id in (&1)

                              13  order by

                              14      o_object_name,

                              15      o_owner,

                              16      o_object_type

                              17  /

                               

                              owner                     object_name                    object_type        CREATED            LAST_DDL_TIME      status    DATA_OBJECT_ID

                              ------------------------- ------------------------------ ------------------ ------------------ ------------------ --------- --------------

                              rtyet                    frdfre                            TABLE              11-JAN-17 17:28:25 28-OCT-17 11:44:18 VALID             202939

                               

                               

                               

                              • 12. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                                John Thorton

                                3204324 wrote:

                                 

                                Thank you for your help. I opened the trace file and found out db file sequential read events and they look like below

                                 

                                WAIT #4856904432: nam='db file sequential read' ela= 308 file#=687 block#=1371163 blocks=1 obj#=202939 tim=45355143777311

                                WAIT #4856904432: nam='db file sequential read' ela= 366 file#=687 block#=1371227 blocks=1 obj#=202939 tim=45355143777731

                                WAIT #4856904432: nam='db file sequential read' ela= 342 file#=687 block#=1371291 blocks=1 obj#=202939 tim=45355143778122

                                WAIT #4856904432: nam='db file sequential read' ela= 289 file#=687 block#=1371355 blocks=1 obj#=202939 tim=45355143778514

                                 

                                 

                                I think the OBJ# is the object id and i can find the object from the dba_objects right ?I already did that it is pointing to me the table and in the entire trace file I dont see any other Object_id's other than 202939 which is my table,

                                 

                                bhdhulip@cdb01prdx2:ACTPRD>select

                                2 owner o_owner,

                                3 object_name o_object_name,

                                4 object_type o_object_type,

                                5 created,

                                6 last_ddl_time,

                                7 status o_status,

                                8 data_object_id

                                9 from

                                10 dba_objects

                                11 where

                                12 object_id in (&1)

                                13 order by

                                14 o_object_name,

                                15 o_owner,

                                16 o_object_type

                                17 /

                                 

                                owner object_name object_type CREATED LAST_DDL_TIME status DATA_OBJECT_ID

                                ------------------------- ------------------------------ ------------------ ------------------ ------------------ --------- --------------

                                rtyet frdfre TABLE 11-JAN-17 17:28:25 28-OCT-17 11:44:18 VALID 202939

                                 

                                 

                                 

                                It is LOOKING for FREE BLOCK for where to INSERT  new row.

                                This can be avoided using /*+ APPEND */ hint

                                1 person found this helpful
                                • 13. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                                  3204324

                                  Thanks for the help.how did you figure that out.can you please let me kmow?

                                  • 14. Re: Insert is running long with more waits on DB FILE SEQUENTIAL READS.
                                    John Brady - UK

                                    My only observation is that the block number seems to be going up by 64 between each read, so it looks like Oracle is skipping sequentially through that table. I don't know why it is doing this, but maybe other people will. It might be something to do with how your tablespaces are managed - dictionary or self managed - or your extent sizes (are they a uniform 64 rather than growing each time the table grows). I don't know either way, I'm just mentioning these things.

                                    1 2 3 4 Previous Next