Re: High consistent Gets and response time in prod

From: Sayan Malakshinov <xt.and.r_at_gmail.com>
Date: Sat, 1 May 2021 02:55:49 +0300
Message-ID: <CAOVevU7UbxisB-ZSjSOuLvW0cKoQ5dcJjDemR7PGPWqkRMv7zA_at_mail.gmail.com>



Hi Ram,

 11.5M blocks

Most likely there were massive deletes and you have a lot of empty blocks. Anyway I wouldn't guess and suggest you just start your query and run Tanel Poder's session snapper on your session for 5-10 seconds to get real info what's going on:
https://tanelpoder.com/snapper/
And just post its output here.
It doesn't require nor diagnostics nor tuning packs. Anyway for such a strange query, I would suggest forcing IFS by primary key index, to avoid "adaptive serial direct path reads" which lead to object checkpoint. for example using SQL Patch which also doesn't require those packs.

On Sat, May 1, 2021 at 2:36 AM John Piwowar <jpiwowar_at_gmail.com> wrote:

> You'll probably get better info from dbms_monitor and tkprof than
> autotrace, but I think your main culprit/clue is the combination of high
> consistent gets and "parallel queries running against the prod table for
> 30+ hours." Depending on what those PQ are doing, you are likely to be
> hitting UNDO pretty hard to get a read-consistent view of even one row.
>
> On Fri, Apr 30, 2021 at 3:39 PM Ram Raman <veeeraman_at_gmail.com> wrote:
>
>> Hi,
>>
>> Fri evening and I have a problem. grrr..
>>
>> We have a simple SELECT statement like this:
>>
>> select * from c.pd where rownum <=1
>>
>> This executes instantly in test, but takes over 2 mins in prod. I did
>> some autotrace and here are some stats:
>>
>> TEST:
>> =====
>> ...
>> Elapsed: 00:00:00.03
>>
>> Execution Plan
>> ----------------------------------------------------------
>> Plan hash value: 1087134000
>>
>>
>> ---------------------------------------------------------------------------------
>> | Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
>> Time |
>>
>> ---------------------------------------------------------------------------------
>> | 0 | SELECT STATEMENT | | 1 | 983 | 2 (0)|
>> 00:00:01 |
>> |* 1 | COUNT STOPKEY | | | | |
>> |
>> | 2 | TABLE ACCESS FULL| PD | 1 | 983 | 2 (0)| 00:00:01 |
>>
>> ---------------------------------------------------------------------------------
>>
>> Predicate Information (identified by operation id):
>> ---------------------------------------------------
>>
>> 1 - filter(ROWNUM<=1)
>>
>>
>> Statistics
>> ----------------------------------------------------------
>> 0 recursive calls
>> 0 db block gets
>> 3 consistent gets
>> 0 physical reads
>> 0 redo size
>> 8556 bytes sent via SQL*Net to client
>> 408 bytes received via SQL*Net from client
>> 2 SQL*Net roundtrips to/from client
>> 0 sorts (memory)
>> 0 sorts (disk)
>> 1 rows processed
>>
>>
>> PROD:
>> =====
>>
>> ...
>> Elapsed: 00:02:13.61
>>
>> Execution Plan
>> ----------------------------------------------------------
>> Plan hash value: 1087134000
>>
>>
>> ---------------------------------------------------------------------------------
>> | Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
>> Time |
>>
>> ---------------------------------------------------------------------------------
>> | 0 | SELECT STATEMENT | | 1 | 993 | 4 (0)|
>> 00:00:01 |
>> |* 1 | COUNT STOPKEY | | | | |
>> |
>> | 2 | TABLE ACCESS FULL| PD | 1 | 993 | 4 (0)| 00:00:01 |
>>
>> ---------------------------------------------------------------------------------
>>
>> Predicate Information (identified by operation id):
>> ---------------------------------------------------
>>
>> 1 - filter(ROWNUM<=1)
>>
>>
>> Statistics
>> ----------------------------------------------------------
>> 0 recursive calls
>> 0 db block gets
>> 11290619 consistent gets
>> 11289575 physical reads
>> 8024 redo size
>> 8510 bytes sent via SQL*Net to client
>> 408 bytes received via SQL*Net from client
>> 2 SQL*Net roundtrips to/from client
>> 0 sorts (memory)
>> 0 sorts (disk)
>> 1 rows processed
>>
>>
>> First thing that jumps out is the number of consistent gets, which is in
>> the same range in prod again and again. In test also, the consistent gets
>> are in the same range for repeated executions - just couple of dozens.
>>
>> I checked the stats and here they are:
>>
>> Test:
>> =====
>>
>> TABLE_NAME NUM_ROWS LAST_ANAL BLOCKS
>> AVG_ROW_LEN PCT_FREE PCT_USED EMPTY_BLOCKS AVG_SPACE
>> ------------------------ ------------------------ --------- ------------
>> ----------- ---------- ---------- ------------ ----------
>> CHAIN_CNT PAR MON COMPRESS
>> ---------- --- --- --------
>> PD 989,633 25-FEB-21 143,844
>> 983 10 0 0
>> 0 NO YES DISABLED
>>
>>
>>
>> PROD:
>> =====
>>
>> TABLE_NAME NUM_ROWS LAST_ANAL BLOCKS
>> AVG_ROW_LEN PCT_FREE PCT_USED EMPTY_BLOCKS AVG_SPACE
>> ------------------------ ------------------------ --------- ------------
>> ----------- ---------- ---------- ------------ ----------
>> CHAIN_CNT PAR MON COMPRESS
>> ---------- --- --- --------
>> PD 1,420,080 29-APR-21 11,537,288
>> 993 10 0 0
>> 0 NO YES DISABLED
>>
>> What is confusing is that the number of blocks the table takes in the
>> prod. I did some calc and I feel that it should take around 172,000+
>> blocks, given our block size is 8K, but I am unable to explain 11.5M
>> blocks.
>>
>> 19c, if that helps. Table definitions are identical in prod and test.
>> Recollecting the table stats in prod at 50% has not helped with the query
>> which I did few minutes ago. Stats almost remain the same - just the number
>> of rows has increased by a few hundred. I see some parallel queries
>> running against the prod table for 30+ hours.
>>
>> Thanks a lot,
>> Ram.
>>
>>
>>

-- 
Best regards,
Sayan Malakshinov
Oracle performance tuning engineer
Oracle ACE Associate
http://orasql.org

--
http://www.freelists.org/webpage/oracle-l
Received on Sat May 01 2021 - 01:55:49 CEST

Original text of this message