Mark/Jonathan
When I created a new table with the same compression, Issue is not appearing
and not sure if this will come back again after heavily DML operation. As it
was fine for several days after imported earlier and suddenly started behaving
badly. I will continue to do the test with the original table as suggested
above by Stefan/Jonathan so as to make sure RCA is done and the same is not
going to pop up again
TxSanjay On Monday, May 20, 2019, 9:29:15 AM EDT, Mark W. Farnham
<mwf@xxxxxxxx> wrote:
Taken all together, I would advocate copying this single table to a
tablespace brand new, all its own and re-running the test.
That will quickly factor out accumulated problems from one time run
problems. Whether you do this as a clone (not the real table) or for real is
an interesting question. A test clone would avoid other activities updating
in competition. A move "for real" might make your problem go away without
fully learning the root cause.
This would help focus on the nature of your actual problem, together with
making it easier to see if the MOS note referenced in the thread is
relevant.
The difference between a Millsap trace on the current object versus the
trace of the same updates to a clone of the table should be very
illuminating.
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Jonathan Lewis
Sent: Monday, May 20, 2019 7:00 AM
To: Oracle-L Freelists
Subject: Re: Simple Insert - very slow
Sanjay,
I don't use snapper often enough to be sure of exactly how it works, but
your figures for a "1 second single snapshot" suggest that it took nearly 2
seconds to do a one second snapshot - which could indicate that the machine
is overloaded and work outside the work you are doing is impacting in your
attempt to load data.
The things I note about the figures are:
a) you read 6,111 blocks - and decrypt 6,110 blocks (so presumably the table
is either encrypted, or in an enctryped tablespace)
b) you generate 6,120 redo entries of which 6,110 are for lost write
detection (so I think you've got "db_lost_write_protect = full" (or your
table is in the SYSTEM tablespace !)
c) you report only 11 db block changes and 750 bytes of "other" redo - so
you haven't managed to insert many rows, and
d) you've got only 3 "gc current block received" but waited 629 times on "gc
current block busy" - which is odd, and also suggests that something else is
hammering away at the table you're trying to insert to.
e) you've examined 2,478 level 1 bitmap blocks leading to 12,388 data block
rejections - so there's a massive conflict between the space the bitmap says
is available and the space that seems to be available when the session
checks the targetted blocks. (This is probably why Stefan is suggesting
stack tracing) to find out why there's such a discrepancy between the
bitmaps and the actual blocks. I note from an earlier post, though that the
table is compressed and has a column txn_upd_dt. If anything is updating the
rows in this table you're likely to end up with lots of migrated rows, and
there used to be a complete foul-up with migrated rows, ITLs and ASSM that
resulted in a major collision and waste of resources.
You've got some trace data for the insert - and identified the blocks being
read as from the table. Do you get file and block ids from the trace ? If
so then (a) do you see the same blocks being re-read many times over the
course of a couple of minutes, and (b) can you dump a few of the blocks that
are read (especially if they are in the middle of a stream of consecute
block ids) so that we can see if they are the target of a lot of migration
and have large numbers of ITL entries (check for "itc" and the number
following it).
Regards
Jonathan Lewis
________________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on
behalf of Stefan Koehler <contact@xxxxxxxx>
Sent: 20 May 2019 10:34
To: Sanjay Mishra
Cc: Oracle-L Freelists
Subject: Re: Simple Insert - very slow
Hello Sanjay,
it seems like this is really an ASSM issue based on the stats of "ASSM gsp*"
and "ASSM cbk*".
Now it would be time to gather stack traces and check in more detail with
the already mentioned trace events 10320 and/or 10612.
You can also try to disable the ASSM rejection cache
(_enable_rejection_cache) or set event 10019 to level 1 but these would be
just some shot in the dark.
Best Regards
Stefan Koehler
Independent Oracle performance consultant and researcher
Website: http://www.soocs.de
Twitter: @OracleSK
Sanjay Mishra <smishra_97@xxxxxxxxx> hat am 18. Mai 2019 um 19:08geschrieben:
what is best way to interpret snapper data but pasting the details and if
Stefan
Thanks for good document created by you to troubleshoot. Need to check as
----------------------------------------------------------------------------
Sampling SID 1070 with interval 1 seconds, taking 1 snapshots...
SID @INST, USERNAME , TYPE, STATISTIC, DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC,
----------------------------------------------------------------------------
1070 @2, SYSADMIN, STAT, session logical reads, 13865, 7.73k, , , , ,
1070 @2, SYSADMIN, STAT, user I/O wait time, 141, 78.65, , , , ,
1070 @2, SYSADMIN, STAT, non-idle wait time, 141, 78.65, , , , ,
1070 @2, SYSADMIN, STAT, non-idle wait count, 12230, 6.82k, , , , ,
1070 @2, SYSADMIN, STAT, physical read total IO requests, 6112, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, physical read requests optimized, 6111, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, physical read total bytes optimized, 50069504, 27.93M, , , , ,
1070 @2, SYSADMIN, STAT, physical read total bytes, 50069504, 27.93M, , , , ,
1070 @2, SYSADMIN, STAT, cell physical IO interconnect bytes, 50069504, 27.93M, , , , ,
1070 @2, SYSADMIN, STAT, gcs messages sent, 3, 1.67, , , , ,
1070 @2, SYSADMIN, STAT, db block gets, 13860, 7.73k, , , , ,
1070 @2, SYSADMIN, STAT, db block gets from cache, 13860, 7.73k, , , , ,
1070 @2, SYSADMIN, STAT, db block gets from cache (fastpath), 7737, 4.32k, , , , ,
1070 @2, SYSADMIN, STAT, consistent gets, 1, .56, , , , ,
1070 @2, SYSADMIN, STAT, consistent gets from cache, 1, .56, , , , ,
1070 @2, SYSADMIN, STAT, consistent gets pin, 1, .56, , , , ,
1070 @2, SYSADMIN, STAT, consistent gets pin (fastpath), 1, .56, , , , ,
1070 @2, SYSADMIN, STAT, logical read bytes from cache, 113541120, 63.34M, , , , ,
1070 @2, SYSADMIN, STAT, physical reads, 6111, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, physical reads cache, 6111, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, physical read IO requests, 6112, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, physical read bytes, 50069504, 27.93M, , , , ,
1070 @2, SYSADMIN, STAT, db block changes, 11, 6.14, , , , ,
1070 @2, SYSADMIN, STAT, free buffer requested, 6112, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, hot buffers moved to head of LRU, 958, 534.39, , , , ,
1070 @2, SYSADMIN, STAT, free buffer inspected, 6144, 3.43k, , , , ,
1070 @2, SYSADMIN, STAT, shared hash latch upgrades - no wait, 7, 3.9, , , , ,
1070 @2, SYSADMIN, STAT, blocks decrypted, 6110, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, redo entries, 6120, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, redo size, 465504, 259.67k, , , , ,
1070 @2, SYSADMIN, STAT, redo entries for lost write detection, 6110, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, redo size for lost write detection, 464756, 259.25k, , , , ,
1070 @2, SYSADMIN, STAT, redo subscn max counts, 7, 3.9, , , , ,
1070 @2, SYSADMIN, STAT, file io wait time, 1408659, 785.78k, , , , ,
1070 @2, SYSADMIN, STAT, gc current blocks received, 3, 1.67, , , , ,
1070 @2, SYSADMIN, STAT, gc local grants, 6116, 3.41k, , , , ,
1070 @2, SYSADMIN, STAT, ASSM cbk:blocks examined, 12366, 6.9k, , , , ,
1070 @2, SYSADMIN, STAT, ASSM gsp:L1 bitmaps examined, 2478, 1.38k, , , , ,
1070 @2, SYSADMIN, STAT, ASSM gsp:L2 bitmaps examined, 1, .56, , , , ,
1070 @2, SYSADMIN, STAT, ASSM gsp:reject db, 12388, 6.91k, , , , ,
1070 @2, SYSADMIN, STAT, buffer is pinned count, 230, 128.3, , , , ,
1070 @2, SYSADMIN, STAT, cell flash cache read hits, 6723, 3.75k, , , , ,
1070 @2, SYSADMIN, TIME, background cpu time, 365192, 203.71ms, 20.4%, [## ], , ,
1070 @2, SYSADMIN, TIME, background elapsed time, 1273623, 710.45ms, 71.0%, [######## ], , ,
1070 @2, SYSADMIN, WAIT, gc current block busy, 629, 350.87us, .0%, [ ], 3, 1.67,
1070 @2, SYSADMIN, WAIT, cell single block physical read, 1557638, 868.88ms, 86.9%, [WWWWWWWWW ], 6746, 3.76k,
--
-- End of Stats snap 1, end=2019-05-18 12:58:58, seconds=1.8
