Re: Simple Insert - very slow

  • From: "Sanjay Mishra" <dmarc-noreply@xxxxxxxxxxxxx> (Redacted sender "smishra_97" for DMARC)
  • To: Rajeev Prabhakar <rprabha01@xxxxxxxxx>
  • Date: Wed, 22 May 2019 22:18:23 +0000 (UTC)

 Rajeev, I will try as the doc is referring to Clustered tables with 2K blocks 
and our table is not clustered and the block is default 8K. But as Stefan also 
mentioned about Rejection cache and so will try
TxSanjay
    On Monday, May 20, 2019, 7:09:39 AM EDT, Rajeev Prabhakar 
<rprabha01@xxxxxxxxx> wrote:  
 
 Sanjay,
Did you already look at this MoS note -2491760.1 ?If this were to be applicable 
to your case, there is a patch and a workaround.
Regards,Rajeev

On May 20, 2019 at 5:34 AM, <Stefan Koehler> wrote:

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: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 @INST, USERNAME  , TYPE, STATISTIC                                       
          ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  
WAITS/SEC,   AVERAGES

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

  1070  @2, SYSADMIN, STAT, session logical reads                             
        ,         13865,      7.73k,         ,             ,          ,       
    ,      14.1k total buffer visits

  1070  @2, SYSADMIN, STAT, user I/O wait time                                
        ,           141,      78.65,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, non-idle wait time                                
        ,           141,      78.65,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, non-idle wait count                               
        ,         12230,      6.82k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical read total IO requests                   
        ,          6112,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical read requests optimized                  
        ,          6111,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical read total bytes optimized               
        ,      50069504,     27.93M,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical read total bytes                         
        ,      50069504,     27.93M,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, cell physical IO interconnect bytes               
        ,      50069504,     27.93M,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, gcs messages sent                                 
        ,             3,       1.67,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, db block gets                                     
        ,         13860,      7.73k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, db block gets from cache                          
        ,         13860,      7.73k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, db block gets from cache (fastpath)               
        ,          7737,      4.32k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, consistent gets                                   
        ,             1,        .56,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, consistent gets from cache                        
        ,             1,        .56,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, consistent gets pin                               
        ,             1,        .56,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, consistent gets pin (fastpath)                    
        ,             1,        .56,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, logical read bytes from cache                     
        ,     113541120,     63.34M,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical reads                                    
        ,          6111,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical reads cache                              
        ,          6111,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, physical read IO requests                         
        ,          6112,      3.41k,         ,             ,          ,       
    ,      8.19k bytes per request

  1070  @2, SYSADMIN, STAT, physical read bytes                               
        ,      50069504,     27.93M,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, db block changes                                  
        ,            11,       6.14,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, free buffer requested                             
        ,          6112,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, hot buffers moved to head of LRU                  
        ,           958,     534.39,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, free buffer inspected                             
        ,          6144,      3.43k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, shared hash latch upgrades - no wait              
        ,             7,        3.9,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, blocks decrypted                                  
        ,          6110,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, redo entries                                      
        ,          6120,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, redo size                                         
        ,        465504,    259.67k,         ,             ,          ,       
    ,          ~ bytes per user commit

  1070  @2, SYSADMIN, STAT, redo entries for lost write detection             
        ,          6110,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, redo size for lost write detection                
        ,        464756,    259.25k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, redo subscn max counts                            
        ,             7,        3.9,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, file io wait time                                 
        ,       1408659,    785.78k,         ,             ,          ,       
    ,   230.47us bad guess of IO wait time per IO request

  1070  @2, SYSADMIN, STAT, gc current blocks received                        
        ,             3,       1.67,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, gc local grants                                   
        ,          6116,      3.41k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, ASSM cbk:blocks examined                          
        ,         12366,       6.9k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, ASSM gsp:L1 bitmaps examined                      
        ,          2478,      1.38k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, ASSM gsp:L2 bitmaps examined                      
        ,             1,        .56,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, ASSM gsp:reject db                                
        ,         12388,      6.91k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, STAT, buffer is pinned count                            
        ,           230,      128.3,         ,             ,          ,       
    ,       1.63 % buffer gets avoided thanks to buffer pin caching

  1070  @2, SYSADMIN, STAT, cell flash cache read hits                        
        ,          6723,      3.75k,         ,             ,          ,       
    ,          ~ per execution

  1070  @2, SYSADMIN, TIME, background cpu time                               
        ,        365192,   203.71ms,    20.4%, [##        ],          ,       
    ,

  1070  @2, SYSADMIN, TIME, background elapsed time                           
        ,       1273623,   710.45ms,    71.0%, [########  ],          ,       
    ,      28.95 % unaccounted time

  1070  @2, SYSADMIN, WAIT, gc current block busy                             
        ,           629,   350.87us,      .0%, [          ],         3,       
1.67,   209.67us average wait

  1070  @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

--

//www.freelists.org/webpage/oracle-l






  

Other related posts: