12c Parse

Following on from a comment to a recent posting of mine about “bad” SQL ending up in the shared pool and the specific detail that too much bad SQL could cause contention problems while staying virtually invisible, there’s a related note today on the ODC (formerly OTN) forum of a little change in 12.2 that alerts you to the problem.

Try executing the following anonymous block (on a non-production system):

rem
rem     Script:         parse_fail_2.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Oct 2017
rem

declare
        m1 number;
begin
        for i in 1..10000 loop
        begin
                execute immediate 'select count(*) frm dual' into m1;
                dbms_output.put_line(m1);
        exception
                when others then null;
        end;
        end loop;
end;
/

Then check your alert log (if you want to be a little cautious, change the 10,000 in the loop to something like 200). If you’re running 12.2.0.1 you’ll find something like the following:

ORCL(3):WARNING: too many parse errors, count=100 SQL hash=0x19a22496
ORCL(3):PARSE ERROR: ospid=4577, error=923 for statement:
2017-10-06T03:46:15.842431-04:00
ORCL(3):select count(*) frm dual
ORCL(3):Additional information: hd=0x7673c258 phd=0x765151a8 flg=0x28 cisid=135 sid=135 ciuid=135 uid=135
2017-10-06T03:46:15.842577-04:00
ORCL(3):----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x76734f18         5  anonymous block
ORCL(3):WARNING: too many parse errors, count=200 SQL hash=0x19a22496
ORCL(3):PARSE ERROR: ospid=4577, error=923 for statement:
2017-10-06T03:46:15.909523-04:00
ORCL(3):select count(*) frm dual
ORCL(3):Additional information: hd=0x7673c258 phd=0x765151a8 flg=0x28 cisid=135 sid=135 ciuid=135 uid=135
2017-10-06T03:46:15.909955-04:00
ORCL(3):----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x76734f18         5  anonymous block

The warning will be repeated every hundred occurrences. As you can see the guilty (ORA-00923: missing FROM) SQL appears in the report so you know what you’re looking for. In my particular case, with the silly PL/SQL block, the address of the calling anonymous pl/sql block was also reported:

select sql_text from V$sql where child_address = '0000000076734F18';

SQL_TEXT
--------------------------------------------------------------------------------
declare m1 number; begin  for i in 1..10000 loop  begin   execute immediate 'sel
ect count(*) frm dual' into m1;   dbms_output.put_line(m1);  exception	 when ot
hers then null;  end;  end loop; end;

The additional information line reports the v$sql.address (phd) and v$sql.child_address (hd) of the cursor – except you won’t see them because cursors that raise parse errors are hidden from the view. Instead you can query x$kglob (if you have sys privileges), after converting to upper case and left padding the values to 8 bytes with zeroes:

select  *
from    x$kglob
where   kglhdadr = hextoraw('000000007673C258')
and     kglhdpar = hextoraw('00000000765151A8')
;

In the case of the OP on ODC the SQL reported in the alert log was simply: “SELECT 1”. As Billy Verreynne suggested in the thread, this looks like the sort of code that would be sent to the database by some of the connection pooling clients to check that the database is up. Unfortunately (apart from the waste of effort) this particular setup seems to think it’s talking to some database other Oracle!

Footnote:

This is a feature of 12.2 – 11g and 12.1 don’t write such warnings to the alert log.

Lagniappe

A tweet from Mohamed Houri reminds me that parse failures like these, of course, show up in the instance activity stats, in particular:

Name                               Value
----                               -----
opened cursors cumulative         10,006
enqueue requests                  10,002
enqueue releases                  10,002
sql area purged                   10,000
sql area evicted                  10,000
parse count (total)               10,008
parse count (hard)                10,002
parse count (failures)            10,000

The enqueue requests are for the ‘CU’ (cursor) enqueue which, I think, appeared in 10g – they’re acquired (and released) on every hard parse.

Most of the figures that my session reports here are likely to be highly camouflaged by the rest of the activity from a normal system, so the most important number is the “parse count (failures)” – so it’s useful to know that you can subtract that number the other statistics to give you an idea of the impact that would be eliminated if you could located and stop the thing generating the failing statements.

Update

Patrick Joliffe (see pingback below) has published an article pointing out that in earlier versions of Oracle you can set event 10035 to get the same information dumped into the alert log on every parse failure.

Update Feb 2020

In 18.1 the information in the flood control dump (and the 10035 dump referenced by Patrick Joliffe) has been enhanced slightly to report the current user name, application (actually module) and action – the latter being set by calls to dbms_application_info.set_module(), so a typical dump now has two extra lines – compare the following with the above:

ORCLPDB(3):PARSE ERROR: ospid=21736, error=923 for statement:
2020-02-17T18:32:10.112969+00:00
ORCLPDB(3):select count(*) frm dual
ORCLPDB(3):Additional information: hd=0x846b21b8 phd=0x819d8038 flg=0x28 cisid=107 sid=107 ciuid=107 uid=107 sqlid=bfqc8ascu494q
ORCLPDB(3):...Current username=TEST_USER
ORCLPDB(3):...Application: My module Action: Special action
ORCLPDB(3):----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x79680930         7  anonymous block

Note the contents of lines 5 and 6. In particular I forced a parse error after setting event 10035 and then executing a call to

execute dbms_application_info.set_module('My module', 'Special action')

For reference, see MOS Doc ID: 25754281.8