Re: Simple Insert - very slow
Date: Mon, 20 May 2019 11:34:21 +0200 (CEST)
Message-ID: <195846070.393004.1558344862001_at_ox.hosteurope.de>
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: _at_OracleSK
> Sanjay Mishra <smishra_97_at_yahoo.com> hat am 18. Mai 2019 um 19:08 geschrieben:
>
>
> Stefan
>
> Thanks for good document created by you to troubleshoot. Need to check as what is best way to interpret snapper data but pasting the details and if someone can provide any better guidance. Will also check more on Tanel site for any demo to interpret the snapper report. As per Pages 20 and Explain plan on Page 21 is exactly the same scenario.
>
>
> Sampling SID 1070 with interval 1 seconds, taking 1 snapshots...
>
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> SID _at_INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> 1070 _at_2, SYSADMIN, STAT, session logical reads , 13865, 7.73k, , , , , 14.1k total buffer visits
> 1070 _at_2, SYSADMIN, STAT, user I/O wait time , 141, 78.65, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, non-idle wait time , 141, 78.65, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, non-idle wait count , 12230, 6.82k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical read total IO requests , 6112, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical read requests optimized , 6111, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical read total bytes optimized , 50069504, 27.93M, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical read total bytes , 50069504, 27.93M, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, cell physical IO interconnect bytes , 50069504, 27.93M, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, gcs messages sent , 3, 1.67, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, db block gets , 13860, 7.73k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, db block gets from cache , 13860, 7.73k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, db block gets from cache (fastpath) , 7737, 4.32k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, consistent gets , 1, .56, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, consistent gets from cache , 1, .56, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, consistent gets pin , 1, .56, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, consistent gets pin (fastpath) , 1, .56, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, logical read bytes from cache , 113541120, 63.34M, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical reads , 6111, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical reads cache , 6111, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, physical read IO requests , 6112, 3.41k, , , , , 8.19k bytes per request
> 1070 _at_2, SYSADMIN, STAT, physical read bytes , 50069504, 27.93M, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, db block changes , 11, 6.14, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, free buffer requested , 6112, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, hot buffers moved to head of LRU , 958, 534.39, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, free buffer inspected , 6144, 3.43k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, shared hash latch upgrades - no wait , 7, 3.9, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, blocks decrypted , 6110, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, redo entries , 6120, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, redo size , 465504, 259.67k, , , , , ~ bytes per user commit
> 1070 _at_2, SYSADMIN, STAT, redo entries for lost write detection , 6110, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, redo size for lost write detection , 464756, 259.25k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, redo subscn max counts , 7, 3.9, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, file io wait time , 1408659, 785.78k, , , , , 230.47us bad guess of IO wait time per IO request
> 1070 _at_2, SYSADMIN, STAT, gc current blocks received , 3, 1.67, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, gc local grants , 6116, 3.41k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, ASSM cbk:blocks examined , 12366, 6.9k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, ASSM gsp:L1 bitmaps examined , 2478, 1.38k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, ASSM gsp:L2 bitmaps examined , 1, .56, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, ASSM gsp:reject db , 12388, 6.91k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, STAT, buffer is pinned count , 230, 128.3, , , , , 1.63 % buffer gets avoided thanks to buffer pin caching
> 1070 _at_2, SYSADMIN, STAT, cell flash cache read hits , 6723, 3.75k, , , , , ~ per execution
> 1070 _at_2, SYSADMIN, TIME, background cpu time , 365192, 203.71ms, 20.4%, [## ], , ,
> 1070 _at_2, SYSADMIN, TIME, background elapsed time , 1273623, 710.45ms, 71.0%, [######## ], , , 28.95 % unaccounted time
> 1070 _at_2, SYSADMIN, WAIT, gc current block busy , 629, 350.87us, .0%, [ ], 3, 1.67, 209.67us average wait
> 1070 _at_2, SYSADMIN, WAIT, cell single block physical read , 1557638, 868.88ms, 86.9%, [WWWWWWWWW ], 6746, 3.76k, 230.9us average wait
>
> -- End of Stats snap 1, end=2019-05-18 12:58:58, seconds=1.8
-- http://www.freelists.org/webpage/oracle-lReceived on Mon May 20 2019 - 11:34:21 CEST