After implementing a recent change, and I pulled of a quick AWR report to compare performance.  At first glance I was impressed by significant improvement in “log file parallel write” event, which had halved from 2 millisecond to 1 millisecond, but something about the numbers didn’t quite look right.

Before:

After:

Let’s calculate the average wait times ourselves:
Before:  2,346s/1,482,747=0.00158219844s=1.58 ms.
After:  2,658s/1,785,172=0.00148893215s=1.49 ms.

So AWR rounds to the nearest millisecond, and this has turned an actual 6% (=(1.58-1.49)/1.58*100)  improvement into a 100% improvement.

Note that in Oracle 12.2 AWR handles this much better by reporting wait events in microseconds, one more reason to upgrade!

Update (2018-07-28) Lukas Eder highlighted via twitter that my comparison was invalid dues to some PL/SQL optimizations. I have updated the testcase, there is still significant improvement, just not as much as my previous test

Recently I’ve been noticing a lot of frequently called PL/SQL code that has structure similar to the following:

SELECT TO_CHAR(l_date, 'YYYY-MM-DD') INTO l_string FROM DUAL;

I really don’t know how people got into the habit of doing things this way, isn’t the following much simpler?

l_string := TO_CHAR(l_date, 'YYYY-MM-DD');

Does it really matter? Isn’t it just a coding preference? Let’s benchmark to see the difference:

SQL> declare
  2      l_string VARCHAR2(10);
  3      l_len NUMBER := 0;
  4      l_date DATE := SYSDATE;
  5  begin
  6
  7      for loopy in 1..1000000
  8      loop
  9          SELECT TO_CHAR(SYSDATE, 'YYYY-MM-DD') into l_string FROM DUAL;
 10          l_len := l_len + LENGTH(l_string);
 11      end loop;
 12      dbms_output.put_line(l_len);
 13  end;
 14  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:17.171
SQL>

We executed the statement one million times in just over 17 seconds. Not too shabby. However let’s try the other way:

SQL> declare
  2      l_string VARCHAR2(10);
  3      l_len NUMBER := 0;
  4  begin
  5      for loopy in 1..1000000
  6      loop
  7          l_string := TO_CHAR(SYSDATE, 'YYYY-MM-DD');
  8          l_len := l_len + LENGTH(l_string);
  9      end loop;
 10      dbms_output.put_line(l_len);
 11  end;
 12  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:02.082

Same amount of work, eight times faster. Why? Probably something to do with context switches between PL/SQL and SQL Engines, but don’t stress too much about that, just look at the figures.

Oracle Database CPU cycles are expensive, don’t waste them doing things inefficiently. Please stop abusing the DUAL table.

We’ve just upgraded the database containing our recovery catalog to 12.2. Although rman operations seemed to be completing OK, we noticed the following slightly worrying error message in the alert log:

PDB(3):WARNING: too many parse errors, count=44106 SQL hash=0x2473a808
PDB(3):PARSE ERROR: ospid=398064, error=6550 for statement:
2018-07-22T17:06:22.313262+08:00
PDB(3):BEGIN :owner := dbms_rai_owner; END;
PDB(3):Additional information: hd=0x26ee29a560 phd=0x26ee122418 flg=0x101476 cisid=343 sid=343 ciuid=343 uid=343
2018-07-22T17:06:22.313360+08:00
PDB(3):----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x26afed3ed8        36  package body RCAT.DBMS_RCVVPC.IS_RA
0x26afed3ed8         8  package body RCAT.DBMS_RCVVPC.__pkg_init
0x240a892a20         1  anonymous block
0x23cb60d9d0         4  anonymous block

I checked the source of the package DBMS_RCVPC in the recovery catalog (it is unwrapped PL/SQL):

FUNCTION is_ra
  RETURN BOOLEAN
  IS
    l_owner all_users.username%TYPE;
  BEGIN
    EXECUTE IMMEDIATE 'BEGIN :owner := dbms_rai_owner; END;'
      USING OUT l_owner;
    RETURN (l_owner IS NOT NULL);
  EXCEPTION
    WHEN OTHERS
    THEN RETURN FALSE;
  END is_ra;

I cannot find any object named dbms_rai_owner in the database.
It seems the package is designed to fail with a parse error and that will be caught by the “WHEN OTHERS” handler and return false, and that is what had been happening when this database was at version  12.1.
What has changed is that Oracle now writes details about such parse errors (see Oracle support document 2320935.1 for more details).

Ideally the Oracle developers need to re-write the package logic so it doesn’t rely on throwing parsing exceptions, but until then, I think this message in the alert log can be safely ignored.

Update (2018-07-27): Bug 28223871 – RMAN12C.DBMS_RCVVPC.IS_RA WARNING: TOO MANY PARSE ERRORS, COUNT=4519

Symptom can be fixed by disabling VPD on recovery catalog using dbmsrmanvpc.sql -novpd. Obviously weigh up the pros and cons of this before proceeding.

Update (2018-03-16) Seems WordPress or SQLPlus messed up my testcase, I have updated post to include unedited testcase as well as output.

Update (2018-03-22) Oracle Support have created a new bug for this issue, Bug 27730925 – WRONG CARDINALITY ESTIMATION FROM HYBRID HISTOGRAM ON NCHAR COLUMN

Update (2018-07-24) Tested the patch for bug 27730925 resolves issue. Note the following is required for fix to take effect: alter session set “_fix_control”=’27730925:1′;

Paraphrasing Jonathan Lewis it’s very easy to start ‘breaking’ Oracle as soon as you start combining a few features that most people are not running. The following demonstrates that if you are using NCHAR datatypes (in our case this is forced on us because due to our JDEdwards application) and if you have a hybrid histogram then cardinality estimates vary greatly depending on whether or not you pad your predicates.

Of course with NCHAR datatypes, the results and hence cardinality should be unchanged whether or not predicates are padded.  The issue does not reproduce the symptoms with CHAR datatypes.

SQL>  CREATE TABLE HH_NC_TAB (COL NCHAR(10));

Table created.

SQL> insert /*+APPEND*/ into HH_NC_TAB
  2      SELECT 'AAA'||mod(rownum, 10) FROM DUAL CONNECT BY LEVEL < 100000
  3      union all
  4      SELECT 'AAA'||rownum FROM DUAL CONNECT BY LEVEL  < 100000
  5  ;

199998 rows created.

SQL> COMMIT;

Commit complete.

SQL> EXEC DBMS_STATS.GATHER_TABLE_STATS(NULL, 'HH_NC_TAB', METHOD_OPT=>'FOR COLUMNS COL SIZE 254');

PL/SQL procedure successfully completed.

SQL> EXPLAIN PLAN FOR SELECT * FROM HH_NC_TAB WHERE COL = 'AAA1';

Explained.

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 2981390417

-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           |     1 |    21 |   206   (2)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| HH_NC_TAB |     1 |    21 |   206   (2)| 00:00:01 |
-------------------------------------------------------------------------------

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

   1 - filter("COL"=U'AAA1')

13 rows selected.

SQL> EXPLAIN PLAN FOR SELECT * FROM HH_NC_TAB WHERE COL = RPAD('AAA1', 10);

Explained.

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 2981390417

-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           | 10236 |   209K|   204   (1)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| HH_NC_TAB | 10236 |   209K|   204   (1)| 00:00:01 |
-------------------------------------------------------------------------------

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

   1 - filter("COL"=U'AAA1      ')

13 rows selected.

SQL>

Issue reproduces on 12.1, 12.2 and I’ve uploaded to LiveSQL so you can verify for yourself on 18.1

I’ll try to write this up further when I make progress, but just wanted somewhere to share testcase. I’m guessing it’s a multi-tenant bug, but if that’s the case I’m a little surprised why no-one else has hit it.

SQL> CREATE TABLE DUMMY AS SELECT * FROM DBA_OBJECTS WHERE 1=0;

Table created.

SQL> SELECT resource_consumer_group
  2  FROM v$session
  3  WHERE sid IN (SELECT sid FROM v$mystat);

RESOURCE_CONSUMER_GROUP
--------------------------------
OTHER_GROUPS

SQL> BEGIN
  2    DBMS_SCHEDULER.create_job (
  3      job_name        => 'RC_JOBA',
  4      job_type        => 'PLSQL_BLOCK',
  5      job_action      => 'BEGIN INSERT INTO DUMMY SELECT * FROM DBA_OBJECTS; DELETE FROM DUMMY; COMMIT; END;',
  6      enabled         => TRUE);
  7  END;
  8  /

PL/SQL procedure successfully completed.

SQL> SELECT DISTINCT consumer_group
  2  FROM
  3      v$active_session_history ash,
  4      dba_rsrc_consumer_groups cg
  5  WHERE
  6      action = 'RC_JOBA'
  7      AND   ash.consumer_group_id = cg.consumer_group_id;

CONSUMER_GROUP
--------------------------------------------------------------------------------
SYS_GROUP

SQL>

Edit: I guess if you are testing you may need to update the task the job does to ensure it writes something into v$active_session_history, if you’ve got suggestion for better way to do that let me know, I can’t think of one right now.

Update 2018-03-02: Worryingly this doesn’t seem to be simply a reporting error. I updated the current database resource plan such that any SQL estimated to take over 1 second to complete would be cancelled.

Running a bad SQL directly as user caused query to be cancelled as expected, running via dbms_scheduler attempted to execute the bad SQL.

SQL> CREATE OR REPLACE PROCEDURE KILL_ME_PROC AS
  2  BEGIN
  3     FOR LOOPY IN (SELECT NULL FROM ALL_OBJECTS A1, ALL_OBJECTS A2, ALL_OBJECTS A3, ALL_OBJECTS A3)
  4     LOOP
  5        NULL;
  6     END LOOP;
  7  END;
  8  /

Procedure created.

SQL>
SQL> EXEC KILL_ME_PROC;
BEGIN KILL_ME_PROC; END;

*
ERROR at line 1:
ORA-00040: active time limit exceeded - call aborted
ORA-06512: at "C##PATRICKJOLLIFFE.KILL_ME_PROC", line 3
ORA-06512: at line 1


SQL> SELECT resource_consumer_group
  2  FROM v$session
  3  WHERE sid IN (SELECT sid FROM v$mystat);

RESOURCE_CONSUMER_GROUP
--------------------------------
OTHER_GROUPS

SQL> BEGIN
  2      DBMS_SCHEDULER.create_job (
  3        job_name        => 'KILL_ME_JOB2',
  4        job_type        => 'STORED_PROCEDURE',
  5        job_action      => 'KILL_ME_PROC',
  6        enabled         => TRUE);
  7  END;
  8  /

PL/SQL procedure successfully completed.

SQL> SELECT ERRORS FROM DBA_SCHEDULER_JOB_RUN_DETAILS WHERE JOB_NAME = 'KILL_ME_JOB2' AND LOG_DATE > SYSDATE-1/24;

ERRORS
--------------------------------------------------------------------------------
ORA-01652: unable to extend temp segment by 128 in tablespace TEMP
ORA-06512: at "C##PATRICKJOLLIFFE.KILL_ME_PROC", line 3


SQL>

Another DBA was investigating a performance difference of a query between two different systems and asked me to take a look. The execution plan, a full table scan, was the same in both cases.  We ran Snapper on the problem system and observed that most of the time was spent on event ‘db file sequential read’.

-- Session Snapper v4.24 - by Tanel Poder ( http://blog.tanelpoder.com/snapper ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

---------------------------------------------------------------------------------------------------------------
  ActSes   %Thread | INST | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
---------------------------------------------------------------------------------------------------------------
     .98     (98%) |    1 | 2kcksks9ht14t   | 0         | db file sequential read             | User I/O
     .03      (3%) |    1 | 2kcksks9ht14t   | 0         | ON CPU                              | ON CPU

--  End of ASH snap 1, end=2017-11-24 16:12:18, seconds=5, samples_taken=40, AAS=1

‘db file sequential read’ is a single block access, not usually associated with a full table scan, however from previous experience I guessed that we had chained rows (one row split among multiple blocks), so we reran snapper and checked the value of statistic ‘table fetch continued row’.

-- Session Snapper v4.24 - by Tanel Poder ( http://blog.tanelpoder.com/snapper ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
30, GLOGOWNER , STAT, session logical reads                                     ,          8477,      1.56k,         ,             ,          ,           ,      8.48k total buffer visits
30, GLOGOWNER , STAT, user I/O wait time                                        ,           531,      98.03,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, non-idle wait time                                        ,           531,      98.03,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, non-idle wait count                                       ,          8449,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, physical read total IO requests                           ,          8449,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, physical read total bytes                                 ,      69214208,     12.78M,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, cell physical IO interconnect bytes                       ,      69214208,     12.78M,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, consistent gets                                           ,          8477,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, consistent gets direct                                    ,          8477,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, physical reads                                            ,          8449,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, physical reads direct                                     ,          8449,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, physical read IO requests                                 ,          8449,      1.56k,         ,             ,          ,           ,      8.19k bytes per request
30, GLOGOWNER , STAT, physical read bytes                                       ,      69214208,     12.78M,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, file io service time                                      ,         16898,      3.12k,         ,             ,          ,           ,        2us bad guess of IO service time per IO request
30, GLOGOWNER , STAT, file io wait time                                         ,       5285794,    975.84k,         ,             ,          ,           ,   625.61us bad guess of IO wait time per IO request
30, GLOGOWNER , STAT, no work - consistent read gets                            ,          8478,      1.57k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, table scan rows gotten                                    ,          3798,     701.17,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, table scan blocks gotten                                  ,           882,     162.83,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, table fetch continued row                                 ,          7567,       1.4k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , STAT, buffer is not pinned count                                ,          8477,      1.56k,         ,             ,          ,           ,          ~ per execution
30, GLOGOWNER , TIME, DB CPU                                                    ,        716890,   132.35ms,    13.2%, [@@        ],          ,           ,
30, GLOGOWNER , TIME, sql execute elapsed time                                  ,       6001826,      1.11s,   110.8%, [##########],          ,           ,
30, GLOGOWNER , TIME, DB time                                                   ,       6001826,      1.11s,   110.8%, [##########],          ,           ,      -10.8 % unaccounted time
30, GLOGOWNER , WAIT, db file sequential read                                   ,       5300427,   978.54ms,    97.9%, [WWWWWWWWWW],      8409,      1.55k,   630.33us average wait

--  End of Stats snap 1, end=2017-11-24 16:12:29, seconds=5.4

We were starting to understand the problem we were facing, especially when the DBA observed that the table in question had more than 255 columns (rows in such tables will always be chained), however we still didn’t understand why on the good performing system, also with chained rows, the query ran very fast, mostly on CPU.

I reran the query with SQL trace on the problem system, and attach a small portion below:

WAIT #139940851571352: nam='direct path read' ela= 3354 file number=11 first dba=257026 block cnt=62 obj#=131201 tim=1988902071975
WAIT #139940851571352: nam='db file sequential read' ela= 316 file#=11 block#=13034 blocks=1 obj#=131201 tim=1988902073088
WAIT #139940851571352: nam='db file sequential read' ela= 576 file#=11 block#=13034 blocks=1 obj#=131201 tim=1988902073711
WAIT #139940851571352: nam='db file sequential read' ela= 472 file#=11 block#=118100 blocks=1 obj#=131201 tim=1988902074209
WAIT #139940851571352: nam='db file sequential read' ela= 382 file#=11 block#=13034 blocks=1 obj#=131201 tim=1988902074629
WAIT #139940851571352: nam='db file sequential read' ela= 558 file#=11 block#=118140 blocks=1 obj#=131201 tim=1988902075214
WAIT #139940851571352: nam='db file sequential read' ela= 479 file#=11 block#=13034 blocks=1 obj#=131201 tim=1988902075732
WAIT #139940851571352: nam='db file sequential read' ela= 532 file#=11 block#=141498 blocks=1 obj#=131201 tim=1988902076290
WAIT #139940851571352: nam='db file sequential read' ela= 605 file#=11 block#=13034 blocks=1 obj#=131201 tim=1988902076933
WAIT #139940851571352: nam='db file sequential read' ela= 512 file#=11 block#=12950 blocks=1 obj#=131201 tim=1988902077472
WAIT #139940851571352: nam='direct path read' ela= 4326 file number=11 first dba=259074 block cnt=62 obj#=131201 tim=1988902081885
WAIT #139940851571352: nam='db file sequential read' ela= 754 file#=11 block#=13035 blocks=1 obj#=131201 tim=1988902082905
WAIT #139940851571352: nam='db file sequential read' ela= 544 file#=11 block#=13035 blocks=1 obj#=131201 tim=1988902083483
WAIT #139940851571352: nam='db file sequential read' ela= 617 file#=11 block#=12955 blocks=1 obj#=131201 tim=1988902084132
WAIT #139940851571352: nam='db file sequential read' ela= 546 file#=11 block#=13035 blocks=1 obj#=131201 tim=1988902084723
WAIT #139940851571352: nam='db file sequential read' ela= 976 file#=11 block#=141559 blocks=1 obj#=131201 tim=1988902085730
WAIT #139940851571352: nam='direct path read' ela= 3240 file number=11 first dba=264450 block cnt=62 obj#=131201 tim=1988902089070
WAIT #139940851571352: nam='db file sequential read' ela= 380 file#=11 block#=13036 blocks=1 obj#=131201 tim=1988902090605
WAIT #139940851571352: nam='db file sequential read' ela= 812 file#=11 block#=13036 blocks=1 obj#=131201 tim=1988902091452
WAIT #139940851571352: nam='db file sequential read' ela= 452 file#=11 block#=118118 blocks=1 obj#=131201 tim=1988902091936
WAIT #139940851571352: nam='db file sequential read' ela= 608 file#=11 block#=13036 blocks=1 obj#=131201 tim=1988902092588
WAIT #139940851571352: nam='db file sequential read' ela= 566 file#=11 block#=13008 blocks=1 obj#=131201 tim=1988902093186

While trying to figure out why the same block, say block# 13034, in the trace was being reread from disk during subsequent events, rather than being accessed from the buffer cache, another of my colleagues (thanks Kei) pointed out that the event associated with the table scan was a ‘direct path read’, rather than the usual ‘db file scattered read’.

‘direct path reads’ bypass the buffer cache, reading blocks directly into the session’s PGA. It seems this behavior also affects subsequent ‘db file sequential read’s necessary for accessing chained row pieces, potentially causing some significant performance issues.

As is often the case, Jonathan Lewis has already blogged about this issue however it’s always more rewarding and fun (re)discovering these issues oneself!