Have you ever seen a result like this:
SQL> select sql_id, count(*) from V$sql group by sql_id having count(*) > 1000; SQL_ID COUNT(*) ------------- ---------- 1dbzmt8gpg8x7 30516
A client of mine who had recently upgraded to 22.214.171.124 RAC, using DRCP (database resident connection pooling) for an application using PHP was seeing exactly this type of behaviour for a small number of very simple SQL statements and wanted to find out what was going on because they were also seeing an undesirable level of contention in the library cache when the system load increased.
In this note I just want to highlight a particular detail of their problem – with an example – showing how easily histograms can introduce problems if you don’t keep an eye out for the dangers.
One of their queries really was as simple as this:
select count(*), sum(skew2) from t1 where skew = :b1;
And I’m going to use this query to model the problem. All I have to do is arrange for a data set that results in a hybrid (or height-balanced) histogram being created on the skew column, and then run the query lots of times with different input bind values. In the case of the client there were around 18,000 possible values for the column, and the number of rows per value varied from 1 to about 20,000 – but whatever the number of rows selected the optimum execution plan was always going to be an indexed access.
rem rem Script: acs_child_cursors.sql rem Author: Jonathan Lewis rem Dated: Jan 2018 rem create table t1 ( id, skew, skew2, padding ) as with generator as ( select rownum id from dual connect by level <= 3e3 ) select rownum id, g1.id id1, g2.id id2, rpad('x',100) from generator g1, generator g2 where g2.id <= g1.id -- > comment to avoid WordPress format issue order by g2.id, g1.id ; alter table t1 modify skew not null; alter table t1 modify skew2 not null; create index t1_skew on t1(skew); begin dbms_stats.gather_table_stats( ownname => user, tabname =>'T1', method_opt => 'for all columns size 1 for columns skew size 254' -- method_opt => 'for all columns size 1' ); end; / variable b1 number exec :b1 := 0; set termout off @start_1000 @start_1000 @start_1000 set termout on set linesize 120 set trimspool on column sql_text format a55 select child_number, plan_hash_value, executions, is_bind_sensitive, is_bind_aware, is_shareable, sql_text from v$sql where sql_id = 'b82my582cnvut' ;
The data set contains 3,000 distinct values for skew and the way I’ve generated the rows means that the value N will appear N times – so there’s one row with the value 1 and 3,000 rows with the value 3,000 and so on for a total of 4,501,500 rows. If you want to run the tes the code is likely to take a couple of minutes to complete, requiring roughly 700 MB of disk space.
The mechanism of the script start_1000 is something I published a few years ago, and essentially it executes a script called start_1.sql 1,000 times which, for this test, contains the following two lines:
exec :b1 := :b1 + 1 select count(*), sum(skew2) from t1 where skew = :b1;
The net effect of the 3 calls to start_1000.sql is that my simple SQL statement is called once in turn for each value of skew from 1 to 3,000. The SQL_ID of the statement is ‘b82my582cnvut’ which I’ve used to query v$sql when the run is complete, with the following result:
CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS I I I SQL_TEXT ------------ --------------- ---------- - - - ------------------------------------------------------- 0 1041516234 498 Y N N select count(*), sum(skew2) from t1 where skew = :b1 1 1041516234 25 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 2 1041516234 104 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 3 1041516234 308 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 4 1041516234 429 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 5 1041516234 640 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 6 1041516234 31 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 7 1041516234 305 Y Y N select count(*), sum(skew2) from t1 where skew = :b1 8 1041516234 660 Y Y Y select count(*), sum(skew2) from t1 where skew = :b1 9 rows selected.
I’ve got 9 child cursors, all with the same execution plan, all except the last labelled as not shareable (you may find that you don’t get exactly the same result, on repeated tests I got between 5 and 9 cursors). Given enough time all these cursors except the last (shareable) one would be aged out of the library cache. In the case of the client, who had a shared pool that was probably quite a bit larger than needed, the number of non-shareable cursors could get very large and they were hanging around for ages. Typically most of the cursors would report an execution count less than 30, with many showing just one or two executions and a handful showing execution counts in the region of several hundred (and that hanful were the ones that were still marked as shareable).
After eliminating the critical histogram (using dbms_stats.delete_column_stats()) and eliminating the redundant child cursors (using dbms_pool.purge()) the massive proliferation stopped happening and the performance threat disappeared. The only issue then was to change the table preferences for stats collection on this table to add the clause “for columns size 1 skew” so that the histogram would not be recreated on the next gather.
I suspect that part of the client’s probem – something that exaggerated the count rather than causing it – could be attributed to using DRCP (database resident connection pool) which probably still has some quirky bits of behaviour. It was also true that the client’s connection pool was probably much bigger than it needed to be so if there were any funny little bits of emergent behaviour at scale the client would probably have hit them.
The problem of escalating child cursors is one that Oracle has been working on for quite a long time, and there’s a (hidden) parameter that was introduced late in 11gR2 (though I think that the 11g mechanism first appeared through a fix control) to allow Oracle to mark a parent cursor obsolete if it acquired too many child cursors. There’s a note on MoS that the client had read on this topic: Doc ID: 2298504.1: “Cursor Mutex X Wait Events: After Upgrading To 12.2″ which looked as if it was describing their symptoms so they had set this parameter (“_cursor_obsolete_threshold“) from 8192 (the 12.2 default) down to 1024 (the default for 12.1 and earlier versions). This had been of some help with the library cache problem. When the sql_id at the top of this article reported 30,516 child cursors that would be 29 “obsolete” parent cursors with 1,024 childs cursor and one “live” parent cursor with 820 child cursors.
You can appreciate that if Oracle has to find a parent cursor and pin it while walking a chain of 30,516 child cursors that’s likely to take a lot more time than walking a chain of 30 parent cursors (while holding a library cache mutex, perhaps) to find the one non-obsolete parent, then acquiring the parent mutex to walk a chain of 820 child cursor.
I don’t know the exact details of the mechanisms involved with manipulating the various chains – but there are likely to be times when one process needs exclusive mutexes/latches to change a chain while other processes are holding shared mutexes/latches to search the chain. When you’ve got 30,000 child cursors in total the important questions become: “where’s the trade-off between making the child chains shorter and making the parent search longer ?” (I’d expect – or hope – that the Oracle developers had actually found a way to code the obsolence so that the new parent was first in the search, and the rest were never visited, of course.)
One of the suggestions I made to try to alleviate the problem – which I had assumed was due in part to the degree of concurrent execution of the statement – was to mark the cursor as “hot” This resulted in 36 differet sql_ids for the same statement (the client machine had 72 CPUs). This had some effect but ultimately meant that there were 36 chains of parents that would eventually end up with lots of child cursors – the only difference was the rate at which the total cursor count was growing (a lot slower), balanced against the threat that they might all manage to get to 30,000+ child cursors! Instead, as a quick and dirty workaround, I supplied the client with a script that could be run at quieter moments during the day to call dbms_shared_pool.purge() for the sql_id to flush all its cursors from the library cache.
One final oddity – which isn’t from the client site. When I changed my test above to avoid generating the histogram (using the commented out method_opt “for all columns size 1”) I found that I still got two child cursors; the first ended up marked as bind-aware but insensitive and non-shareable, the second appeared (time and time again) when my bind value got to 499 and was marked bind-sensitive, bind-aware and shareable. I still have no idea why this happened.
When repeating the test I started with a “flush shared_pool” – but I’ve removed this line from the code above in case anyone ran it without considering the possible side effects. You do need to clear previous copies of the key statement from the library cache, though, if you want to avoid confusing the issue on repeated runs of the test.