alert.log:
Mon Oct 22 14:00:44 2012 Errors in file /opt/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_9219.trc (incident=110752): ORA-00600: internal error code, arguments: [kglUnKeepHandle], [0x7D39A5EE0], [], [], [], [], [], [], [], [], [], [] Mon Oct 22 14:01:58 2012 Non critical error ORA-48913 caught while writing to trace file "/opt/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_9219.trc" Error message: ORA-48913: Writing into trace file failed, file size limit [512000000] reached Writing to the above trace file is disabled for now on...
- попутная ошибка ORA-48913 вызвана ограничением размера трейса:
SQL> @param max_dump_file_size NAME VALUE DSC ------------------- -------- ------------------------------------ max_dump_file_size 1000000 Maximum size (in bytes) of dump file
, в отличие от описания выраженного в блоках ОС = 512 байт (Oracle 11.1.0.7 Linux x86_64) – см. [ID 30762.1]
Трейс /opt/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_9219.trc достаточно быстро указывает на причину ошибки ORA-600 [kglUnKeepHandle]:
...
DDE: Problem Key 'ORA 600 [kglUnKeepHandle]' was flood controlled (0x4) (incident: 110752)
ORA-00600: internal error code, arguments: [kglUnKeepHandle], [0x7D39A5EE0], [], [], [], [], [], [], [], [], [], []
LIBRARY HANDLE:0x7d39a5ee0 bid=52158 hid=fd48cbbe lmd=0 pmd=0 sta=VALD
name=
SELECT ... from view_with_precomp_subq WHERE id IN (:1, :2, :3, :4, :5, :6, :7, :8, :
hash=e7a430b898d4a02916b5b863fd48cbbe idn=0
tim=10-16-2012 19:47:38kkkk-dddd-llll=0000-0001-0001
exc=1753322 ivc=437016 ldc=491263 slc=0 lct=504459 pct=1
cbb=1 rpr=1 kdp=10 kep=0 bus=45706 hus=45706 rfc=0 dbg=0
dmtx=0x7d39a5f88(0, 0, 0) mtx=0x7d39a5ff8(0, 4179427737, 89203)
nsp=CRSR(00) typ=CRSR(00) llm=0 flg=RON/KGHP/TIM/PN0/DBN/[10012840]
lwt=0x7d39a5f68[0x7d39a5f68,0x7d39a5f68]
pwt=0x7d39a5f48[0x7d39a5f48,0x7d39a5f48]
ref=0x7d39a5f78[0x7d39a5f78,0x7d39a5f78]
LIBRARY OBJECT: 0x79fc970b0
flg=EXS[0001] pfl=[0000] ssta=VALD
CHILDREN: size=65536 ### дальше можно не читать: предельное кол-во child / cursor - Bug 2458443 : ORA-00600 [17059] ON UPDATE STATEMENT
child# table reference handle
------ -------- --------- --------
0 79fc96f60 79fc96ae0 7d39a5cf0
1 79fc96f60 79fc81390 7d3913e60
...
- проблема, очевидно связана с достижением предельного кол-ва дочерних курсоров (child cursors) объекта LIBRARY CACHE
Текущий version count, для V$SQL.HASH_VALUE=4249406398, что соответствует hid=fd48cbbe из предыдущего трейса:
11.1.0.7.@ SQL> @shared_cu111 1dddscgynjkxy SQL_ID VERSION_COUNT ADDRESS HASH_VALUE PARSING_SCHEMA_NAME REASON SQL_TEXT ------------- ------------- ---------------- ---------- ------------------- ---------------------- -------- 1dddscgynjkxy 52123 00000007DB99FC58 4249406398 SCOTT CURSOR_PARTS_MISMATCH SELECT ... from view_with_precomp_subq WHERE id IN (:1, :2, :3, :4, :5, :6, :7, :8, :
CURSOR_PARTS_MISMATCH в качестве причины high verion count стабильно вызывается при использовании подсказки PRECOMPUTE_SUBQUERY (например, в OLTP приложениях), что отлично продемонстрировано у Tanel Poder. Multipart cursor subexecution and PRECOMPUTE_SUBQUERY hint – и действительно, как выяснилось, разработчики активно использовали эту подсказку и даже создали с ней несколько интенсивно используемых обзоров (view_with_precomp_subq)
Ожидания самого проблемного запроса:
SQL> select decode(session_state, 'WAITING', event, session_state) waits4, 2 count(*) 3 from v$active_session_history 4 where sql_id = '1dddscgynjkxy' 5 group by decode(session_state, 'WAITING', event, session_state) 6 order by count(*) desc 7 / WAITS4 COUNT(*) ----------------------------- ---------- ON CPU 6559 latch: shared pool 30 -- характерно для high version count SQL*Net more data from client 3 db file sequential read 1
Распределение времени при выполнении запроса указывает на активное использование процессора:
SQL> select
2 round(st.executions) as execs,
3 st.sql_id,
4 st.plan_hash_value as plan,
5 round(st.elapsed_time/st.executions) as ela_per_exec,
6 round(st.cpu_time/st.executions) as cpu_per_exec,
7 round(st.user_io_wait_time/st.executions) as iowaits_per_exec
8 from gv$sqlstats st
9 where sql_id in ('1dddscgynjkxy')
10 and st.executions > 0
11 /
EXECS SQL_ID PLAN ELA_PER_EXEC CPU_PER_EXEC IOWAITS_PER_EXEC
----- ------------- ---------- ------------ ------------ ----------------
45182 1dddscgynjkxy 753640476 27545 26508 0
Характерные данные AWR за проблемный период:
Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 12,032M 12,032M Std Block Size: 16K
Shared Pool Size: 18,048M 18,048M Log Buffer: 54,036K -- очевидно перегруженный Shared Pool
...
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
cursor: pin S wait on X 190 16,800 88421 86.5 Concurrenc -- интересное ожидание с огромным средним временем
DB CPU 2,055 10.6
db file sequential read 149,630 680 5 3.5 User I/O
log file sync 15,382 29 2 .2 Commit
SQL*Net more data to client 1,878,217 15 0 .1 Network
...
SQL ordered by Sharable Memory DB/Inst: ORCL/orcl Snaps: 1884-1885
-> Only Statements with Sharable Memory greater than 1048576 are displayed
Sharable Mem (b) Executions % Total SQL Id
---------------- ------------ -------- -------------
207,596,256 N/A 1.10 7mp0r72y6wrau
merge into tt using (select ... from view_with_precomp_subq where ...
...
SQL ordered by Version Count DB/Inst: ORCL/orcl Snaps: 1884-1885
-> Only Statements with Version Count greater than 20 are displayed
Version
Count Executions SQL Id
-------- ------------ -------------
65,278 N/A 1dddscgynjkxy -- запрос, получавший ORA-00600: [kglUnKeepHandle]
SELECT ... from view_with_precomp_subq WHERE id IN (:1, :2, :3, :4, :5, :6, :7, :8, :
...
1,585 N/A 7mp0r72y6wrau -- запросы, ожидавшие cursor: pin S wait on X
merge into tt using (select ... from view_with_precomp_subq where ...
...
357 N/A 707nxz109utbg -- --//--
select * from view_with_precomp_subq where ID = :1
- кроме запроса с рекордным количеством версий sql_id=1dddscgynjkxy (из трейса ORA-600) значительными значениями Version Count и объёмом в library cache отличались курсоры, в основном ожидавшие cursor: pin S wait on X , также использовавшие выполнение курсора по частям через подсказку /*+ PRECOMPUTE_SUBQUERY*/ в обзоре VIEW_WITH_PRECOMP_SUBQ:
SQL> select sql_id, count(*) 2 from dba_hist_active_sess_history 3 where snap_id = 1885 4 and event = 'cursor: pin S wait on X' 5 group by sql_id 6 order by count(*) desc 7 / SQL_ID COUNT(*) ------------- ---------- 7mp0r72y6wrau 1595 707nxz109utbg 76
Разработчики, к слову сказать, использовали PRECOMPUTE_SUBQUERY не от хорошей жизни – с помощью этого хинта в запросе указывался явный список используемых субпартиций с валидными локальными индексами, т.е. таким способом решали проблему индексного доступа при наличии unusable index subpartition в версиях до 11g !
Описанное в заметке исправление запросов / обзоров с явным указанием индекса подсказкой INDEX позволило исключить использование опасной и разумно недокументированной и нерекомендуемой подсказки PRECOMPUTE_SUBQUERY и избавиться от цепочки проблем:
high version count -> ORA-00600: [kglUnKeepHandle] -> shared pool contention & over-sizing
Статистика выполнения бывшего проблемным запроса значительно улучшилась, сократив среднее время выполнения в 50 с лишним раз:
SQL> select
2 round(st.executions) as execs,
3 st.sql_id,
4 st.plan_hash_value as plan,
5 round(st.elapsed_time/st.executions) as ela_per_exec,
6 round(st.cpu_time/st.executions) as cpu_per_exec,
7 round(st.user_io_wait_time/st.executions) as iowaits_per_exec
8 from gv$sqlstats st
9 where sql_id in ('1dddscgynjkxy')
10 and st.executions > 0
11 /
EXECS SQL_ID PLAN ELA_PER_EXEC CPU_PER_EXEC IOWAITS_PER_EXEC
---------- ------------- ---------- ------------ ------------ ----------------
18053 1dddscgynjkxy 1688089918 593 208 9
Статистика использования SGA сразу после изменений мгновенно не улучшилась, однако в Shared Pool появилась огромная неиспользуемая область ~ 16 GB:
11.1.0.7.@ SQL> @sga ASMM_STATUS ----------- ASMM:on SGA Parameters Parameters MB DISPLAY_VALUE DESCRIPTION ---------------------------------------- ---------- -------------------- ------------------------------------------------------------ sga_max_size 30720 30G max total SGA size sga_target 30720 30G Target size of SGA db_cache_size 2048 2G Size of DEFAULT buffer pool for standard block size buffers ... shared_pool_size 0 0 size in bytes of shared pool SGAINFO SGA Info MB RESIZEABLE ---------------------------------------- ---------- ---------- Maximum SGA Size 30583 No Shared Pool Size 16896 Yes -- всё ещё огромный Buffer Cache Size 13184 Yes ... Shared Pool Components - TOP6 Shared Pool Components MB ---------------------------------------- ---------- free memory 16250 -- но, в основном, пустой пул PCursor 95 Cursor Stats 81 db_block_hash_buckets 45 FileOpenBlock 44 sql area 38
, что даёт основания надеяться что магическая сила ASMM со временем адекватно перераспределит память в пользу невинно пострадавшего буферного кэша
