I recently learned from Jonathan Lewis’s blog that in version 12.2 details of invalid SQL statements are written to the alert log (after every 100 occurrences for a particular SQL statement).

Its worth to  mention that similar functionality can be achieved in earlier versions by setting event 10035 (not to be confused with it’s more (in)famous sibling, event 10053).

I will demonstrate with version 12.1 using the same invalid SQL from Jonathan’s post (I have tested that this works at least as far back as 10.2):

Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> ALTER SESSION SET EVENTS='10035 trace name context forever, level 1';

Session altered.

SQL> select count(*) frm dual;

Error starting at line : 1 in command -
select count(*) frm dual
Error at Command Line : 1 Column : 21
Error report -
SQL Error: ORA-00923: FROM keyword not found where expected
00923. 00000 - "FROM keyword not found where expected"
*Cause:
*Action:

The following information is written in the alert log:

PARSE ERROR: ospid=14737, error=923 for statement:
Sun Oct 08 01:14:43 2017
select count(*) frm dual
Additional information: hd=0x6bffaa18 phd=0x71c88e18 flg=0x28 cisid=8 sid=8 ciuid=8 uid=8
PARSE ERROR: ospid=14737, error=923 for statement:
Sun Oct 08 01:14:43 2017
select count(*) frm dual
Additional information: hd=0x6bffaa18 phd=0x71c88e18 flg=0x28 cisid=8 sid=8 ciuid=8 uid=8
Sun Oct 08 01:14:43 2017
----- PL/SQL Call Stack -----
object line object
handle number name
0x6f9e6a10 1120 package body SYS.DBMS_SQL
0x727c2ba8 15 anonymous block

Due to the extra overhead this would add to the parse of every invalid SQL, I would suggest to only set this event temporarily at session or system level after identifying that this is a problem from the statistic “parse count (failures)”.

Update

I just found out that Tanel covered this back in 2009 as part of an deep-dive article into diagnostic events, that is well worth a read.

Last week, developers reported some unexpected behavior on a test system.  I thought I would take advantage of the long weekend here in Hong Kong to build the simplest possible reproducible testcase.  I find this is useful to not only in allowing others to easily test on their system, but also to distill exactly what is and is not relevant to the problem, an essential first step for understanding what is going on.

The result confirms something I think I heard from Jonathan Lewis, in that when you start to mix certain features that majority of customers are not using, in this case in-memory column store, tables with >255 columns, and NCHAR columns, then you can start to see some ‘interesting’ results.

For my testcase I am running 12.1.0.2 with 170418 DBBP.

Observe the first part of the setup, I simply use PL/SQL block to create a table with 256 columns (note the first is an NCHAR) and populate it with a couple of rows.  The rows both have c1 set to ‘X’, and on one I populate the last field c256 with value 0, on the other it is NULL.  A query from the the table where c1=’X’ returns both rows as expected.

SQL> DECLARE
  2      sqltext   VARCHAR2(32767);
  3  BEGIN
  4      sqltext := 'CREATE TABLE IM256 (C1 NCHAR(1), ';
  5      FOR loopy IN 2..256 LOOP
  6          sqltext := sqltext
  7           || 'c'
  8           || loopy
  9           || ' NUMBER,';
 10      END LOOP;
 11      -- Remove trailing comma and add close braket
 12      sqltext := SUBSTR(sqltext, 1, LENGTH(SQLTEXT)-1) || ')' ;
 13      EXECUTE IMMEDIATE sqltext;
 14  END;
 15  /

PL/SQL procedure successfully completed.

SQL>
SQL> INSERT INTO IM256(C1, C256) VALUES ('X' , 0);

1 row inserted.

SQL> INSERT INTO IM256(C1) VALUES ('X');

1 row inserted.

SQL> COMMIT;

Commit complete.

SQL>
SQL> SELECT * FROM IM256 WHERE C1 = 'X';

X














                                                                                                                                                                   0

X

















2 rows selected.

SQL>

As soon as I move the table into In-Memory Column Store, the query with the predicate starts to return only one row. The query without predicate still returns both rows.

SQL> ALTER TABLE IM256 INMEMORY NO MEMCOMPRESS;

Table IM256 altered.

SQL> SELECT * FROM IM256 WHERE C1 = 'X';

X














                                                                                                                                                                   0


1 row selected.

SQL> SELECT * FROM IM256;

X














                                                                                                                                                                   0

X














                                                                                                                                                                   0


2 rows selected.

SQL>

Stefan Koehler pointed me towards event 12099 which is mentioned in a couple of bug reports in this area, as a way to disable ‘turboscan’ and indeed setting this event causes the expected results to appear.

SQL>  alter session set events '12099 trace name context forever, level 1';

Session altered.

SQL> SELECT * FROM IM256 WHERE C1 = 'X';

X














                                                                                                                                                                   0

X

















2 rows selected.

Oracle support have identified this as bug 20508559 which is described in further detail in document 20508559.8 – Wrong Results / ORA-600 [kdmv_check_row] with more than 255 columns with nulls.

Edit: I have just tested the patch and after applying it the issue is resolved.

Earlier in the year while digging into AWR Warehouse internals I noticed that POUG (Pint with/Polish Oracle User Group depending on who you ask) had opened their call for papers so on impulse I submitted an abstract and thought no more about it.

I was surprised to receive a response that I could attend as a reserve speaker, they hoped I wasn’t too disappointed. I don’t think they realized I considered this the perfect outcome, an opportunity to attend a fantastic conference without the pressure of having to present.

A couple of weeks before the conference I received some disturbing news, one of their speakers had dropped out, and would be presenting. I would actually have to work for my conference ticket!

The conference itself was everything I had hoped for and more. It was held in a microbrewery so there was free flow beer for the duration which really contributed to the relaxed social atmosphere. All the organizers and staff were great, in particular Kamil’s enthusiasm was complemented by Luiza’s attention to detail. They were so accommodating and had added so many personalized touches to how I was treated. Likely because of this they had also attracted a top list of A-list speakers.

One thing I hadn’t expected was the support from the other speakers. As a first time presenter I received reassuring words from many, but in particular those from Neil Chandler and Jim Czuprynski really helped calm my nerves.

In summary if you have yet to present at a conference then consider submitting a paper, you never know what might happen. Also if you ever get the opportunity to attend a future POUG conference then don’t hesitate to go.

We had some issues, fortunately on a test instance, after applying a database
patch. With the help of a colleague (thanks Kei) I was able to identify what had
gone wrong and setup a testcase to demonstrate the issue. I think it is worth
sharing as it reveals some of the complexities of the relationships between
the components of the Oracle stack.

My setup consists of two database instances on the same host configured in Oracle Restart. To start the patching process I stop both instances. Note in particular the group owner of oracle binary is asmadmin.

[oracle@hkexdb01 ~]$ srvctl stop database -db PVJA -o abort
[oracle@hkexdb01 ~]$ srvctl stop database -db PVJB -o abort
[oracle@hkexdb01 ~]$ ls -alrt $ORACLE_HOME/bin/oracle
-rwsr-s--x 1 oracle asmadmin 327575894 Jun 13 14:52 /u01/app/oracle/product/12.1.0.2/dbhome_2/bin/oracle

Next I apply database patch (I have omitted some details from the
patch session as they are not relevant). Observe that after patch completes,
oracle binary has been re-linked, and owner is now oinstall.

[oracle@hkexdb01 ~]$ cd ~/25397136
[oracle@hkexdb01 25397136]$ $ORACLE_HOME/OPatch/opatch apply
Oracle Interim Patch Installer version 12.2.0.1.9
Copyright (c) 2017, Oracle Corporation.  All rights reserved.


Oracle Home       : /u01/app/oracle/product/12.1.0.2/dbhome_2
Central Inventory : /u01/app/oraInventory
   from           : /u01/app/oracle/product/12.1.0.2/dbhome_2/oraInst.loc
OPatch version    : 12.2.0.1.9
OUI version       : 12.1.0.2.0
Log file location : /u01/app/oracle/product/12.1.0.2/dbhome_2/cfgtoollogs/opatch/opatch2017-06-13_14-58-15PM_1.log

Verifying environment and performing prerequisite checks...
OPatch continues with these patches:   24732088  25397136  

Do you want to proceed? [y|n]
y
User Responded with: Y
All checks passed.

Please shutdown Oracle instances running out of this ORACLE_HOME on the local system.
(Oracle Home = '/u01/app/oracle/product/12.1.0.2/dbhome_2')


Is the local system ready for patching? [y|n]
y
User Responded with: Y
Backing up files...
Applying sub-patch '24732088' to OH '/u01/app/oracle/product/12.1.0.2/dbhome_2'

--DETAILS OMITTED

Patching component oracle.rdbms.install.plugins, 12.1.0.2.0...
Composite patch 25397136 successfully applied.
Log file location: /u01/app/oracle/product/12.1.0.2/dbhome_2/cfgtoollogs/opatch/opatch2017-06-13_14-58-15PM_1.log

OPatch succeeded.
[oracle@hkexdb01 25397136]$ ls -alrt $ORACLE_HOME/bin/oracle
-rwsr-s--x 1 oracle oinstall 327813870 Jun 13 14:59 /u01/app/oracle/product/12.1.0.2/dbhome_2/bin/oracle

After patching is complete, I now restart PVJA outside of
clusterware (note the group owner of oracle binary is still oinstall).

[oracle@hkexdb01 25397136]$ export ORACLE_SID=PVJA
[oracle@hkexdb01 25397136]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Tue Jun 13 15:00:54 2017

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

Connected to an idle instance.

SYS@PVJA> startup
ORACLE instance started.

Total System Global Area 2147483648 bytes
Fixed Size                  2926472 bytes
Variable Size            1564297336 bytes
Database Buffers          570425344 bytes
Redo Buffers                9834496 bytes
Database mounted.
Database opened.
SYS@PVJA> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options
[oracle@hkexdb01 25397136]$ ls -alrt $ORACLE_HOME/bin/oracle
-rwsr-s--x 1 oracle oinstall 327813870 Jun 13 14:59 /u01/app/oracle/product/12.1.0.2/dbhome_2/bin/oracle

I then restart PVJB instance through clusterware. Note that clusterware
updates the group owner of the oracle binary.

srvctl start database -db PVJB 
ls -alrt $ORACLE_HOME/bin/oracle

[oracle@hkexdb01 25397136]$ srvctl start database -db PVJB 
[oracle@hkexdb01 25397136]$ ls -alrt $ORACLE_HOME/bin/oracle
-rwsr-s--x 1 oracle asmadmin 327813870 Jun 13 14:59 /u01/app/oracle/product/12.1.0.2/dbhome_2/bin/oracle
[oracle@hkexdb01 25397136]$ 

This change in group ownership ‘breaks’ the PVJA instance. There are lots of errors in the alert log.

Errors in file /u01/app/oracle/diag/rdbms/pvja/PVJA/trace/PVJA_j000_64968.trc:
ORA-27140: attach to post/wait facility failed
ORA-27300: OS system dependent operation:invalid_egid failed with status: 1
ORA-27301: OS failure message: Operation not permitted
ORA-27302: failure occurred at: skgpwinit6
ORA-27303: additional information: startup egid = 1001 (oinstall), current egid = 1006 (asmadmin)

Note the clusterware log seems to indicate the point at which this action took
place.

2017-06-13 14:55:47.233925 :CLSDYNAM:4045649664: [ora.pvjb.db]{1:31716:24755} [start] Utils:execCmd action = 1 flags = 6 ohome = /u01/app/12.1.0.2/grid cmdname = setasmgidwrap

This behaiour seems to match Bug 9784037 : SETASMGID CAUSING ORA-27303, which
was closed as “Not a Bug”. The provided workaround is “always remember to execute setasmgidwrap after doing relink all / patch apply in RDBMS Oracle Home”.
However I think just making sure that all instances are restarted through
clusterware is probably a better way to handle this.

Update, seems Frits Hoogland has run into this issue too, I now feel a bit better about my ‘mistake’.

We have noticed a change in the behavior of READ ANY TABLE auditing in 12.2.

The following initial setup is performed as SYS:

SQL> AUDIT
  2      SELECT ANY TABLE;

Audit succeeded.

SQL>
SQL> AUDIT
  2      READ ANY TABLE;

Audit succeeded.

SQL>
SQL> CREATE USER tst_table_owner IDENTIFIED BY tst_table_owner
  2      ACCOUNT LOCK;

User TST_TABLE_OWNER created.

SQL>
SQL> CREATE USER tst_view_owner IDENTIFIED BY tst_view_owner
  2      ACCOUNT LOCK;

User TST_VIEW_OWNER created.

SQL>
SQL> GRANT
  2      READ ANY TABLE
  3  TO tst_view_owner WITH ADMIN OPTION;

Grant succeeded.

SQL>
SQL> GRANT
  2      SELECT ANY TABLE
  3  TO tst_view_owner WITH ADMIN OPTION;

Grant succeeded.

SQL>
SQL> CREATE USER tst_login IDENTIFIED BY tst_login;

User TST_LOGIN created.

SQL>
SQL> GRANT
  2      CREATE SESSION
  3  TO tst_login;

Grant succeeded.

SQL>
SQL> CREATE TABLE tst_table_owner.tst_table
  2      AS
  3          SELECT
  4              *
  5          FROM
  6              dual
  7          WHERE
  8              1 = 0;

Table TST_TABLE_OWNER.TST_TABLE created.

SQL>
SQL> CREATE VIEW tst_view_owner.tst_view AS
  2      SELECT
  3          *
  4      FROM
  5          tst_table_owner.tst_table;

View TST_VIEW_OWNER.TST_VIEW created.

SQL>
SQL> GRANT SELECT ON tst_view_owner.tst_view TO tst_login;

Grant succeeded.

SQL>
SQL> GRANT SELECT ON dba_capture TO tst_login;

Grant succeeded.

The following select statements are then run as newly created tst_login user:

SELECT
    COUNT(*)
FROM
    tst_view_owner.tst_view;

SELECT
    COUNT(*)
FROM
    dba_capture;

Querying the audit trail in 12.1 shows no entries, however in 12.2:

SQL> SELECT
  2      db_user,
  3      object_schema,
  4      object_name,
  5      sql_text,
  6      priv_used
  7  FROM
  8      dba_common_audit_trail
  9  WHERE
 10          extended_timestamp > SYSDATE - 2 / 24 / 60
 11      AND
 12          statement_type = 'SELECT';

DB_USER    OBJECT_SCHEMA    OBJECT_NAME               SQL_TEXT  PRIV_USED

TST_LOGIN  TST_TABLE_OWNER  TST_TABLE                           READ ANY TABLE
TST_LOGIN  TST_VIEW_OWNER   TST_VIEW
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              STREAMS$_APPLY_PROCESS
TST_LOGIN  SYS              STREAMS$_APPLY_MILESTONE
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              STREAMS$_APPLY_PROCESS
TST_LOGIN  SYS              STREAMS$_APPLY_MILESTONE
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              XSTREAM$_SERVER
TST_LOGIN  SYS              PROPS$
TST_LOGIN  SYS              DUAL
TST_LOGIN  SYS              PROPS$
TST_LOGIN  SYS              DUAL
TST_LOGIN  SYS              STREAMS$_CAPTURE_PROCESS
TST_LOGIN  SYS              _DBA_CAPTURE
TST_LOGIN  SYSTEM           LOGMNR_SESSION$                     READ ANY TABLE
TST_LOGIN  SYS              DBA_LOGMNR_SESSION
TST_LOGIN  SYS              USER$
TST_LOGIN  SYS              _SXGG_DBA_CAPTURE
TST_LOGIN  SYS              PROPS$
TST_LOGIN  SYS              DUAL
TST_LOGIN  SYS              PROPS$
TST_LOGIN  SYS              DUAL
TST_LOGIN  SYS              STREAMS$_CAPTURE_PROCESS
TST_LOGIN  SYS              _DBA_CAPTURE
TST_LOGIN  SYSTEM           LOGMNR_SESSION$                     READ ANY TABLE
TST_LOGIN  SYS              DBA_LOGMNR_SESSION
TST_LOGIN  SYS              USER$
TST_LOGIN  SYS              _SXGG_DBA_CAPTURE
TST_LOGIN  SYS              DBA_CAPTURE

34 rows selected.

It appears that READ ANY TABLE is audited when querying a view, if the privilege is required by  the view owner to access the base table.

Oracle support have now confirmed that this is not the expected behavior, and have created Bug 26035911 : AUDIT RECORDS GENERATED EVEN WHEN THE SYSTEM PRIVILEGE IS NOT EXERCISED IN 12.2

I have been investigating a PL/SQL process which was failing because a non-optimal plan was being used due to a combination of Bind Variable Peeking and data skew.
I put together a reproducible test case executing the problem SQL from SQLPlus, and found that addition of a /*+bind_aware*/ hint to inform CBO that this query was bind sensitive seemed to resolve the issue.

However retesting via a PL/SQL showed that the plan being used was still that of the first bind variables encountered.

I have simplified the testcase to more easily reproduce the behavior I was seeing (database version 12.1.0.2):

create table skew_table nologging as
   select rownum id,  
        case mod(rownum,  10000) when 0 then 0 else 1 end c10000,
        rpad('X', 255, 'X') padding
        from dual
        connect by level <= 1e6; create index skew_index on skew_table(c10000); exec dbms_stats.gather_table_stats(NULL, 'SKEW_TABLE', METHOD_OPT=>'FOR ALL COLUMNS SIZE SKEWONLY');

create or replace procedure get_skew(p in number)
is 
   dummy number;
begin
   select /*+ bind_aware sktest */ count(*) INTO dummy FROM skew_table where c10000 = p;
end;
/

declare
   dummy number;
begin
   get_skew(0);
   get_skew(1);
end;   
/

Checking v$sql we can see only one plan was generated:

select child_number, executions, parse_calls, is_bind_sensitive, is_bind_aware  from v$sql where sql_id = '1rg2w46daksr4';  

CHILD_NUMBER EXECUTIONS PARSE_CALLS I I                                                                                                                             
------------ ---------- ----------- - -                                                                                                                             
           0          2           1 Y Y    

I guessed that PL/SQL cursor caching was resulting in even the soft parse being skipped, so disabled this optimization in the calling code:

declare
   dummy number;
begin
   execute immediate 'ALTER SESSION SET session_cached_cursors = 0';
   get_skew(0);
   get_skew(1);
   execute immediate 'ALTER SESSION RESET session_cached_cursors';
end;   
/

You can see now that the cursor is re-parsed, and that appropriate plans based on bind variables is now taking place correctly:

SQL> select child_number, executions, parse_calls, is_bind_sensitive, is_bind_aware  from v$sql where sql_id = '1rg2w46daksr4';                                     
                                                                                                                                                                    
CHILD_NUMBER EXECUTIONS PARSE_CALLS I I                                                                                                                             
------------ ---------- ----------- - -                                                                                                                             
           0          3           3 Y Y                                                                                                                             
           1          1           0 Y Y                                                                                                                             

Update: while this was interesting to investigate, for the live issue I have simply locked in a plan that is acceptable (if not optimal) for all values.