Once again, there was a lesson to be learned about the Oracle RDBMS. The occaison was a direct upgrade from Enterprise Edition 10gR2 to EE 11gR2, the application was kept untouched for good reason.
Problem
After running the new version for two hours, everything became incredibly slow, and the CPU load on the DB server was hitting 100%. Research in the Oracle Wait Interface quickly showed me the wait event: “Cursor: mutex S”. The mutex S is a serialization mutex for the cursor cache. It is involved, as soon as two sessions try to (hard/soft) parse the same statement in sense of SQL_IDs.
A quick look into the cursor cache with v$sql immediately showed an UPDATE statement that has more than 1000 child cursors for the same SQL_ID, it was very likely to have found the culprit, because creating new child cursors means expensive hard parsing, and searching the list of existing children means CPU load as well.
During the next hours, it turned out that on 11gR2 for this machine and constellation off peak hours (thus with low DB load), the critical mass was around 1500 cursors. Beyond this point, the server became slow as described above: The mutex S ate up all CPU power available. In peak time, with lots of DB activity and high basic load, the critical number of child cursors for this UPDATE was around 300, so about 1/5 of “peacetime”. With a growth of 200 new child cursors per minute, expect no fun!
So what can we do about it?
Workaround
Since the number of child cursors and the appearance of the “Cursor: mutex S” wait event was closely related, a stable and well-working workaround was to flush out this particular cursor on a regular basis. Luckyly 11gR2 allows this. In earlier days, with 10g in basic functionality, we would have been toasted at this point – because flushing the whole shared pool once a minute (yes, with a growth of 200/min, and the abyss at 300…) killed us by excessive parse times of everything!
So my workaround was a dbms_scheduler job, running every 1 minute, executing dbms_shared_pool.purge:
DECLARE
SQ_ADD VARCHAR2(100) := '';
BEGIN
execute immediate 'select address from v$sqlarea where sql_id = ''someSQLIDfoo''' into SQ_ADD;
dbms_shared_pool.purge (SQ_ADD||',123454321','C');
END;
Fetching the address dynamically has to be done, because of course it changes as soon as the statement fell out of the cursor cache for some reason (manual flush, statistics deleting the cursor, restart of DB). But the SQL_ID is stable within one DB release.
Additional remark: The SQL_ID of a statement will change from 10gR2 to 11gR2, as it did in the case described here.
Looking for a solution
But as you can imagine, nobody was happy about hardly being able to maintain operations with a job running every minute, knowing to be on 66% of real emergency in every minute of the peak time. So there was an urgent need to know where this behaviour comes from. Mutex S, the number of child cursors, parsing – everything pointed on bind variables.
- But the statement DID consist of bind variables: 47 columns updated at once, 47 bind variables in the cursor definition, plus one in the WHERE condition, looks good!
- Okay, then maybe adaptive cursor sharing playing a fool on me: But there’s only one plan for all of the children. Mh.
- So – I should have done it earlier – let’s look at the reason for invalidating all the children in v$sql_shared_cursor: All of the children in question have been invalidated due to “bind mismatch”.
Okay, so lets have a look at 10046 traces, level 12. It was quite unnervig, since the application uses an own connection pool, it was not easily predictable which session out of some 30 will execute my UPDATE next time. But after a while, I managed to collect enough trace files and sorted them out, to see this situation:
Trace 1:
Bind#6
>> oacdty=01 mxl=32(04) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000010 frm=01 csi=873 siz=0 off=168
kxsbbbfp=1118e1cd8 bln=32 avl=00 flg=01
Trace 2:
Bind#6
>> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=168
kxsbbbfp=110977db8 bln=22 avl=02 flg=01
value=99
FYI, the corresponding field to bind #6 in the table is number(). Both traces are taken from the same UPDATE, same SQL_ID. Only, for some reason, two different child cursors have been used.
So do you see it? The statement in trace 1 sets the bind position number 6 to NULL, and trace 2 sets it to numeric value of “99”. Nothing bad with that, but have a look at “oacdty” – it changes from trace 1 to 2. oacdty=01 means VARCHAR2(), and oacdty=02 means NUMBER(). So see and believe, changing the data type of a bind variable invalidates the child cursor (“bind mismatch”)!
Furthermore, we have 30 nullable numeric fileds here. Simple maths tells us, that 2^30 combinations can be the result. Thus the ceiling would be 2^30 possible child cursors – but the server already dies in fire at 1500 … Sometimes I’m simply loving it. 🙂
Hold on, we still are not at the finish line. Who decides, what data type a bind variable has? It’s a JDBC application, and uses the newest jdbc driver shipped with the 11gR2 database. Luckily, the source code of the application is available, so we can see that using the jdbc driver follows the API documentation as it should:
setNumber() for setting field #6 to 99, and setNull for NULLing it.
But simply using setNull by default means setNull.NULL, and in both cases the setter method will not automatically use the data type of the field in the table. Instead, the default is VARCHAR2, and exactly this makes my datatype different to previous executions! So in theory, setting over 30 numeric values to null and non-null in an alternating matter, creates 2^30 child cursors. Nice.
Solution
After knowing all the above, the solution is quite simple now: Use setNull.NUMBER or setNull.INTEGER etc. to set your numeric fields to NULL, avoid setNull or setNull.NULL. But how really simple it is to implement it in software of any kind, I don’t know and can’t discuss. But it’s clearly something all jdbc programmers and DBAs should know.
Open question
To be sure, of course I early checked an old AWR report, containing the days before the update: There have been more than 800 children for this cursor as well, but nobody in the last years complained about being slow or having (excessive) mutex S wait events.
No question, creating that many cursors is the wrong way, but why did it not cause problems in 10gR2? There IS something different in 11gR2!
Follow-up
All of this process was flanked by an open Oracle Service Request. At some point, the MOS “Manager Performance Team Americas” stated in the SR:
Its important to note that cursor obsoletion code was removed in version 11. That means we no longer obsolete a parent cursor when it reaches 1024 child cursors.
Nice to know …
My advice
Double-check the number of child cursors in your database before upgrading to 11gR2 or above. That’s my statement for that:
select a.cursors, a.sql_id,b.sql_text
from
(
select count(*) as cursors, ssc.sql_id
from v$sql_shared_cursor ssc
group by ssc.sql_id
order by cursors desc
) a,
(
select sa.sql_id, sa.sql_text from v$sqlarea sa
) b
where a.sql_id=b.sql_id;
Best regards, and keep your eyes wide open before changing your DB version.
Martin Klier
Related bugs: 9940784, 4708989
Special thanks to Uwe Lahmann, the oracle-l mailing list and Tanel Poder!