Oracle mechanics

11.11.2012

ORA-00600: [kglUnKeepHandle] при превышении лимита количества дочерних курсоров

Filed under: hints,Oracle,shared pool — Игорь Усольцев @ 22:19
Tags: , ,

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 со временем адекватно перераспределит память в пользу невинно пострадавшего буферного кэша

About these ads

Добавить комментарий »

Комментариев нет.

RSS-лента комментариев к этой записи. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Тема: Rubric. Создайте бесплатный сайт или блог на WordPress.com.

Отслеживать

Get every new post delivered to your Inbox.

Join 142 other followers

%d такие блоггеры, как: