event ORA$AT_OS_OPT_SY_????, ORA-27403, ORA-00600

업무 테이블 DELETE의 지연 발생 (평소 초단위 수행건이 5시간 이상 수행중)

모니터링 솔루션을 통해 확인함.

1. DELETE를 수행중이던 세션이  
enq : TX - index contention 락이 발생하며 대기중.

enq : TX - index contention
타 세션이 DML에 의해 TX - exclusive Lock을 획득한 상태에서
데이터가 INSERT되면서 인덱스 리프노드가 SPLIT되는 중에
내 세션의 DML수행으로 SPLIT중인 해당 리프노드를
변경하고자 하는 경우 이 이벤트가 발생한다.

2. 해당 락을 잡고 있는 세션을 추적하니
INSERT를 수행중이던 세션을 확인함.
이 세션도 gc buffer busy acquire 이벤트와 함께 10시간 넘게 대기중.

3. INSERT를 수행중이던 세션과 함께 대기중이던 세션 발견.
SYS에서 DBMS_SCHEDULER가 수행중임을 확인함.
20시간이 넘도록 gc cr request 이벤트와 함께 대기중이었고
이 세션을 KILL하니 대기중이던 작업이 완료됨.

원인 확인

DBMS_SCHEDULER에서 수행중이던 작업 확인해 보았다.
아래 쿼리가 수행중이었다.

SELECT /*+ opt_param('_optimizer_use_auto_indexes' 'on')
      parallel_index(t, "INDEX_NAME", 23)
      dbms_stats
      cursor_sharing_exact
      use_weak_name_resl
      dynamic_sampling(0)
      no_monitoring
      xmlindex_sel_idx_tbl
      opt_param('optimizer_inmemory_aware' 'false')
      no_substrb_pad
      no_expand
      index_ffs(t, "INDEX_NAME") */
      Count(*) AS nrw,
      Count(DISTINCT Sys_op_lbid(161708, 'L', t.ROWID)) AS nlb,
      NULL AS ndk,
      Sys_op_countchg(Substrb(t.ROWID,1,15),1) AS clf
FROM "OWNER"."TABLE_NAME" t
WHERE "COLUMN_NAME1" IS NOT NULL
OR "COLUMN_NAME2" IS NOT NULL

1. 원인 1
해당 쿼리의
opt_param('_optimizer_use_auto_indexes' 'on')
구문을 보면 DBMS_AUTO_INDEX와 연관이 있어보인다.

아래 테이블로 AUTO_INDEX와 연관된 정보를 확인할 수 있다.
DBA_AUTO_INDEX_VERIFICATIONS
DBA_AUTO_INDEX_STATISTICS
DBA_AUTO_INDEX_CONFIG
DBA_AUTO_INDEX_EXECUTIONS
DBA_AUTO_INDEX_SQL_ACTIONS
DBA_AUTO_INDEX_IND_ACTIONS

이중에 DBA_AUTO_INDEX_CONFIG 테이블을 확인해보면
AUTO_INDEX_MODE 행이 있는데
이것의 PARAMETER_VALUE값이 OFF가 아닌 경우에만
이번의 이슈가 DBMS_AUTO_INDEX 기능때문이라는 것으로
유추해볼 수 있다.

하지만 이번 사례는 해당 값이 OFF이므로 AUTO_INDEX와는
연관이 없었다.

그러면 해당 쿼리는 뭐때문에 수행되었는가?

2. 원인 2.
이 쿼리의 수행목적은 아래 뷰테이블의 수집 목적일 가능성이 크다.
V$INDEX_USAGE_INFO
DBA_INDEX_USAGE

아래의 히든 파라미터값이 TRUE인 경우 해당 인덱스 정보가 자동수집된다.
Default가 TRUE이다.

  NAME                       DESCRIPTION                               DEFAULT
  -------------------------  ----------------------------------------  -------
  _iut_enable                Control Index usage tracking              TRUE
  _iut_max_entries           Maximum Index entries to be tracked       30000
  _iut_stat_collection_type  Specify Index usage stat collection type  SAMPLED

**참고 : http://ksun-oracle.blogspot.com/2020/05/12cr2-index-usage-tracking-manual.html


원인은 알았고.
그럼 왜 종료되지 않고 계속 waing되었는가?

DBMS_SCHEDULER 작업 상태 확인

아래 쿼리로 스케줄러에서 수행하는 JOB을 확인할 수 있다.

SELECT LOG_DATE, OWNER, JOB_NAME, STATUS, SESSION_ID
      ,ADDITIONAL_INFO
FROM DBA_SCHEDULER_JOB_RUN_DETAILS
WHERE JOB_NAME LIKE '%AT_OS_OPT_SY%'
ORDER BY ACTUAL_START_DATE;

결과를 보면 지금까지 수행한 INDEX통계수집 정보를 날짜별로 확인가능하다.

JOB_NAME => ORA$AT_OS_OPT_SY_????
STATUS => JOB수행결과 (이 부분이 STOPPED였다.)
ADDITIONAL_INFO => 작업실패 원인
작업실패 원인이
REASON='Job slave process was terminated"
인 것 을 확인할 수 있었다.
Job slave process가 비정상상태인것이 원인이었다.

ALERT log확인

그리고 alert.log도 확인해 보았다.
해당 스케줄러가 수행중인 초기에는 log가 떨어진게 없었지만
약 10시간 이후부터 trace파일과 함께 아래 에러메시지가 떨어졌다.
System State dumped to trace file /pwd/DB_NAME_j000_3043.trc
Errors in file /pwd/DB_NAME_p00r_34422.trc
ORA-00600: internal error code, arguments: [15709], [29], [1], [2], [27], [P00R], [34422], [],
ORA-27403: scheduler stop job event
Incident details in: /pwd/incident/incdir_791189/DB_NAME_j000_3043_i791189.trc

ORA-00600의 아규먼트를 ORACLE SUPPORT에서 조회해도
내용이 나오지 않으므로
SR 오픈하여 진행해야한다.

결론

해당 이슈는 DBMS_SCHEDULER의 JOB에 의한
INDEX 통계정보 수집중 Job Process의 이슈로 인한 비정상 수행이
원인이 되어 해당 테이블에 Lock이 발생.
이후 업무 쿼리는 대기상태에 돌입.
해당 이슈로 인한 ORA-600에러 발생으로
정확한 진상규명이 어려워 ORACLE에 SR오픈하여 파악하는게 맞다.

끝.