Re: High consistent Gets and response time in prod
Date: Sat, 1 May 2021 03:07:35 +0300
Message-ID: <CAOVevU7nD-9ocw70eLWXH6GfqxjLJ4n_xQVG508Cq3SBFYhjNA_at_mail.gmail.com>
On Sat, May 1, 2021 at 2:55 AM Sayan Malakshinov <xt.and.r_at_gmail.com> wrote:
> 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
>
-- Best regards, Sayan Malakshinov Oracle performance tuning engineer Oracle ACE Associate http://orasql.org -- http://www.freelists.org/webpage/oracle-lReceived on Sat May 01 2021 - 02:07:35 CEST