Search

Top 60 Oracle Blogs

Recent comments

Oakies Blog Aggregator

Hint Reports

Nigel Bayliss has posted a note about a frequently requested feature that has now appeared in Oracle 19c – a mechanism to help people understand what has happened to their hints.  It’s very easy to use, it’s just another format option to the “display_xxx()” calls in dbms_xplan; so I thought I’d run up a little demonstration (using an example I first generated 18 years and 11 versions ago) to make three points: first, to show the sort of report you get, second to show you that the report may tell you what has happened, but that doesn’t necessarily tell you why it has happened, and third to remind you that you should have stopped using the /*+ ordered */ hint 18 years ago.

I’ve run the following code on livesql:


rem
rem     Script:         c_ignorehint.sql
rem     Author:         Jonathan Lewis
rem     Dated:          March 2001
rem


drop table ignore_1;
drop table ignore_2;

create table ignore_1
nologging
as
select
        rownum          id,
        rownum          val,
        rpad('x',500)   padding
from    all_objects
where   rownum <= 3000
;

create table ignore_2
nologging
as
select
        rownum          id,
        rownum          val,
        rpad('x',500)   padding
from    all_objects
where   rownum <= 500
;

alter table ignore_2
add constraint ig2_pk primary key (id);


explain plan for
update
        (
                select
                        /*+
                                ordered
                                use_nl(i2)
                                index(i2,ig2_pk)
                        */
                        i1.val  val1,
                        i2.val  val2
                from
                        ignore_1        i1,
                        ignore_2        i2
                where
                        i2.id = i1.id
                and     i1.val <= 10
        )
set     val1 = val2
;

select * from table(dbms_xplan.display(null,null,'hint_report'));

explain plan for
update
        (
                select
                        /*+
                                use_nl(i2)
                                index(i2,ig2_pk)
                        */
                        i1.val  val1,
                        i2.val  val2
                from
                        ignore_1        i1,
                        ignore_2        i2
                where
                        i2.id = i1.id
                and     i1.val <= 10
        )
set     val1 = val2
;

select * from table(dbms_xplan.display(null,null,'hint_report'));

As you can see I’ve simply added the format option “hint_report” to the call to dbms_xplan.display(). Before showing you the output I’ll just say a few words about the plans we might expect from the two versions of the update statement.

Given the /*+ ordered */ hint in the first statement we might expect Oracle to do a full tablescan of ignore_1 then do a nested loop into ignore_2 (obeying the use_nl() hint) using the (hinted) ig2_pk index. In the second version of the statement, and in the absence of the ordered hint, it’s possible that the optimizer will still use the same path but, in principle, it might find some other path.

So what do we get ? In order here are the two execution plans:


Plan hash value: 3679612214
 
--------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT                      |          |    10 |   160 |   111   (0)| 00:00:01 |
|   1 |  UPDATE                               | IGNORE_1 |       |       |            |          |
|*  2 |   HASH JOIN                           |          |    10 |   160 |   111   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID BATCHED| IGNORE_2 |   500 |  4000 |    37   (0)| 00:00:01 |
|   4 |     INDEX FULL SCAN                   | IG2_PK   |   500 |       |     1   (0)| 00:00:01 |
|*  5 |    TABLE ACCESS STORAGE FULL          | IGNORE_1 |    10 |    80 |    74   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("I2"."ID"="I1"."ID")
   5 - storage("I1"."VAL"<=10)
       filter("I1"."VAL"<=10)
 
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 3 (U - Unused (1))
---------------------------------------------------------------------------
   1 -  SEL$DA9F4B51
           -  ordered
 
   3 -  SEL$DA9F4B51 / I2@SEL$1
         U -  use_nl(i2)
           -  index(i2,ig2_pk)




Plan hash value: 1232653668
 
------------------------------------------------------------------------------------------
| Id  | Operation                     | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT              |          |    10 |   160 |    76   (0)| 00:00:01 |
|   1 |  UPDATE                       | IGNORE_1 |       |       |            |          |
|   2 |   NESTED LOOPS                |          |    10 |   160 |    76   (0)| 00:00:01 |
|   3 |    NESTED LOOPS               |          |    10 |   160 |    76   (0)| 00:00:01 |
|*  4 |     TABLE ACCESS STORAGE FULL | IGNORE_1 |    10 |    80 |    74   (0)| 00:00:01 |
|*  5 |     INDEX UNIQUE SCAN         | IG2_PK   |     1 |       |     0   (0)| 00:00:01 |
|   6 |    TABLE ACCESS BY INDEX ROWID| IGNORE_2 |     1 |     8 |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   4 - storage("I1"."VAL"<=10)
       filter("I1"."VAL"<=10)
   5 - access("I2"."ID"="I1"."ID")
 
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 2
---------------------------------------------------------------------------
   5 -  SEL$DA9F4B51 / I2@SEL$1
           -  index(i2,ig2_pk)
           -  use_nl(i2)

As you can see, the “Hint Report” shows us how many hints have been seen in the SQL text, then the body of the report shows us which query block, operation and table (where relevant) each hint has been associated with, and whether it has been used or not.

The second query has followed exactly the plan I predicted for the first query and the report has shown us that Oracle noted, and used, the use_nl() and index() hints to access table ignore2, deciding for itself to visit the tables in the order ignore_1 -> ignore_2, and doing a full tablescan on ignore_1.

The first query reports three hints, but flags the use_nl() hint as unused. (There is (at least) one other flag that could appear against a hint – “E” for error (probably syntax error), so we can assume that this hint is not being ignored because there’s something wrong with it.) Strangely the report tells us that the optimizer has used the ordered hint but we can see from the plan that the tables appear to be in the opposite order to the order we specified in the from clause, and the chosen order has forced the optimizer into using an index full scan on ig2_pk because it had to obey our index() hint.  Bottom line – the optimizer has managed to find a more costly plan by “using but apparently ignoring” a hint that described the cheaper plan that we would have got if we hadn’t used the hint.

Explanation

Query transformation can really mess things up and you shouldn’t be using the ordered hint.

I’ve explained many times over the years that the optimizer evaluates the cost of an update statement by calculating the cost of selecting the rowids of the rows to be updated. In this case, which uses an updatable join view, the steps taken to follow this mechanism this are slightly more complex.  Here are two small but critical extracts from the 10053 trace file (taken from an 18c instance):


CVM:   Merging SPJ view SEL$1 (#0) into UPD$1 (#0)
Registered qb: SEL$DA9F4B51 0x9c9966e8 (VIEW MERGE UPD$1; SEL$1; UPD$1)

...

SQE: Trying SQ elimination.
Query after View Removal
******* UNPARSED QUERY IS *******
SELECT
        /*+ ORDERED INDEX ("I2" "IG2_PK") USE_NL ("I2") */
        0
FROM    "TEST_USER"."IGNORE_2" "I2",
        "TEST_USER"."IGNORE_1" "I1"
WHERE   "I2"."ID"="I1"."ID"
AND     "I1"."VAL"<=10


The optimizer has merged the UPDATE query block with the SELECT query block to produce a select statement that will produce the necessary plan (I had thought that i1.rowid would appear in the select list, but the ‘0’ will do for costing purposes). Notice that the hints have been preserved as the update and select were merged but, unfortunately, the merge mechanism has reversed the order of the tables in the from clause. So the optimizer has messed up our select statement, then obeyed the original ordered hint!

Bottom line – the hint report is likely to be very helpful in most cases but you will still have to think about what it is telling you, and you may still have to look at the occasional 10053 to understand why the report is showing you puzzling results. You should also stop using a hint that was replaced by a far superior hint more than 18 years ago – the ordered hint in my example should have been changed to /*+ leading(i1 i2) */ in Oracle 9i.

SYS.STATS_TARGET$

Here is a little note about the SYS.STATS_TARGET$ table used by the automatic statistics gathering job run at maintenance window, or when running it manually with:

exec dbms_auto_task_immediate.gather_optimizer_stats

This table is not documented and has no view on it, so those are only my guesses about what I observed, and comments are welcome. Basically, this table is used by the Auto Stats job to list the tables to process, from one execution to the other.

Note that in 12c the same information is updated into DBA_OPTSTAT_OPERATION_TASKS and visible through DBMS_STATS.REPORT_STATS_OPERATIONS. But I still use STATS_TARGET$ so see in real-time what is currently processed.

Columns description

STATUS

When the Auto Stats job lists the objects to process, they are in state PENDING (STATUS=0).

Then, when it is its turn to be processed, the START_TIME is set to current timestamp and it can be SKIPPED (STATUS=4) or processed IN PROGRESS (STATUS=1)

Then, when processing ends the END_TIME is set to current timestamp and the status can be COMPLETED (STATUS=2) if successful, or FAILED (STATUS=3) in case of error. If it ends before completion at the end of the maintenance window, the IN PROGRESS and PENDING become TIMED OUT (STATUS=5)

Note that START_TIME and END_TIME have been introduced in 12c

STALENESS

This is similar, but more precise, than the STALE column in DBA_TAB_STATISTICS. Rather than YES/NO we have here an evaluation of staleness (comparing the modifications from DBA_TAB_MODIFICATIONS with the number of rows) in a logarithmic scale between -1.0 and 1.0 where the lowest is the more stale.

TYPE# and OBJ#

This is the OBJECT_TYPE and OBJECT_ID from DBA_OBJECTS. The decode of TYPE# to OBJECT_TYPE is in the DBA_OBJECTS view on OBJ$ definition. Rather than hardcoding it in my queries, I get it from:

select /*+ RESULT_CACHE (SYSOBJ=TRUE)*/ 
distinct type#,object_type
from (select object_id obj#,object_type from dba_objects)
natural join sys.obj$

OSIZE

This is the estimated object size, from the known number of blocks and blocksize, and can be used to estimate roughly the time it takes to gather statistics.

BO# and PART#

Those are the physical identifiers for partitions and subpartitions, tables: it makes the links with the parent object, and between index and table, probably for the purpose of CASCADE gathering.

FLAGS

This is a bitmap with some information about the staleness and the status. Here is my decode (which may be wrong as it is not documented)

ltrim(
case when bitand(flags,1)=1 then ',RETRY' end
|| case when bitand(flags,2)=2 then ',NON-SEGMENT' end
|| case when bitand(flags,4)=4 then ',?' end
|| case when bitand(flags,8)=8 then ',TIMED OUT' end
|| case when bitand(flags,16)=16 then ',?' end
|| case when bitand(flags,32)=32 then ',GATHER GLOBAL' end
|| case when bitand(flags,64)=64 then ',GATHER PARTITION' end
|| case when bitand(flags,128)=128 then ',MISSING COL STATS' end
|| case when bitand(flags,256)=256 then ',STALE STATS' end
|| case when bitand(flags,512)=512 then ',NO STATS' end
|| case when bitand(flags,1024)=1024 then ',HAS DIRECTIVES' end
|| case when bitand(flags,2048)=2048 then ',MISSING EXTENSION' end
|| case when bitand(flags,4096)=4096 then ',MISSING HISTOGRAM' end
|| case when bitand(flags,8192)=8192 then ',CASCADED' end
|| case when bitand(flags,16384)=16384 then ',REPORTING RUN' end
|| case when bitand(flags,32768)=32768 then ',FIXED TABLE' end
|| case when bitand(flags,65536)=65536 then ',SYNOPSIS MISMATCH' end
,',') flags

RETRY is for the gathering which was IN PROGRESS and was stopped with TIMED OUT.

SID, SERIAL#

The last session running the Auto Stats (i.e PENDING, IN PROGRESS, TIMED OUT) is identified here so you can join with V$SESSION or even V$ACTIVE_SESSION_HISTORY to get more information afterward about the duration (which is END_TIME-START_TIME). You can also find the long-running ones in V$SQL_MONITOR.

Query examples

details

Here is an example while the Auto Stats job is running. This shows which table is currently gathered (IN PROGRESS), already done (COMPLETED) or to be done (PENDING). The flags indicate that the previous execution was TIMED OUT, and which is global level gathering.

I also join with V$SESSION in order to see the currently running job (and its login time) as I’m in 11g without the START_TIME:

Here is the query I used for this output:

select logon_time
--,start_time,end_time,end_time-start_time duration
--,start_time-lag(end_time)over(partition by sid,serial# order by start_time) after_previous,
,object_type,owner,object_name,subobject_name,sid||','||serial# "sid/ser#",round(osize/1024/1024/1024) GBytes
,rtrim(case status when 0 then 'PENDING' when 1 then 'IN PROGRESS' when 2 then 'COMPLETED' when 3 then 'FAILED'
when 4 then 'SKIPPED' when 5 then 'TIMEOUT' end) STATUS,status status#
,case staleness when -100 then 'MISSING' when -99 then null
else rtrim('STALE '||lpad(' ',round(2*(1+(staleness))),'+')) end staleness
,ltrim(
case when bitand(flags,1)=1 then ',TIMED OUT' end
|| case when bitand(flags,2)=2 then ',NON-SEGMENT' end
|| case when bitand(flags,4)=4 then ',4' end
|| case when bitand(flags,8)=8 then ',TIMED_OUT' end
|| case when bitand(flags,16)=16 then ',16' end
|| case when bitand(flags,32)=32 then ',GATHER GLOBAL' end
|| case when bitand(flags,64)=64 then ',GATHER PARTITION' end
|| case when bitand(flags,128)=128 then ',MISSING CSTATS' end
|| case when bitand(flags,256)=256 then ',STALE STATS' end
|| case when bitand(flags,512)=512 then ',NO STATS' end
|| case when bitand(flags,1024)=1024 then ',HAS DIRECTIVES' end
|| case when bitand(flags,2048)=2048 then ',MISSING EXTENSION' end
|| case when bitand(flags,4096)=4096 then ',MISSING HISTOGRAM' end
|| case when bitand(flags,8192)=8192 then ',CASCADED' end
|| case when bitand(flags,16384)=16384 then ',REPORTING RUN' end
|| case when bitand(flags,32768)=32768 then ',FIXED TABLE' end
|| case when bitand(flags,65536)=65536 then ',SYNOPSIS MISMATCH' end
,',') flags
from (
select *
from STATS_TARGET$
natural left outer join (select /*+ result_cache */ distinct type#,object_type from (select object_id obj#,object_type from dba_objects) natural join sys.obj$)
natural left outer join (select object_id obj#,owner,object_name,subobject_name from dba_objects)
natural left outer join (select sid,serial#,program,sql_id,logon_time from gv$session)
left outer join (select bo#,part#,hiboundval,analyzetime,obj# part_obj# from sys.tabpart$) using(bo#,part#)
) v
--order by end_time desc nulls last, start_time desc nulls last
order by logon_time desc nulls last,status#
/

summary

Here is another query which checks the global status while the Auto Stats job is running:

select logon_time,status,staleness,count(*),sum(GBytes) GBytes
,object_type,round(100*sum(GBytes)/max(TotGB)) "%"
from (
select logon_time,object_type,round(osize/1024/1024/1024) GBytes,sum(osize/1024/1024/1024)over(partition by logon_time) TotGB
,rtrim(case status when 0 then 'PENDING' when 1 then 'IN PROGRESS' when 2 then 'COMPLETED' when 3 then 'FAILED' when 4 then 'SKIPPED' when 5 then 'TIMEOUT' end) STATUS
,case staleness when -100 then 'MISSING' when -99 then null else 'STALE' end staleness
from STATS_TARGET$
natural left outer join (select /*+ result_cache */ distinct type#,object_type from (select object_id obj#,object_type from dba_objects) natural join sys.obj$)
natural left outer join (select sid,serial#,program,sql_id,logon_time from gv$session)
)
group by logon_time,object_type,status,staleness having logon_time is not null
order by logon_time nulls last,status,object_type,staleness;
LOGON_TIME        STATUS      STALENE   COUNT(*)     GBYTES
----------------- ----------- ------- ---------- ----------
15-JAN-2019 08:44 COMPLETED STALE 288 2177
15-JAN-2019 08:44 IN PROGRESS STALE 1 210
15-JAN-2019 08:44 PENDING MISSING 58744 18311
15-JAN-2019 08:44 PENDING STALE 2567 8579
15-JAN-2019 08:44 PENDING 55 0

Processing order

As this table is used to list the tables to process, the columns are used to order it. We know that the Auto Stats starts with the most stale (and MISSING is the first there). But before that, the tables are listed before the partitions, and partitions before subpartition. And tables are processed before indexes.

EXPORT not GATHER with DBMS_STATS

Just a short post today on something that came in as a question for the upcoming Office Hours session which I thought could be covered quickly in a blog post without needing a lot of additional discussion for which Office Hours is more suited to.

The question was:

“When I gather statistics using DBMS_STATS, can I just create a statistic table and pass that as a parameter to get the results of the gather”

And the answer simply is “No” Smile but let me clear up the confusion.

Many DBMS_STATS routines allow you to pass the name of the “statistics table” into which statistical information for the table, schema, database etc will be stored. For example, you can see the STAT-prefixed parameter to GATHER_TABLE_STATS


PROCEDURE GATHER_TABLE_STATS
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 OWNNAME                        VARCHAR2                IN
 TABNAME                        VARCHAR2                IN
 PARTNAME                       VARCHAR2                IN     DEFAULT
 ESTIMATE_PERCENT               NUMBER                  IN     DEFAULT
 BLOCK_SAMPLE                   BOOLEAN                 IN     DEFAULT
 METHOD_OPT                     VARCHAR2                IN     DEFAULT
 DEGREE                         NUMBER                  IN     DEFAULT
 GRANULARITY                    VARCHAR2                IN     DEFAULT
 CASCADE                        BOOLEAN                 IN     DEFAULT
 STATTAB                        VARCHAR2                IN     DEFAULT
 STATID                         VARCHAR2                IN     DEFAULT
 STATOWN                        VARCHAR2                IN     DEFAULT
 NO_INVALIDATE                  BOOLEAN                 IN     DEFAULT
 STATTYPE                       VARCHAR2                IN     DEFAULT
 FORCE                          BOOLEAN                 IN     DEFAULT
 CONTEXT                        CCONTEXT                IN     DEFAULT
 OPTIONS                        VARCHAR2                IN     DEFAULT

The statistics table must be of a certain structure, which is managed via the API as well using the CREATE_STAT_TABLE routine.


SQL> exec dbms_stats.create_stat_table('','st')

PL/SQL procedure successfully completed.

SQL> desc ST
 Name                          Null?    Type
 ----------------------------- -------- --------------------
 STATID                                 VARCHAR2(128)
 TYPE                                   CHAR(1)
 VERSION                                NUMBER
 FLAGS                                  NUMBER
 C1                                     VARCHAR2(128)
 C2                                     VARCHAR2(128)
 C3                                     VARCHAR2(128)
 C4                                     VARCHAR2(128)
 C5                                     VARCHAR2(128)
 C6                                     VARCHAR2(128)
 N1                                     NUMBER
 N2                                     NUMBER
 N3                                     NUMBER
 N4                                     NUMBER
 N5                                     NUMBER
 N6                                     NUMBER
 N7                                     NUMBER
 N8                                     NUMBER
 N9                                     NUMBER
 N10                                    NUMBER
 N11                                    NUMBER
 N12                                    NUMBER
 N13                                    NUMBER
 D1                                     DATE
 T1                                     TIMESTAMP(6) WITH TI
                                        ME ZONE
 R1                                     RAW(1000)
 R2                                     RAW(1000)
 R3                                     RAW(1000)
 CH1                                    VARCHAR2(1000)
 CL1                                    CLOB
 BL1                                    BLOB

But when calling the GATHER_xxx routines, if you pass the name of the statistic table, please note that this is for getting a copy of the relevant statistics before the fresh gathering of statistics is done. We can see this with a simple demo.


SQL> create table t1 as select * from dba_objects;

Table created.

SQL>
SQL> select num_rows
  2  from   user_tables
  3  where  table_name = 'T1';

  NUM_ROWS
----------
     83608

1 row selected.

So we can see that the table T1 has ~83,000 rows in it. Since I’m running this on 12c, there was no need to gather statistics after this initial load, because they were collected automatically as part of the loading process. (Very nifty!).

I now add another ~250,000 rows and perform a new GATHER_TABLE_STATS call, this time passing in the name of the statistics table (ST) that I just created.


SQL>
SQL> insert into t1
  2  select * from t1;

83608 rows created.

SQL>
SQL> insert into t1
  2  select * from t1;

167216 rows created.

SQL>
SQL> begin
  2  dbms_stats.gather_table_stats
  3   ( ownname=>'MCDONAC',
  4     tabname=>'T',
  5     stattab=>'ST',
  6     statid=>'STATS'
  7  );
  8  end;
  9  /

PL/SQL procedure successfully completed.

Digging into the statistic table data, you can see that the number of rows recorded for T1 is 83597, which is the before image of the optimizer stat, not the after image.


SQL> select * from st where c1 = 'T1' and type = 'T'
  2  @pr
==============================
STATID                        : STATS
TYPE                          : T
VERSION                       : 8
FLAGS                         : 2
C1                            : T1
C2                            :
C3                            :
C4                            :
C5                            : MCDONAC
C6                            :
N1                            : 83597
N2                            : 1607
N3                            : 129
N4                            : 83597
N5                            :
N6                            :
N7                            :
N8                            :
N9                            : 0
N10                           :
N11                           :
N12                           :
N13                           :
D1                            : 16-JAN-19
T1                            :
R1                            :
R2                            :
R3                            :
CH1                           :
CL1                           :
BL1                           :

PL/SQL procedure successfully completed.

So just remember that if you want to get the DBMS_STATS information that is the result of a GATHER_xxx call, then you can follow it up with the appropriate EXPORT_xxx call to dump the data.

Announcement: New “Oracle Diagnostics and Performance Tuning” Seminar Now Available !!

It’s been a work in progress for quite some time, with many of my customers asking when will it be completed. Well, I’m very excited to announce that I have finally completed my new 2 day “Oracle Diagnostics and Performance Tuning” seminar and that it’s ready to be presented. I already have a number of […]

My APEX was fine and then it wasn’t

I got a nasty shock this morning when I fired up my local Application Expression installation.

image

It had been working fine and all of a sudden…just dead. I sounded like all of those family members that as I.T practitioners we have to deal with (and that we’re so sceptical of) when they say: “I didn’t change anything…it just stopped!” Smile

In keeping with the treatment of family members, I then adopted the advice that I normally give them first.

turning_on_and_off

and upon restart, I saw the following during the startup


C:\oracle\ords181>java -jar ords.war standalone
2019-01-11 11:47:36.071:INFO::main: Logging initialized @1378ms to org.eclipse.jetty.util.log.StdErrLog
Jan 11, 2019 11:47:36 AM
INFO: HTTP and HTTP/2 cleartext listening on port: 8080
Jan 11, 2019 11:47:36 AM
INFO: The document root is serving static resources located in: C:\oracle\ords181\conf\ords\standalone\doc_root
2019-01-11 11:47:36.409:INFO:oejs.Server:main: jetty-9.4.z-SNAPSHOT, build timestamp: 2017-11-22T05:27:37+08:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
2019-01-11 11:47:36.422:INFO:oejs.session:main: DefaultSessionIdManager workerName=node0
2019-01-11 11:47:36.423:INFO:oejs.session:main: No SessionScavenger set, using defaults
2019-01-11 11:47:36.423:INFO:oejs.session:main: Scavenging every 600000ms
Jan 11, 2019 11:47:37 AM
WARNING: The pool named: |apex|| is invalid and will be ignored: The connection pool named: apex is not correctly configured, due to the following error(s): ORA-28001: the password has expired

Jan 11, 2019 11:47:37 AM
WARNING: The pool named: |apex|al| is invalid and will be ignored: The connection pool named: apex_al is not correctly configured, due to the following error(s): ORA-28001: the password has expired

Since security is our #1 thing for 2019 and probably should be the #1 item on your agenda for 2019, this was caused by some improvements to the Oracle defaults when you perform a database installation. Rather than the default being an “flexible” (aka loose Smile) policy we used to have when it comes to password management, we’ve gone for some more sensible options out of the box.


SQL> select * from dba_profiles order by 1,2
PROFILE          RESOURCE_NAME                    RESOURCE LIMIT
---------------- -------------------------------- -------- -----------
DEFAULT          COMPOSITE_LIMIT                  KERNEL   UNLIMITED
DEFAULT          CONNECT_TIME                     KERNEL   UNLIMITED
DEFAULT          CPU_PER_CALL                     KERNEL   UNLIMITED
DEFAULT          CPU_PER_SESSION                  KERNEL   UNLIMITED
DEFAULT          FAILED_LOGIN_ATTEMPTS            PASSWORD 10
DEFAULT          IDLE_TIME                        KERNEL   UNLIMITED
DEFAULT          INACTIVE_ACCOUNT_TIME            PASSWORD UNLIMITED
DEFAULT          LOGICAL_READS_PER_CALL           KERNEL   UNLIMITED
DEFAULT          LOGICAL_READS_PER_SESSION        KERNEL   UNLIMITED
DEFAULT          PASSWORD_GRACE_TIME              PASSWORD 7
DEFAULT          PASSWORD_LIFE_TIME               PASSWORD 180
DEFAULT          PASSWORD_LOCK_TIME               PASSWORD 1
DEFAULT          PASSWORD_REUSE_MAX               PASSWORD UNLIMITED
DEFAULT          PASSWORD_REUSE_TIME              PASSWORD UNLIMITED
DEFAULT          PASSWORD_VERIFY_FUNCTION         PASSWORD NULL
DEFAULT          PRIVATE_SGA                      KERNEL   UNLIMITED
DEFAULT          SESSIONS_PER_USER                KERNEL   UNLIMITED

So if you want your APEX public accounts (and I stress, no others!) to have a non-expiring password, then you should create a custom profile for those accounts and assign them accordingly.


create profile no_expire 
limit  password_life_time  unlimited;
  
alter user apex_public_user      profile no_expire ;
alter user apex_rest_public_user profile no_expire ;
alter user apex_listener         profile no_expire ;
alter user ords_public_user      profile no_expire ;

This will ensure you don’t get an unexpected drama next time you want to fire up Application Express.

Flamegraph with function annotation

Recently, Franck Pachot tweeted the following:
https://fritshoogland.files.wordpress.com/2019/01/tweet-franck.png?w=84&... 84w, https://fritshoogland.files.wordpress.com/2019/01/tweet-franck.png 310w" sizes="(max-width: 168px) 100vw, 168px" />
This is a very clever way of using Brendan Gregg’s flame graphs for Oracle database process flame graphs and using my ora_functions project database.

However, the awk script uses a full match using f[$2]:
– f is an array with the function name annotations filled using {f[$1]=$2;next}.
– // means to only work on lines that have in it.
– The lines have the oracle function stuck to , for example: kcbgtcr.
– The first sub() function (substitute); which is sub(“”,”& “) places a space after “” so it looks like: kcbgtcr; “&” means “the first argument of the sub function”.
– FS=” ” means the field separator is a space.
– The next sub() function; which is sub(“”,””f[$2]”&”) substitutes on the pattern, and uses the f array using the second field ($2) of the input, which now is the oracle function thanks to the field separator and the previous sub() function.

But…the function names in the database/csv file are build up on layers. I done this deliberately to avoid having to type all the layer names for a function when entering new ones, but more importantly so I can actually identify the code layers in the oracle executable. Because of the layers, I don’t need the full function descriptions, I can still get an understanding what is going on by looking in what layer a function is called.

To get the layers in the function names, I added a script in my ora_functions repository called ‘annotate_flamegraph.awk’, which takes the function name csv file actually exactly like Franck did, but now builds up the annotation of every function in an existing flamegraph. It simply takes an existing flamegraph SVG file with oracle database functions as an input, and outputs the annotated version on STDOUT, so this is how it’s run to get an annotated SVG:

$ ./annotate_flamegraph.awk dt_11856.txt_1.fold.svg > dt_11856.txt_1.fold.annotated.svg

This is how it looks like (please mind these are snapshots from flamegraph output in a browser):
https://fritshoogland.files.wordpress.com/2019/01/flamegraph-annotation1... 600w, https://fritshoogland.files.wordpress.com/2019/01/flamegraph-annotation1... 150w" sizes="(max-width: 300px) 100vw, 300px" />
(click on the graph to see it in the original size)
If you hoover over a row in the flamegraph, it will show the full information at the bottom row, in this case I hoovered over ttcpip.
If you click a row, it will zoom in to the row. The next picture is a good way to show that the function layers and the stack make it obvious what is going on, while most of the functions do not have the full annotation:
https://fritshoogland.files.wordpress.com/2019/01/flamegraph-annotation3... 600w, https://fritshoogland.files.wordpress.com/2019/01/flamegraph-annotation3... 150w" sizes="(max-width: 300px) 100vw, 300px" />
(click on the graph to see it in the original size)

Again, thanks to Franck for the inspiration. I hope this will be useful for investigating what oracle is doing!

You don’t need the PLAN_TABLE table

This post is about the following error you may get when looking at an execution plan after setting the current_schema:

Error: cannot fetch last explain plan from PLAN_TABLE

It is related with old versions and relics from even older versions.

In the old times, PLAN_TABLE was a permanent shared regular table created by utlxplan.sql. Since Oracle 8i which introduced Global Temporary Tables, the PLAN_TABLE public synonym refers to SYS.PLAN_TABLE$ which is a GTT, not shared and emptied at the end of your session.

When I want to tune a query, I usually connect with my DBA user and change my session schema to the application one, so that I can explain or run the user query without having to prefix all tables. But when there is a PLAN_TABLE in the current schema, DBMS_XPLAN.DISPLAY may fail:

SQL> alter session set current_schema=SCOTT;
Session altered.
SQL> explain plan for select * from dual;
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT                                                  
--------------------------------------------------------------------
Error: cannot fetch last explain plan from PLAN_TABLE

I can check that in addition to the SYS GTT and PUBLIC synonyms, there’s a PLAN_TABLE in this schema

SQL> select owner,object_name,object_type,created from all_objects where object_name like 'PLAN_TABLE%' and owner in (sys_context('userenv','current_schema'),'PUBLIC','SYS');
OWNER    OBJECT_NAME OBJECT_T CREATED                    
-------- ----------- -------- -----------------
SCOTT PLAN_TABLE TABLE 07-MAR-2014 09:15
PUBLIC PLAN_TABLE SYNONYM 29-JAN-2014 21:47
SYS PLAN_TABLE$ TABLE 29-JAN-2014 21:47

This is annoying and not needed, then I drop it

SQL> drop table PLAN_TABLE;
Table PLAN_TABLE dropped.

Of course, you must be sure that this is not an application table with the same name. Just select to see what is there, and in case of doubt, rename it instead of drop:

SQL> rename PLAN_TABLE to "old plan table, delete me";
Table renamed.

Now EXPLAIN PLAN and DBMS_XPLAN.DISPLAY work as expected:

SQL> select * from table(dbms_xplan.display);
Plan hash value: 272002086

-------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Time |
-------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 2 | 00:00:01 |
| 1 | TABLE ACCESS FULL| DUAL | 1 | 2 | 00:00:01 |
-------------------------------------------------------------

Actually, I think the problem does not appear in recent versions. I checked on 18c and EXPLAIN PLAN inserts into the current schema (it was inserted in the connected user schema in 11g).

Making some more sense of direct path reads during primary key lookups

After having published my first article of 2019 I have received feedback I felt like including. With a nod to @fritshoogland, @ChrisAntognini and @FranckPachot.

In the previous post I showed you output of Tanel Poder’s ashtop.sql as proof that direct path reads can occur even if all you do is look up data by primary key. This script touches v$active_session_history, and I’m not getting tired of mentioning that you need to license the system in scope for Enterprise Edition and the Diagnostics Pack to do so.

What I haven’t shown you in more detail in the previous article is what causes these direct path reads. This is what I’ll try to do next. I have started by repeating my test case but added the gather_plan_statistics hint to the statement, resulting in a different SQL ID. Yesterday I noticed that Safari doesn’t show the scroll bar at the bottom of this code snippet other browsers show, I hope output isn’t garbled. I’m using the universal excuse here “it works on my laptop”.

SQL> @xia a66axyw2g6yjb
Display Execution plan in advanced format for sqlid a66axyw2g6yjb

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  a66axyw2g6yjb, child number 0
-------------------------------------
select /*+ gather_plan_statistics CLOB standalone */ *  from
martin.orders_clob  where order_id = :1

Plan hash value: 3284193906

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name           | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                |      1 |        |       |     3 (100)|          |      0 |00:00:00.01 |       3 |
|   1 |  TABLE ACCESS BY INDEX ROWID| ORDERS_CLOB    |      1 |      1 |   137 |     3   (0)| 00:00:01 |      0 |00:00:00.01 |       3 |
|*  2 |   INDEX UNIQUE SCAN         | PK_ORDERS_CLOB |      1 |      1 |       |     2   (0)| 00:00:01 |      0 |00:00:00.01 |       3 |
----------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1 / ORDERS_CLOB@SEL$1
   2 - SEL$1 / ORDERS_CLOB@SEL$1

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('18.1.0')
      DB_VERSION('18.1.0')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "ORDERS_CLOB"@"SEL$1" ("ORDERS_CLOB"."ORDER_ID"))
      END_OUTLINE_DATA
  */

Peeked Binds (identified by position):
--------------------------------------

   1 - :1 (NUMBER): 519990

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ORDER_ID"=:1)

Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - "ORDER_ID"[NUMBER,22], "ORDERS_CLOB"."ORDER_CLOB"[LOB,4000], "ORDERS_CLOB"."ORDER_DATE"[TIMESTAMP WITH LOCAL TIME
       ZONE,11], "ORDERS_CLOB"."ORDER_MODE"[VARCHAR2,8], "ORDERS_CLOB"."CUSTOMER_ID"[NUMBER,22],
       "ORDERS_CLOB"."ORDER_STATUS"[NUMBER,22], "ORDERS_CLOB"."ORDER_TOTAL"[NUMBER,22], "ORDERS_CLOB"."SALES_REP_ID"[NUMBER,22],
       "ORDERS_CLOB"."PROMOTION_ID"[NUMBER,22], "ORDERS_CLOB"."WAREHOUSE_ID"[NUMBER,22], "ORDERS_CLOB"."DELIVERY_TYPE"[VARCHAR2,15],
       "ORDERS_CLOB"."COST_OF_DELIVERY"[NUMBER,22], "ORDERS_CLOB"."WAIT_TILL_ALL_AVAILABLE"[VARCHAR2,15],
       "ORDERS_CLOB"."DELIVERY_ADDRESS_ID"[NUMBER,22], "ORDERS_CLOB"."CUSTOMER_CLASS"[VARCHAR2,30],
       "ORDERS_CLOB"."CARD_ID"[NUMBER,22], "ORDERS_CLOB"."INVOICE_ADDRESS_ID"[NUMBER,22]
   2 - "ORDERS_CLOB".ROWID[ROWID,10], "ORDER_ID"[NUMBER,22]


57 rows selected.

After a few minutes of executing the statement repeatedly, direct path reads are clearly visible again

SELECT
    COUNT(*),
    event,
    session_state
FROM
    v$active_session_history ash
WHERE
    sql_id = 'a66axyw2g6yjb'
    AND sample_time > SYSDATE - 15 / 1440
GROUP BY
    event,
    session_state
ORDER BY
    1 DESC;

  COUNT(*) EVENT                                    SESSION
---------- ---------------------------------------- -------
      1592                                          ON CPU
        24 direct path read                         WAITING
         6 cursor: pin S                            WAITING
         4 SQL*Net more data to client              WAITING

So far so good. Getting back to the original question: what’s causing these? ASH provides the answer to that question as well.

SELECT
    COUNT(*),
    event,
    session_state,
    sql_plan_operation
    || ' '
    || sql_plan_options AS what,
    CASE
        WHEN wait_class IN(
            'Application',
            'Cluster',
            'Concurrency',
            'User I/O'
        )THEN object_name
        ELSE 'undef'
    END AS obj
FROM
    v$active_session_history ash,
    dba_objects o
WHERE
    ash.current_obj# = o.object_id
    AND sql_id = 'a66axyw2g6yjb'
GROUP BY
    event,
    session_state,
    sql_plan_operation
    || ' '
    || sql_plan_options,
    CASE
        WHEN wait_class IN(
            'Application',
            'Cluster',
            'Concurrency',
            'User I/O'
        )THEN object_name
        ELSE 'undef'
    END
ORDER BY 1 desc;

  COUNT(*) EVENT                                    SESSION WHAT                           OBJ
---------- ---------------------------------------- ------- ------------------------------ ------------------------------
      3006                                          ON CPU  SELECT STATEMENT               undef
       223                                          ON CPU  INDEX UNIQUE SCAN              undef
       126                                          ON CPU  TABLE ACCESS BY INDEX ROWID    undef
        50 direct path read                         WAITING SELECT STATEMENT               SYS_LOB0000081921C00002$$
         8 cursor: pin S                            WAITING SELECT STATEMENT               SYS_LOB0000081921C00002$$
         8 SQL*Net more data to client              WAITING SELECT STATEMENT               undef
         1                                          ON CPU                                 undef

7 rows selected.

I think you might be getting the idea by now … I can link the segment back to DBA_LOBS, and … it’s the LOB column of ORDERS_CLOB.

SELECT
    table_name,
    column_name,
    segment_name,
    cache,
    securefile
FROM
    dba_lobs
WHERE
    segment_name = 'SYS_LOB0000081921C00002$$';

TABLE_NAME      COLUMN_NAME     SEGMENT_NAME                   CACHE      SEC
--------------- --------------- ------------------------------ ---------- ---
ORDERS_CLOB     ORDER_CLOB      SYS_LOB0000081921C00002$$      NO         YES

QED.

Another option is to query session statistics. I looked at one of the sessions using snapper4.sql but the output was too wide to paste it as text. I’ll resort to the traditional way of doing this:

SELECT
name,
value
FROM
v$sesstat st
NATURAL JOIN v$statname sn
WHERE
st.sid = 128
AND st.value <> 0
AND REGEXP_LIKE(name, '(physical|securefile).*read.*')
ORDER BY
sn.name;

NAME VALUE
----------------------------------------- ----------
physical read IO requests 106836
physical read bytes 875200512
physical read total IO requests 106836
physical read total bytes 875200512
physical reads 106836
physical reads direct 106836
physical reads direct (lob) 106836
securefile direct read bytes 875200512
securefile direct read ops 106836
9 rows selected.

I admit this was a rather manual way of extracting this piece of information, you might be able to get the same data with an ASH report (provided the number of I/O samples against that segment is significant enough to show up). In this context I’d like to recommend planx.sql you can find on Carlos Sierra’s and Mauro Pagano’s github repository. It’s small, lightweight, and incredibly useful.

Oracle global vs. partition level statistics CBO usage

Global statistics are complex to gather. Gathering on the whole table can be very long and doesn’t ‘scale’ because the duration will increase with the volume. Incremental gathering can be a solution but has its side effects (such as the size of the synopsis). But having stale global statistics can be dangerous. Do you know when the optimizer bases its estimation on global or on partition level statistics? The partition level statistics are used only:

  • when partition pruning iterates on only one single partition
  • when this partition is known at optimization time during the parse phase

This is clearly explained in Jonathan Lewis ‘Cost-Based Oracle Fundamentals’:

Cost-Based Oracle Fundamentals

I also tested on the current release (18c) to verify this. Here is the test-case.

I create a table partitioned by year, fill 100 rows in one partition and 5000 rows in another. Then I gather the statistics:

SQL> create table DEMO (day date) partition by range(day) (
partition P2018 values less than (date '2019-01-01'),
partition P2019 values less than (date '2020-01-01'),
partition P2020 values less than (date '2021-01-01'),
partition P2021 values less than (date '2022-01-01')
);
Table DEMO created.
SQL> insert into DEMO 
select date '2019-01-01'+rownum from xmltable('1 to 100');
100 rows inserted.
SQL> insert into DEMO 
select date '2018-01-01'-rownum/24 from xmltable('1 to 5000');
5,000 rows inserted.
SQL> exec dbms_stats.gather_table_stats(user,'DEMO');
PL/SQL procedure successfully completed.

My goal is to show when the partition or the global statistics are used.

Here are the statistics:

SQL> select partition_name,object_type,num_rows,global_stats 
,to_date((regexp_replace(
extract(dbms_xmlgen.getxmltype(
'select high_value from dba_tab_partitions
where table_owner='''||owner||'''
and table_name='''||table_name||'''
and partition_name='''||partition_name||''''
),'/ROWSET/ROW/HIGH_VALUE/text()').getstringval()
,'[^;]*apos; *([^;]*) *[^;]apos;.*','\1'))
,'yyyy-mm-dd hh24:mi:ss') high_value
from dba_tab_statistics
where owner=user and table_name='DEMO' order by 1 nulls first;
PARTITION_ OBJECT_TYPE    NUM_ROWS GLO HIGH_VALUE 
---------- ------------ ---------- --- -----------
TABLE 5100 YES
P2018 PARTITION 5000 YES 01-JAN-2019
P2019 PARTITION 100 YES 01-JAN-2020
P2020 PARTITION 0 YES 01-JAN-2021
P2021 PARTITION 0 YES 01-JAN-2022

I’ll query partitions above 2019 where I have 100 rows. But the global statistics count 5100 rows. Let’s see which one is used.

Pstart = Pstop (PARTITION RANGE SINGLE) -> partition

This first query reads the rows from only one partition, and the optimizer knows it at parse time because I use literals:

SQL> select count(*) from DEMO where day between to_date( '2019-01-08','yyyy-mm-dd' ) and to_date( '2019-02-08','yyyy-mm-dd' ) ;
COUNT(*)
----------
32
SQL> select * from dbms_xplan.display_cursor(
format=>'basic +rows +outline +peeked_binds +partition');
PLAN_TABLE_OUTPUT                                                   
--------------------------------------------------------------------
EXPLAINED SQL STATEMENT:
------------------------
select count(*) from DEMO
where day between to_date( '2019-01-08','yyyy-mm-dd' )
and to_date( '2019-02-08','yyyy-mm-dd' )

Plan hash value: 849908795

----------------------------------------------------------------
| Id | Operation | Name | Rows | Pstart| Pstop |
----------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | PARTITION RANGE SINGLE| | 33 | 2 | 2 |
| 3 | TABLE ACCESS FULL | DEMO | 33 | 2 | 2 |
----------------------------------------------------------------
  • Partition-level statistics are used when only one partition is accessed, known at the time of parsing. You see that with Pstart=Pstop = number.

Pstart <> Pstop (PARTITION RANGE ITERATOR/FULL) -> global

The second query still knows the partitions are parse time, but multiple partitions are concerned:

SQL> select count(*) from DEMO where day between to_date( '2019-01-08','yyyy-mm-dd' ) and to_date( '2020-02-08','yyyy-mm-dd' );
COUNT(*)
----------
94
SQL> select * from dbms_xplan.display_cursor(
format=>'basic +rows +outline +peeked_binds +partition');
PLAN_TABLE_OUTPUT                                                   
--------------------------------------------------------------------
EXPLAINED SQL STATEMENT:
------------------------
select count(*) from DEMO
where day between to_date( '2019-01-08','yyyy-mm-dd' )
and to_date( '2020-02-08','yyyy-mm-dd' )

Plan hash value: 1988821877

------------------------------------------------------------------
| Id | Operation | Name | Rows | Pstart| Pstop |
------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | PARTITION RANGE ITERATOR| | 705 | 2 | 3 |
| 3 | TABLE ACCESS FULL | DEMO | 705 | 2 | 3 |
------------------------------------------------------------------

This high estimation comes from the high number known at the table level.

  • Global table level statistics are used when more than one partition is accessed, even when they are known at the time of parsing. You see that with Pstart <> Pstop.

KEY — KEY (PARTITION RANGE ITERATOR/FULL) -> global

For the third query, I use bind variables and set them to access only one partition:

SQL> variable d1 varchar2(10)
SQL> variable d2 varchar2(10)
SQL> exec :d1:='2019-01-08' ; :d2:='2019-02-08'
PL/SQL procedure successfully completed.
SQL> select count(*) from DEMO where day between to_date( :d1,'yyyy-mm-dd' ) and to_date( :d2,'yyyy-mm-dd' );
COUNT(*)
----------
32
SQL> select * from dbms_xplan.display_cursor(
format=>'basic +rows +outline +peeked_binds +partition');
PLAN_TABLE_OUTPUT                                                   
--------------------------------------------------------------------
EXPLAINED SQL STATEMENT:
------------------------
select count(*) from DEMO
where day between to_date( :d1,'yyyy-mm-dd' )
and to_date( :d2,'yyyy-mm-dd' )

Plan hash value: 203823535

-------------------------------------------------------------------
| Id | Operation | Name | Rows | Pstart| Pstop |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | FILTER | | | | |
| 3 | PARTITION RANGE ITERATOR| | 33 | KEY | KEY |
| 4 | TABLE ACCESS FULL | DEMO | 33 | KEY | KEY |
-------------------------------------------------------------------


Peeked Binds (identified by position):
--------------------------------------

1 - :D1 (VARCHAR2(30), CSID=873): '2019-01-08'
2 - :D2 (VARCHAR2(30), CSID=873): '2019-02-08'

The cardinality is estimated correctly: the partition statistics were used.

  • Partition-level statistics are used when only one partition is accessed, known at the time of parsing, even the value is known with bind peeking. You see that with KEY/KEY for Pstart/Pstop and with bind variables listed by +peeked_binds format

Of course, this accurate estimation has a drawback: executing the query again for another range of dates may re-use the same execution plan. You should code a different statement when you know that you cover something different.

Without bind peeking -> global

It is not a recommendation, but to avoid the risk mentioned above, some sessions may prefer to disable bind peeking. When bind variable peeking is disabled, the optimization is done before any value is known, so there is no possibility to know which partition is concerned.

SQL> alter session set "_optim_peek_user_binds"=false;
Session altered.
SQL> select count(*) from DEMO where day between to_date( :d1,'yyyy-mm-dd' ) and to_date( :d2,'yyyy-mm-dd' );
COUNT(*)
----------
32
SQL> select * from dbms_xplan.display_cursor(
format=>'basic +rows +outline +peeked_binds +partition');
PLAN_TABLE_OUTPUT                                                   
--------------------------------------------------------------------
EXPLAINED SQL STATEMENT:
------------------------
select count(*) from DEMO
where day between to_date( :d1,'yyyy-mm-dd' )
and to_date( :d2,'yyyy-mm-dd' )

Plan hash value: 203823535

-------------------------------------------------------------------
| Id | Operation | Name | Rows | Pstart| Pstop |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | FILTER | | | | |
| 3 | PARTITION RANGE ITERATOR| | 13 | KEY | KEY |
| 4 | TABLE ACCESS FULL | DEMO | 13 | KEY | KEY |
-------------------------------------------------------------------

Outline Data
-------------

/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('19.1.0')
DB_VERSION('19.1.0')
OPT_PARAM('_optim_peek_user_binds' 'false')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "DEMO"@"SEL$1")
END_OUTLINE_DATA
*/

Here the optimizer estimates 13/5100≈0.25% of global rows.

In conclusion, there is only one case where the partition level statistics can be used: partition pruning to one single partition, known at parse time by the literal value or the peeked bind. Then, you cannot ignore global statistics.

By the way, why did I use a range between 2019–01–08 and 2019–02–08? Probably to remind you that there’s only one month left for the #KaaS19 Belgium Tech Days …

Order Tickets " Techdays Belgium

Making sense of direct path reads during primary key lookups

I recently made an interesting observation while monitoring database performance on an Oracle Enterprise Edition system. While looking at some ASH data (for which you must be licensed appropriately!) I came across direct path reads attributed to a select statement performing a primary key lookup. At first, this didn’t make much sense to me, but it’s actually intended behaviour and not a bug.

In this post I’m reproducing what I observed. I am using Oracle 18.4.0 for this experiment running on my Linux lab environment. The hardware uses 1s8c16t with 64 GB of memory.

Direct Path Reads are multi-block reads you often find in decision support systems when a query is going over large amounts of data. They are un-buffered, as in they use the reading session’s private memory, not the buffer cache. Not exactly what you would expect with a primary key lookup if the index was used. It should be more like this tkprof’d SQL trace:

SQL ID: b5dxjj3wm4yz8 Plan Hash: 4043159647
select *
from
orders where order_id = 100

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 378 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 382 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 82
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID ORDERS (cr=4 pr=0 pw=0 time=32 us starts=1 cost=3 size=95 card=1)
1 1 1 INDEX UNIQUE SCAN ORDER_PK (cr=3 pr=0 pw=0 time=22 us starts=1 cost=2 size=0 card=1)(object id 81853)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL Net message to client 2 0.00 0.00
SQL Net message from client 2 11.40 11.40

No physical I/O anywhere to be seen.

During my original investigation I noticed that direct path reads were attributed to a table containing a CLOB column. The query was something along the lines of “select * from table where primaryKeyColumn = :bindVariable”. The primaryKeyColumn was defined as a number. This should be easy to recreate.

The test case

Based on the Swingbench “ORDERS” table I created a new table using the following DDL:

CREATE TABLE martin.orders_clob (
    order_id                  NUMBER(12,0)
        NOT NULL ENABLE,
    order_clob                CLOB
        NOT NULL ENABLE,
    order_date                TIMESTAMP(6) WITH LOCAL TIME ZONE
        NOT NULL ENABLE,
    order_mode                VARCHAR2(8 BYTE),
    customer_id               NUMBER(12,0)
        NOT NULL ENABLE,
    order_status              NUMBER(2,0),
    order_total               NUMBER(8,2),
    sales_rep_id              NUMBER(6,0),
    promotion_id              NUMBER(6,0),
    warehouse_id              NUMBER(6,0),
    delivery_type             VARCHAR2(15 BYTE),
    cost_of_delivery          NUMBER(6,0),
    wait_till_all_available   VARCHAR2(15 BYTE),
    delivery_address_id       NUMBER(12,0),
    customer_class            VARCHAR2(30 BYTE),
    card_id                   NUMBER(12,0),
    invoice_address_id        NUMBER(12,0),
    constraint pk_orders_clob primary key ( order_id )
) tablespace bigfile_tbs
lob ( order_clob ) store as securefile (enable storage in row);

Please note that the clob is stored in row.

Next I inserted a large number of rows into the table, based again on soe.orders:

INSERT/*+ enable_parallel_dml append parallel(4) */ INTO martin.orders_clob
    SELECT /*+ parallel(4) */
        order_id,
        case
          when mod(rownum,10) = 0 then rpad('X',5000,'Y')
          else rpad('Y', 50, 'Z') 
        end,
        order_date,
        order_mode,
        customer_id,
        order_status,
        order_total,
        sales_rep_id,
        promotion_id,
        warehouse_id,
        delivery_type,
        cost_of_delivery,
        wait_till_all_available,
        delivery_address_id,
        customer_class,
        card_id,
        invoice_address_id
    FROM
        soe.orders
    WHERE    
        ROWNUM <= 1E6;

The case statement ensures that every 10th row has a lob exceeding the size limit of an inline LOB. Apparently that’s 4000 bytes minus a little bit of overhead. As a result the LOB data should be stored outside the table.

Load!

I am now generating some load against the system, being careful not to overload my lab system. I limited myself to 8 sessions:

SQL> select count(*) from v$session where username = 'MARTIN' and program like 'JDBC%';

  COUNT(*)
----------
         8

After a few minutes I can see these direct path reads show up. This is really easy if you have the right tools – I use Tanel Poder’s scripts a lot. One particularly useful script is ashtop.sql (remember the license thing again!) that you can see here:

SQL> @ashtop sql_id,event,session_state username='MARTIN' "to_date('19.12.2018 15:35:00', 'dd.mm.yyyy hh24:mi:ss')" "to_date('19.12.2018 15:45:00','dd.mm.yyyy hh24:mi:ss')"

    Total
  Seconds     AAS %This   SQL_ID        EVENT                                    SESSION FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ------------- ---------------------------------------- ------- ------------------- ------------------- -----------------
     1380     2.3   74% | 7hth4y8d9h7q8                                          ON CPU  2018-12-19 15:35:02 2018-12-19 15:44:58              1232
      225      .4   12% |                                                        ON CPU  2018-12-19 15:35:04 2018-12-19 15:44:59                 2
      175      .3    9% | 7hth4y8d9h7q8 library cache: mutex X                   WAITING 2018-12-19 15:35:15 2018-12-19 15:44:49               175
       65      .1    3% | 7hth4y8d9h7q8 direct path read                         WAITING 2018-12-19 15:35:25 2018-12-19 15:44:41                65
        8      .0    0% | 7hth4y8d9h7q8 SQL*Net more data to client              WAITING 2018-12-19 15:38:52 2018-12-19 15:44:29                 8
        3      .0    0% | 7hth4y8d9h7q8 cursor: pin S                            WAITING 2018-12-19 15:36:59 2018-12-19 15:42:08                 1
        3      .0    0% |               cursor: pin S                            WAITING 2018-12-19 15:35:57 2018-12-19 15:42:08                 1

7 rows selected.

I’ll also show you the execution plan to confirm I’m not actually performing an unintentional full table scan:

SQL> select * from dbms_xplan.display_cursor('7hth4y8d9h7q8');

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------
SQL_ID  7hth4y8d9h7q8, child number 0
-------------------------------------
select /* CLOB */ * from martin.orders_clob where order_id =
trunc(dbms_random.value(1,1000000))

Plan hash value: 3284193906

----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                |       |       |     3 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| ORDERS_CLOB    |     1 |   227 |     3   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | PK_ORDERS_CLOB |     1 |       |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ORDER_ID"=TRUNC("DBMS_RANDOM"."VALUE"(1,1000000)))


20 rows selected.

I didn’t want to use Java’s random method generator, hence the call to dbms_random.value. So there you have it: direct path reads when performing index lookups.

Thanks and big shout out to Tanel Poder for his scripts, they are awesome.