Re: Simple Insert - very slow

  • From: "Sanjay Mishra" <dmarc-noreply@xxxxxxxxxxxxx> (Redacted sender "smishra_97" for DMARC)
  • To: Oracle-L Freelists <oracle-l@xxxxxxxxxxxxx>, Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
  • Date: Wed, 22 May 2019 22:14:23 +0000 (UTC)

 Thanks Jonathan
I love reading lots of articles. Thanks for the explanation and I was reading 
one of your discussion where it says that there is an issue with OLTP 
compression in 12.2 and it looks like might be an issue. what you mentioned 
based on the Snapper data is correct that data is encrypted and db_lost_write 
mode is also full. What is the best event or session setting that can be used 
to see the flow of the SQL as tracing running session with 10046 to admin level 
12 was only showing nothing but mostly cell single physical read. In 10046 
trace, I can see cellhas#,diskhash# and obj# and I can see that obj# is same  
but combination of Cellhash# and diskhash# appearing multiple time with same 
combination like WAIT #145673456782356: nam='cell single block physical read' 
ela= 228 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235507735WAIT #145673456782356: nam='cell single block physical read' 
ela= 182 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235507984WAIT #145673456782356: nam='cell single block physical read' 
ela= 179 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235508215WAIT #145673456782356: nam='cell single block physical read' 
ela= 218 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235508496WAIT #145673456782356: nam='cell single block physical read' 
ela= 175 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235508718WAIT #145673456782356: nam='cell single block physical read' 
ela= 223 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235508988WAIT #145673456782356: nam='cell single block physical read' 
ela= 194 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235509257WAIT #145673456782356: nam='cell single block physical read' 
ela= 190 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235509510WAIT #145673456782356: nam='cell single block physical read' 
ela= 233 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235509815WAIT #145673456782356: nam='cell single block physical read' 
ela= 224 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235510103WAIT #145673456782356: nam='cell single block physical read' 
ela= 227 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235510398WAIT #145673456782356: nam='cell single block physical read' 
ela= 194 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235510647WAIT #145673456782356: nam='cell single block physical read' 
ela= 220 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235510923WAIT #145673456782356: nam='cell single block physical read' 
ela= 189 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235511157WAIT #145673456782356: nam='cell single block physical read' 
ela= 183 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235511400WAIT #145673456782356: nam='cell single block physical read' 
ela= 156 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235511604WAIT #145673456782356: nam='cell single block physical read' 
ela= 193 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235511858WAIT #145673456782356: nam='cell single block physical read' 
ela= 168 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235512099WAIT #145673456782356: nam='cell single block physical read' 
ela= 288 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235512447WAIT #145673456782356: nam='cell single block physical read' 
ela= 246 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235512749WAIT #145673456782356: nam='cell single block physical read' 
ela= 174 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235512988WAIT #145673456782356: nam='cell single block physical read' 
ela= 218 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235513277WAIT #145673456782356: nam='cell single block physical read' 
ela= 220 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235513562WAIT #145673456782356: nam='cell single block physical read' 
ela= 225 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235513843WAIT #145673456782356: nam='cell single block physical read' 
ela= 190 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235514096WAIT #145673456782356: nam='cell single block physical read' 
ela= 163 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235514335WAIT #145673456782356: nam='cell single block physical read' 
ela= 190 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235514587WAIT #145673456782356: nam='cell single block physical read' 
ela= 219 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235514861WAIT #145673456782356: nam='cell single block physical read' 
ela= 223 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235515146WAIT #145673456782356: nam='cell single block physical read' 
ela= 223 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235515463WAIT #145673456782356: nam='cell single block physical read' 
ela= 223 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235515766WAIT #145673456782356: nam='cell single block physical read' 
ela= 187 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235516017WAIT #145673456782356: nam='cell single block physical read' 
ela= 204 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235516291WAIT #145673456782356: nam='cell single block physical read' 
ela= 194 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235516541WAIT #145673456782356: nam='cell single block physical read' 
ela= 220 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235516809WAIT #145673456782356: nam='cell single block physical read' 
ela= 231 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235517095WAIT #145673456782356: nam='cell single block physical read' 
ela= 237 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235517397WAIT #145673456782356: nam='cell single block physical read' 
ela= 186 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235517639WAIT #145673456782356: nam='cell single block physical read' 
ela= 222 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235517922WAIT #145673456782356: nam='cell single block physical read' 
ela= 221 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235518197WAIT #145673456782356: nam='cell single block physical read' 
ela= 226 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235518484WAIT #145673456782356: nam='cell single block physical read' 
ela= 160 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235518700WAIT #145673456782356: nam='cell single block physical read' 
ela= 215 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235518976WAIT #145673456782356: nam='cell single block physical read' 
ela= 170 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235519205WAIT #145673456782356: nam='cell single block physical read' 
ela= 290 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235519558WAIT #145673456782356: nam='cell single block physical read' 
ela= 221 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235519846WAIT #145673456782356: nam='cell single block physical read' 
ela= 163 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235520071WAIT #145673456782356: nam='cell single block physical read' 
ela= 194 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235520319WAIT #145673456782356: nam='cell single block physical read' 
ela= 255 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235520639WAIT #145673456782356: nam='cell single block physical read' 
ela= 178 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235520890WAIT #145673456782356: nam='cell single block physical read' 
ela= 241 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235521190WAIT #145673456782356: nam='cell single block physical read' 
ela= 175 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235521422WAIT #145673456782356: nam='cell single block physical read' 
ela= 174 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235521659WAIT #145673456782356: nam='cell single block physical read' 
ela= 235 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235521952WAIT #145673456782356: nam='cell single block physical read' 
ela= 187 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235522206WAIT #145673456782356: nam='cell single block physical read' 
ela= 222 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235522485WAIT #145673456782356: nam='cell single block physical read' 
ela= 226 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235522794WAIT #145673456782356: nam='cell single block physical read' 
ela= 225 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235523092WAIT #145673456782356: nam='cell single block physical read' 
ela= 176 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235523344WAIT #145673456782356: nam='cell single block physical read' 
ela= 184 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235523585WAIT #145673456782356: nam='cell single block physical read' 
ela= 215 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235523848WAIT #145673456782356: nam='cell single block physical read' 
ela= 227 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235524121WAIT #145673456782356: nam='cell single block physical read' 
ela= 216 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235524397WAIT #145673456782356: nam='cell single block physical read' 
ela= 159 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235524611WAIT #145673456782356: nam='cell single block physical read' 
ela= 248 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235524933WAIT #145673456782356: nam='cell single block physical read' 
ela= 172 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235525162WAIT #145673456782356: nam='cell single block physical read' 
ela= 252 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235525504WAIT #145673456782356: nam='cell single block physical read' 
ela= 347 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235525903WAIT #145673456782356: nam='cell single block physical read' 
ela= 301 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235526266WAIT #145673456782356: nam='cell single block physical read' 
ela= 222 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235526550WAIT #145673456782356: nam='cell single block physical read' 
ela= 169 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235526759WAIT #145673456782356: nam='cell single block physical read' 
ela= 233 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235527059WAIT #145673456782356: nam='cell single block physical read' 
ela= 217 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235527348WAIT #145673456782356: nam='cell single block physical read' 
ela= 229 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235527628WAIT #145673456782356: nam='cell single block physical read' 
ela= 195 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235527890WAIT #145673456782356: nam='cell single block physical read' 
ela= 155 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235528113WAIT #145673456782356: nam='cell single block physical read' 
ela= 219 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235528402WAIT #145673456782356: nam='cell single block physical read' 
ela= 207 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235528674WAIT #145673456782356: nam='cell single block physical read' 
ela= 219 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235528953WAIT #145673456782356: nam='cell single block physical read' 
ela= 174 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235529192WAIT #145673456782356: nam='cell single block physical read' 
ela= 229 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235529484WAIT #145673456782356: nam='cell single block physical read' 
ela= 190 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235529766WAIT #145673456782356: nam='cell single block physical read' 
ela= 201 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235530033WAIT #145673456782356: nam='cell single block physical read' 
ela= 259 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235530335WAIT #145673456782356: nam='cell single block physical read' 
ela= 211 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235530611WAIT #145673456782356: nam='cell single block physical read' 
ela= 242 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235530918WAIT #145673456782356: nam='cell single block physical read' 
ela= 158 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235531125WAIT #145673456782356: nam='cell single block physical read' 
ela= 211 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235531414WAIT #145673456782356: nam='cell single block physical read' 
ela= 306 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235531781WAIT #145673456782356: nam='cell single block physical read' 
ela= 169 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235531993WAIT #145673456782356: nam='cell single block physical read' 
ela= 221 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235532271WAIT #145673456782356: nam='cell single block physical read' 
ela= 165 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235532483WAIT #145673456782356: nam='cell single block physical read' 
ela= 187 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235532718WAIT #145673456782356: nam='cell single block physical read' 
ela= 233 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235533015WAIT #145673456782356: nam='cell single block physical read' 
ela= 176 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235533258WAIT #145673456782356: nam='cell single block physical read' 
ela= 247 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235533564WAIT #145673456782356: nam='cell single block physical read' 
ela= 247 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235533871WAIT #145673456782356: nam='cell single block physical read' 
ela= 231 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235534192WAIT #145673456782356: nam='cell single block physical read' 
ela= 181 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235534442WAIT #145673456782356: nam='cell single block physical read' 
ela= 217 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235534712WAIT #145673456782356: nam='cell single block physical read' 
ela= 190 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235534952WAIT #145673456782356: nam='cell single block physical read' 
ela= 188 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235535208WAIT #145673456782356: nam='cell single block physical read' 
ela= 265 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235535524WAIT #145673456782356: nam='cell single block physical read' 
ela= 210 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235535794WAIT #145673456782356: nam='cell single block physical read' 
ela= 235 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235536083WAIT #145673456782356: nam='cell single block physical read' 
ela= 187 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235536358WAIT #145673456782356: nam='cell single block physical read' 
ela= 225 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235536639WAIT #145673456782356: nam='cell single block physical read' 
ela= 207 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235536909WAIT #145673456782356: nam='cell single block physical read' 
ela= 236 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235537205WAIT #145673456782356: nam='cell single block physical read' 
ela= 216 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235537474WAIT #145673456782356: nam='cell single block physical read' 
ela= 292 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235537819WAIT #145673456782356: nam='cell single block physical read' 
ela= 188 cellhash#=6791789098 diskhash#=5637245889 bytes=8192 obj#=56135 
tim=13440235538071WAIT #145673456782356: nam='cell single block physical read' 
ela= 330 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235538489WAIT #145673456782356: nam='cell single block physical read' 
ela= 165 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235538732WAIT #145673456782356: nam='cell single block physical read' 
ela= 185 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235538977WAIT #145673456782356: nam='cell single block physical read' 
ela= 329 cellhash#=4462536783 diskhash#=5673267889 bytes=8192 obj#=56135 
tim=13440235539372

I checked that table has no row migration using analyze command. Issue is not 
happening in 12.1 as I worked with App team to point to 12.1 env vs 12.2. So 
either something is changed in 12.2 vs 12.1 or data need to be reorganized. Any 
suggestion to get better flow with event or trace
TxSanjay
    On Monday, May 20, 2019, 7:01:00 AM EDT, Jonathan Lewis 
<jonathan@xxxxxxxxxxxxxxxxxx> wrote:  
 
 
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: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


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

  

Other related posts: