Skip to Main Content

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

User_WVSC7Jan 7 2018 — edited Jan 11 2018

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

Comments
Post Details
Added on Jan 7 2018
46 comments
11,934 views