Re: Query ASH for Undo Blocks

From: Lothar Flatz <l.flatz_at_bluewin.ch>
Date: Fri, 17 Jun 2022 16:04:45 +0200
Message-ID: <5a765dc0-12e7-1e84-b8fc-56ebe8a88370_at_bluewin.ch>



Hi Jonathan,

On the very database I am limited in rights, therefore I can not provide all the Information you asked for.
In particular there is no SQL Monitor, one execution runs to fast and I can not switch it on.
The statement is rather simple (I changed all Names):

  -------------------------------------------------------------------------------------------
| Id  | Operation                    | Name       | Rows  | Bytes | Cost (%CPU)| Time     |

|   0 | SELECT STATEMENT             |            | |       |     2 (100)|          |
|   1 |  FOR UPDATE                  |            | |       |            
|          |
|*  2 |   TABLE ACCESS BY INDEX ROWID| Tab1       |     1 | 42 |     2   
(0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | Index1     |     1 |       |     2   (0)| 00:00:01 |

Predicate Information (identified by operation id):


    2 - filter("Date_col1"<=CASE "status" WHEN 2 THEN :B1 WHEN 3 THEN
               LOCALTIMESTAMP(6) END )
    3 - access("ID"=:B3 AND "Date_col1"<=GREATEST(:B1,LOCALTIMESTAMP(6))
               )
        filter("ID2"=COALESCE(:B2,"ID2"))

Here the Stats of a batch run

Stat Name Statement   Per Execution % Snap

---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                        3.9098E+08 45.7     3.2 CPU Time (ms)                            3.8841E+08 45.4     4.5
Executions                                8,546,245 1.0     0.0
Buffer Gets                              3.2236E+10 3,772.0     6.9
Disk Reads                                  364,449 0.0     0.0
Parse Calls                                 187,232 0.0     0.0 Rows                                      6,441,767 0.8     N/A User I/O Wait Time (ms)                     328,217 0.0     0.0
Cluster Wait Time (ms)                            0 0.0     0.0
Application Wait Time (ms)                      117 0.0     0.0
Concurrency Wait Time (ms)                1,693,881 0.2     0.1
Invalidations                                     0 N/A     N/A Version Count                                 1,536 N/A     N/A Sharable Mem(KB)                             64,108 N/A     N/A

ASH says time is spent:

SQL_PLAN_OPERATION SQL_PLAN_OPTIONS        SQL_PLAN_LINE_ID   SECONDS    % seconds

CPU                            RANGE SCAN                            
3     415160           97
CPU                            BY INDEX ROWID                        
2       6100            1
CPU 1       3170            1 buffer busy waits                                                    1 1310            0
CPU 480            0
read by other session          BY INDEX ROWID                        
2        220            0
db file sequential read        BY INDEX ROWID                        
2        100            0 latch: cache buffers chains    BY INDEX ROWID                        2         90            0 buffer busy waits              BY INDEX ROWID                       
2         70            0
db file scattered read                                               1 
40            0

latch: cache buffers chains    RANGE SCAN                            3         30            0 latch: cache buffers chains                                          1 30            0

This is the Index Definition:

INDEX_NAME   COMPRESSION BLEVEL   LEAF_BLOCKS   DISTINCT_KEYS   AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY Index1      DISABLED               3         112885 6290                         17                        102

col stats
COLUMN_NAME NUM_DISTINCT  NUM_NULLS NUM_BUCKETS


  • ---------- ----------- ID 56   37349080           1 Date_col1 2628   39004885           1

Bind Variable B2 is always Null btw. B1 is never captured. (Do you know why? I wonder if the reason might be that it is used in an expression.)

These Numbers are from a Test DB. Here I got about 200 Buffers per execution. Question: where does the rest come from?



| Id  | Operation                    | Name       | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
|   0 | SELECT STATEMENT             |            | 49M|        |     
42M|15:17:46.13 |      17G|  12889 |
|   1 |  FOR UPDATE                  |            | 49M|        |     
42M|15:17:46.13 |      17G|  12889 |
|*  2 |   TABLE ACCESS BY INDEX ROWID| Tab1       | 49M|      2 |     57M|13:45:46.36 |      16G|  12874 | |*  3 |    INDEX RANGE SCAN          | Index1     |     49M| 22 |     12G|07:27:46.63 |      10G|   1536 |

Thanks

Lothar

Am 13.06.2022 um 20:13 schrieb Jonathan Lewis:

>
> What's the scale of the problem?  i.e. how long does the query run, 
> how complex is the query/plans, how much of the time relates to the 
> index range scan, how many buffer gets does that index range scan step 
> take, how many do you think it should take.  How frequently doe the 
> query run, how repeatable is the experiment?
>
> How are you working out that that index range scan is doing more 
> buffer gets than you expect - have you enabled SQL Monitor for the SQL_Id?
>
> Regards
> Jonathan Lewis
>
>
> On Mon, 13 Jun 2022 at 11:35, Lothar Flatz <l.flatz_at_bluewin.ch> wrote:
>
>     Hi,
>
>     there is a plan with an Index Range scan that generates way more
>     buffer_gets than you would expect.
>     Would it be correct to query active session history using
>     CURRENT_FILE#
>     and CURRENT_BLOCK# to check against DBA_EXTENTS
>     to find out if some buffer gets are coming from undo?
>     The query does work, but i am not sure if the result is showing the
>     indented answer.
>
>     Thanks
>
>     Lothar
>
>
>
>     --
>     http://www.freelists.org/webpage/oracle-l
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Fri Jun 17 2022 - 16:04:45 CEST

Original text of this message