Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Interested in getting your voice heard by members of the Developer Marketing team at Oracle? Check out this post for AppDev or this post for AI focus group information.

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

Bhavani DhulipallaJan 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

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

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

.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

This post has been answered by Jonathan Lewis on Jan 9 2018

Jump to Answer

Erik - Hotspot Engineer-Oracle

Answer

1) Yes, using the maxage parameter. But it only works if disk=true, if you have a disk repository, If you don't specify maxage/maxsize, and only set disk=true, the JVM will set up default values, if you use defaultrecording=true. If you want infinite, set maxsize=0,maxage=0 to overide the defaults.

2) The maxage/maxsize parameters are thresholds at which the JVM will start to remove recording chunks from the disk repository. Since it would be to expensive to check thresholds at every event written, the thresholds are only checked when a new recording chunk is created, which happens about every 12-15 Mb (depending on how much data exist in thread buffers when they are flushed) So with a short maxage, like 1 minute, there may not have been enough data to trigger removal of chunks.

Marked as Answer by ctoomey · Sep 27 2020

ctoomey

Thanks Erik, adding disk=true did the trick.

I've found that the documentation and functionality of the -XX:StartFlightRecording and -XX:FlightRecorderOptions is very unclear and confusing. Can you or others comment/clarify the following?

Is it correct that the XX:StartFlightRecording options are meant to only apply to a special start recording (that starts at server start time), while the XX:FlightRecorderOptions are meant to apply to any/all recordings?
Why are some of the XX:FlightRecorderOptions not also available for XX:StartFlightRecording, e.g., disk=true, dumponexit=true? This makes it tricky to configure the start recording as you need to specify different options with different XX: parameters.
The settings=path option seems to have no effect when given to XX:FlightRecorderOptions, even though it's listed in the documentation page above as being a supported option. When I use settings=path with XX:FlightRecorderOptions, I still get the default settings. Is this a known implementation or documentation bug?
With both XX:StartFlightRecording and XX:FlightRecorderOptions, what's the behavior when defaultrecording=false? The documentation says "Specifies whether the recording is a continuous background recording or it runs for a limited time. By default, this parameter is set to false (recording runs for a limited time)." What is this limited time (how long)? And is it a limited time forward from the beginning, or backwards from the current time? Why is this setting even needed given the maxage, maxsize, and duration settings?

thanks,

Chris

1 person found this helpful

Erik - Hotspot Engineer-Oracle

"Is it correct that the XX:StartFlightRecording options are meant to only apply to a special start recording (that starts at server start time), while the XX:FlightRecorderOptions are meant to apply to any/all recordings"

-XX:FlightRecorderOptions is meant to configure global settings, but there are also options that controls the default in-memory recording (called "Hotspot default"), which can be turned on by setting defaultrecording=true. Since Flight Recorder records the union of all ongoing recordings, it will in practise apply to other recordings as well.

"The settings=path option seems to have no effect when given to XX:FlightRecorderOptions, even though it's listed in the documentation page above as being a supported option. When I use settings=path with XX:FlightRecorderOptions, I still get the default settings. Is this a known implementation or documentation bug?"

It's a known bug, as a workaround you can replace the file named default.jfc in JRE_HOME/lib/jfr with the settings file you want, i.e profile.jfc

"With both XX:StartFlightRecording and XX:FlightRecorderOptions, what's the behavior when defaultrecording=false? "

No default (in-memory) recording will be started

"The documentation says "Specifies whether the recording is a continuous background recording or it runs for a limited time. By default, this parameter is set to false (recording runs for a limited time)." What is this limited time (how long)? And is it a limited time forward from the beginning, or backwards from the current time? Why is this setting even needed given the maxage, maxsize, and duration settings?"

It's incorrect, defaultrecording=true is just a convenience option for starting the default in-memory recording. There is no limit put in place if you set it to false.

If you want to use a disk repository, you can ignore all options that includes the word "default" and just use -XX:StartFlightRecording.

ctoomey

Thanks Erik.

If you want to use a disk repository, you can ignore all options that includes the word "default" and just use -XX:StartFlightRecording.

I found that even when I use -XX:StartFlightRecording, I can only get that recording dumped to disk on exit if I set defaultrecording=true along with disk=true,dumponexit=true,dumponexitpath=path via -XX:FlightRecorderOptions .

Chris

Erik - Hotspot Engineer-Oracle

ctoomey wrote:

Thanks Erik.

If you want to use a disk repository, you can ignore all options that includes the word "default" and just use -XX:StartFlightRecording.

Chris

You should be able dump the buffers on exit, even if you haven't started a defaultrecording.

I will file a bug report. Thanks for reporting.

1 - 5

Locked Post

New comments cannot be posted to this locked post.

Locked on Feb 7 2018

Added on Jan 7 2018

#general-database-discussions

46 comments

13,278 views

Oracle Database Discussions

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

Comments

Post Details