Gathering statistics in 10.2.0.5+ and 11.2.0.2+ encounters strange waits

June 4, 2013

It appears that, somewhere in the 10.2.0.5 and 11.2.0.2 patchsets, Oracle introduced some additional unwanted functionality to the “GATHER_*_STATS” procedures in the DBMS_STATS package.

I have been working on a customer’s 11.2.0.3.0 database supporting a data-mart application where the data loading programs call DBMS_STATS.GATHER_TABLE_STATS as a concluding part of load processing, which means that the procedure gets called a *lot*.

We noticed that some calls to the same procedure were waiting excessively on the event “enq: TX – allocate ITL entry” and being blocked by sessions calling similar DBMS_STATS procedures, themselves in turn waiting excessively on the event “row cache lock” on data dictionary tables like SYS.CON$ (i.e. underlying the DBA_CONSTRAINTS view) and SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$.

OK, not that it isn’t confusing or worrisome to have data dictionary objects be the source of contention within standard packages such as DBMS_STATS, but I can understand the involvement of a table like WRI$_OPTSTAT_SYNOPSIS_HEAD$ since this *is* the DBMS_STATS package and that table involves the “synopses” used for incremental stats gathering in 11g.

But, what do constraints have to do with anything?

So, it appears that changes introduced to the DBMS_STATS package (or its supporting underlying packages) somewhere in the 10.2.0.5.x and 11.2.0.2.x patchsets now apparently cause the package to operate in a slightly anal-retentive way. According to MOS note ID#13784384.8 (entitled “Bug 13784384 – DBMS_STATS produces unnecessary constraints during gather of statistics“), the cause is…

Superfluous NOT NULL constraints could be generated for internal TEMP 
tables by DBMS_STATS when gathering table statistics. This can lead to poor 
performance of statistics gathering in parallel / concurrent sessions.
This can also cause the system to hit ORA-600 [12807] and prevent 
creation of any new constraints if left to occur for a long period of 
time.

So in creating a global temporary table from the data in the table on which we are gathering statistics, someone decided that there was a justification to create constraints (i.e. NOT NULL) on data which did not require validation. Superfluous indeed! The note goes on to comment…

Rediscovery Notes:
 Evidence of excessive constraint creation.

 In extreme cases this issue can also cause ORA-600 [12807] due to 
 exceeding the maximum number of allowed constraints over time.
 In this case one would see the _NEXT_CONSTRAINT value in CON$
 as very high.
  eg: select con# from con$ where name='_NEXT_CONSTRAINT' and owner#=0;
      ^
      If this value is anywhere near 2147483647 then the system is 
	close to the maximum constraint number.

In our situation, we were seeing those symptoms (i.e. poor performance for concurrent DBMS_STATS calls), in addition to the “allocate ITL entry” contention on the data dictionary tables.

The contention in the data dictionary slowly expanded to affect just about all operations, so I had time to construct a fun tree-structured query to illustrate the stacked pattern of database sessions blocking each other…

SQL> select  rpad('.', s.lvl-1, '.')||s.inst_id||'@'||s.sid||'.'||s.serial#||' - '||
  2          decode(o.owner,'',' ',o.owner||'.'||o.object_name||'('||o.object_type||')')||' - '||
  3          event||' ['||seconds_in_wait||'] {'||sql_id||'}' txt
  4  from    (select  r, lvl, inst_id, sid, serial#,
  5                   blocking_instance, blocking_session,
  6                   row_wait_obj#, sql_id, sql_child_number,
  7                   event, seconds_in_wait,
  8                   max(lvl) over (partition by cbr_sid) max_lvl
  9           from    (select      rownum r, level lvl, inst_id, sid, serial#,
 10                                connect_by_root((inst_id*1000000)+sid) cbr_sid,
 11                                blocking_instance, blocking_session,
 12                                row_wait_obj#, sql_id, sql_child_number,
 13                                event, seconds_in_wait
 14                    from        gv$session
 15                    where       status = 'ACTIVE'
 16                    and         state = 'WAITING'
 17                    start with  blocking_session is null
 18                    connect by  blocking_instance = prior inst_id
 19                           and  blocking_session = prior sid)) s,
 20          dba_objects     o
 21  where   s.max_lvl > 1
 22  and     o.object_id (+) = s.row_wait_obj#
 23  order by s.r;

2@219.1449 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {bsnkd25z5bv1u}
.1@1076.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63335] {4bjwv5sp99589}
.2@741.301 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {7pay8fq94tkrh}
..2@3522.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {awuxsc7bwcs3v}
...2@439.5 -   - row cache lock [3] {bmp0ynrs81mf1}
....2@1633.12341 -   - row cache lock [1] {ajbqjx5px1dsz}
.....1@240.877 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63308] {4bjwv5sp99589}
.....1@3383.1 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63301] {4bjwv5sp99589}
.....2@2454.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {3b2st0yh73gdc}
......2@1145.15 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {650n0can8wufy}
.......1@62.1095 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63337] {4bjwv5sp99589}
.......2@2792.13 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {8vu6d1tzrwm4w}
........2@599.1931 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {b7a4r7wq8z6bc}
.........2@3150.407 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {bmss7cw3ts40r}
..........1@1715.431 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63338] {4bjwv5sp99589}
..........2@3188.2189 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {6w5j91fdpgnv6}
...........1@1.6249 - SYS.AUD$(TABLE) - enq: TX - allocate ITL entry [25034] {9xp91bkh5na4k}
...........2@2308.87 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {a95xtgf967t5x}
............2@1968.671 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {bu5pu9r77rj7t}
.............2@1379.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {fhhg93axnx3a3}
..............2@2504.669 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {9w0wb60n8tvuq}
...............2@125.1281 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63330] {4bjwv5sp99589}
...............2@308.717 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {0n56a6hk42553}
................2@474.7 - SYS.AUD$(TABLE) - enq: TX - allocate ITL entry [24280] {8ydgkfhxf3mdm}
.................2@2779.6395 -   - row cache lock [3] {8ydgkfhxf3mdm}
.................2@3600.27 -   - row cache lock [2] {8ydgkfhxf3mdm}
.................2@3680.43037 - SYS.AUD$(TABLE) - row cache lock [1] {8ydgkfhxf3mdm}
................2@607.2029 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {4xvk29rqdkkba}
.................2@1729.2931 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {3d5pyqj9udu51}
..................2@2785.21 -   - row cache lock [2] {70xtajvb8vg80}
...................2@2788.7341 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {gbc0xfpnjmrak}
....................2@1007.271 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {6h42v2v1j2q2f}
.....................2@1606.25 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {c1sh35uq76vxh}
......................1@3606.1375 -   - enq: TX - allocate ITL entry [63258] {59vjj34vugaav}
......................2@2072.1703 -   - enq: TX - allocate ITL entry [63203] {bwt0pmxhv7qk7}
......................2@3250.75 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {d54nq2r6zj4ax}
.......................1@3249.6625 - SYS.SCHEDULER$_JOB(TABLE) - enq: TX - allocate ITL entry [62979] {4bjwv5sp99589}
........................1@3364.3 - SYS.SCHEDULER$_GLOBAL_ATTRIBUTE(TABLE) - enq: JS - queue lock [58125] {}
.......................2@711.1977 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {b1wuayvajfa64}
........................2@197.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {fn3akj947hpty}
.........................2@2544.35 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63342] {4bjwv5sp99589}
.........................2@3392.13 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63339] {4bjwv5sp99589}
.........................2@3462.16147 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {ak6t8bjy44f66}
..........................1@3198.585 -   - enq: TX - allocate ITL entry [63262] {59vjj34vugaav}
..........................2@1257.21 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {dvn1xr77da6ra}
...........................2@3402.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {6x5am3j3u3n1z}
............................2@2421.487 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {8ymnjz5uvrr25}
.............................2@1857.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {ayadjnh49j01z}
..............................2@2697.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {80y25g63db9rm}
...............................2@1360.143 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {8zc8xmm2zxj2r}
................................1@534.1737 -   - enq: TX - allocate ITL entry [63271] {59vjj34vugaav}
................................2@2931.19 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {7yau3vaq99r7a}
.................................1@2480.1111 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63341] {4bjwv5sp99589}
.................................2@2930.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {5udwzbjrwha9v}
..................................2@2077.35 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {g0u3fx9rk023z}
...................................2@850.2303 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {3rb4zwsmgkuaz}
....................................2@1965.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {6qcgpq814jtr0}
.....................................1@3676.1 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63341] {4bjwv5sp99589}
.....................................2@419.1641 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {7y8p7g5z9zwfc}
......................................1@2315.21449 - SYS.I_OBJ1(INDEX) - enq: TX - allocate ITL entry [63341] {59vjj34vugaav}
.......................................2@3014.16071 -   - row cache lock [0] {}
......................................2@1507.11 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {dhxvmvpdhfv1s}
.......................................2@2573.37 -   - row cache lock [0] {0v2nusrufxjfm}
........................................2@2391.1429 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {9kwa78pr71b6w}
.........................................2@3079.16241 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {4dq16jamcyw39}
..........................................2@3032.823 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {2g0f7m56yxfqq}
...........................................2@617.1471 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {7c74qc3mnr3gz}
............................................2@36.1071 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {a2qscspby48xz}
.............................................2@366.1099 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {7j95tn9j7dyy1}
..............................................2@632.2797 -   - enq: TX - allocate ITL entry [63198] {bwt0pmxhv7qk7}
..............................................2@1500.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {cr15w70sdbx4k}
...............................................1@299.1461 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63335] {4bjwv5sp99589}
...............................................1@1959.1327 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63306] {4bjwv5sp99589}
...............................................1@2370.3509 -   - enq: TX - allocate ITL entry [63305] {4bjwv5sp99589}
...............................................2@3602.5729 -   - row cache lock [3] {2vckpdzuzthjh}
................................................2@1841.51 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {3bpm8xm0g5vp8}
.................................................2@717.317 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {11gzrjaag1pjx}
..................................................2@72.25 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {7qfczckxgdurc}
...................................................1@1894.18487 -   - enq: TX - allocate ITL entry [63256] {59vjj34vugaav}
...................................................2@75.1265 -   - enq: TX - allocate ITL entry [63331] {4bjwv5sp99589}
...................................................2@1276.15 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {1zqhynv3axs0m}
....................................................2@5.1415 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {44kxhsxbqg0hw}
.....................................................2@981.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {d0a7z7qgj8z62}
......................................................2@1986.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {4xrg2kf0d570j}
.......................................................2@2601.4649 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {4nc5b2xsb3f82}
........................................................2@3745.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {3p3c6gtg54vsv}
.........................................................2@272.1851 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {34yp7a3fcvkuv}
..........................................................2@2212.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {1s99z5rw25kux}
...........................................................2@249.1715 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {3vd70d6n0hc0h}
............................................................1@178.469 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63324] {4bjwv5sp99589}
............................................................2@3366.2951 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {9w3fjfncud71b}
.............................................................2@1960.3113 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {adn4gk433muxt}
..............................................................2@2574.11 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {1p6k5k3n2z9yx}
...............................................................2@3438.2105 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {gz8s1adarn60q}
................................................................1@3430.53519 -   - enq: TX - allocate ITL entry [63292] {59vjj34vugaav}
................................................................2@1025.23 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {f442682t8r16f}
.................................................................2@3560.17443 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {4570cty0ggvx2}
..................................................................2@3030.27 -   - row cache lock [3] {bujrahka3pb6m}
...................................................................2@1743.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {87673srwpxrh7}
....................................................................2@2456.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {apydhymp3aynf}
.....................................................................2@2906.333 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {22yrd1fvrsdv6}
......................................................................2@1871.15 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {7dysg327qcq05}
.......................................................................2@3623.889 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {gkzhhytjjx1u3}
........................................................................2@3732.337 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {9d3mhv6sqmyd7}
.........................................................................2@70.721 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {dzr08d4wk8jcd}
..........................................................................1@1192.1639 -   - enq: TX - allocate ITL entry [63260] {59vjj34vugaav}
..........................................................................2@1249.123 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63311] {4bjwv5sp99589}
..........................................................................2@2335.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63325] {4bjwv5sp99589}
..........................................................................2@3631.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {cng9azjaxhgb5}
...........................................................................1@3024.1 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63300] {4bjwv5sp99589}
...........................................................................2@614.405 -   - row cache lock [1] {2nf27axmrzvuf}
............................................................................2@748.2961 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {f0wxsdh5pdqzd}
.............................................................................1@1777.953 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63311] {4bjwv5sp99589}
.............................................................................2@864.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {00swnpvas1df7}
..............................................................................2@3048.5 -   - row cache lock [2] {2msq18uq154bc}
...............................................................................2@1721.45 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {6wfk2bf2udbqn}
................................................................................2@1860.21 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {g1u3w0upxyr10}
.................................................................................2@2068.59 -   - enq: TX - allocate ITL entry [63341] {8nhg2pdrzs3ww}
..................................................................................2@957.1423 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63344] {4bjwv5sp99589}
.................................................................................2@3659.32559 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [0] {0tgrjcckf2akt}
..................................................................................1@2190.37713 -   - enq: TX - allocate ITL entry [63258] {59vjj34vugaav}
..................................................................................2@484.433 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {bf2jpw6816sxn}
...................................................................................2@121.1553 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {48fnk2k3yd91c}
....................................................................................2@3257.551 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {1askjs3715rx1}
.....................................................................................2@3699.1787 -   - row cache lock [0] {fh70a2au1tp8j}
......................................................................................2@3283.21 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {g7suptjvx1s33}
.......................................................................................1@3434.16369 -   - enq: TX - allocate ITL entry [63287] {59vjj34vugaav}
.......................................................................................2@2679.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {4xug3acq6k0j1}
........................................................................................2@1869.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [1] {bbwyhcta8a9rv}
.........................................................................................2@1146.7 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [3] {3guv8dr2z6mmk}
..........................................................................................2@479.1161 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {7yk436u8nyrxu}
...........................................................................................2@130.1853 -   - enq: TX - allocate ITL entry [63321] {bwt0pmxhv7qk7}
...........................................................................................2@1623.27 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - row cache lock [2] {9znsq1kq2x9hy}
............................................................................................1@3130.359 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63328] {4bjwv5sp99589}
............................................................................................2@380.475 -   - row cache lock [2] {dz7z5spuv0f4v}
..........................................................................................2@863.1925 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63314] {4bjwv5sp99589}
.........................................................................2@1497.25 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63341] {4bjwv5sp99589}
....................................................................2@3137.59 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63324] {4bjwv5sp99589}
....................................................2@1130.141 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63340] {8nhg2pdrzs3ww}
.....................................................1@832.705 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63313] {4bjwv5sp99589}
.....................................................2@3521.19 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63311] {4bjwv5sp99589}
....................................................2@1325.25639 -   - enq: TX - allocate ITL entry [62268] {4bjwv5sp99589}
...................................................2@2656.2773 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63306] {4bjwv5sp99589}
..............................................2@2192.1119 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63315] {4bjwv5sp99589}
.............................................2@671.1621 -   - enq: TX - allocate ITL entry [63320] {bwt0pmxhv7qk7}
..............................................2@544.15201 -   - enq: TX - allocate ITL entry [63842] {a44jdqsy96zpc}
..............................................2@1138.40947 -   - enq: TX - allocate ITL entry [63719] {a44jdqsy96zpc}
..............................................2@1957.5145 -   - enq: TX - allocate ITL entry [63841] {a44jdqsy96zpc}
..............................................2@3152.879 -   - enq: TX - allocate ITL entry [63841] {a44jdqsy96zpc}
..............................................2@3256.36199 -   - enq: TX - allocate ITL entry [63720] {a44jdqsy96zpc}
..............................................2@3624.2265 -   - enq: TX - allocate ITL entry [63720] {a44jdqsy96zpc}
......................................2@3637.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63344] {4bjwv5sp99589}
.....................................2@2804.21 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63337] {4bjwv5sp99589}
...................................2@2088.5 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63314] {4bjwv5sp99589}
...................................2@2304.1377 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63317] {4bjwv5sp99589}
...........2@2373.5887 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63343] {4bjwv5sp99589}
...2@1389.35 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63345] {4bjwv5sp99589}
.2@3405.9 - SYS.WRI$_OPTSTAT_SYNOPSIS_HEAD$(TABLE) - enq: TX - allocate ITL entry [63343] {4bjwv5sp99589}

158 rows selected

I confess: once I saw this output, I made little effort to understand the details, and simply admired the aesthetics of it. The output from this query grew to almost 100 tree levels, so we would have quite a job on our hands if we were to begin killing sessions.

As it was Friday evening by the time we had all of the bug information and an action plan in hand, we bounced the production RAC instances to clear the problem. One-off patches for bug #13784384 exist for specific versions, including 11.2.0.3.0, 11.2.0.3.5, and 11.2.0.3.6, because the fix is not included until 11.2.0.4, which has not yet been released. Fortunately, this is a software-only patch (i.e. no modifications made to the data dictionary), so it is “RAC rolling-upgradeable”, thus allowing a minimum of down-time.

It all just goes to show, a party can erupt even under the most banal of circumstances.

EvDBT

Gathering statistics in 10.2.0.5+ and 11.2.0.2+ encounters strange waits

Leave a Reply Cancel reply