2021/12/28 오전 10:35분경 업무가 정상 처리가 안된다는 연락을 받고
최초 테이블 Lock을 의심해서 Lock 정보를 조회하려 DB에 접속 시도를 했으나, 접속이 되지 않았다.
몇 번의 접속 시도를 하는데 갑자기 접속이 되어 DB를 보니 다른 Muiti-Zone으로 failover가 된 상태였다.
DB 시작시간을 확인해 보니 2021/12/28 오전 10:39:09 였다. 장애 발생 이후 시간이다.
이후 AWS RDS의 모니터링과 Performnace Insights 를 살펴보았다.
특정 시점에서 평소 5미만인 Active session이 478까지 증가하였고,
그 시점의 SQL이 library cache lock, library cache : mutex X, regmgr CPU quantum, kksfbc child completion, CPU 지표들이 상당히 높계 계측되었다.
CloudWatch가 수집한 서버 모니터링 정보를 보니,
CPU, DB Connections, Write IOPS, read IOPS 등의 장애 시점에 평소 대비 높았다.
특히 Freeable Memory는 장애 시점에 0으로 여유 메모리가 없는 상황이 발생했다. 이런 상황에서 AWS에서 RDS를 장애로 판단하고 Failover 시킨 것으로 보인다.
일단, SQL 을 추출하여 Plan 정보를 확인해 보았다. SQL문은 Bind 변수를 사용하였다.
특별한 점은 없어 보였다.
library cache lock event 로 보아, 장애 시점에 DDL이 있었을 것이라고 판단하고 object 들의 생성일자와 수정일자를 살펴보았다. 그 시점에 생성이나 변경된 object는 보이지 않았다. ( 생성하고 삭제했을 경우에는 알수가 없을까?)
장애 원인으로 가정한 아래 세가지 상황은 아니다.
1) 테이블 LOCK
2) library cache lock 이 발생한 SQL 관련 object의 생성이나 수정
3) 과도한 SQL 문장(bind 변수없이 literal 사용 포함)
그래서 library cache lock, library cache : mutex X 2가지 event를 추적해 보았다.
첫번째 왜 이런 이벤트(library cache lock, library cache : mutex X)가 발생하는가?
library cache lock 은
- SQL 구문을 파싱할 때나 LCO를 참조할 때 획득해야 하는 Lock으로 library cache lock 획득하지 못하여 대기하며 발생하는 이벤트이다.
library cache : mutex X
- shared pool에서 cursor를 검색할 때 mutex를 획득하지 못하여 대기하며 발생하는 이벤트이다
결론은 child cursor가 너무 많아 검색 시간이 오래 걸리면서 다른 세션들이 library cache lock, library cache : mutex X 를 획득하는데 대기하는 이벤트가 발생한 것으로 판단해 볼 수 있다.
장애 시점의 child cursor 에 대한 상세 정보를 추적해 본다.
1. snap_id 확인
dba_hist_snapshot 에서 장애 발생 시점의 snap_id를 확인해 보았다.
- 장애 직전 snapshot : 649
- 장애 이후 snapshot : 650
DB 기동 시간 : 2021/12/28 AM 10:39:09.000
2. sql_id와 SQL 관련 정보 확인
SQL fulltext와 sql_id 등의 정보를 얻고자 v$sql 을 조회하려고 했으나 v$sql은 dynamic performance view로 DB가 기동된 이후의 정보만 조회할 수 있으므로 failover된 상태라 dba_hist_sqltext과 dba_hist_sqlstat 뷰를 조회했다.
dba_hist_sqltext 에서 sql_id를 추출했다.
추출한 sql_id로 dba_hist_sqlstat 을 조회했다. 특이사항을 확인해 본다.
plan_hash_value 가 0 인 경우가 많다.
메모리 부족현상이 있었으니 sharable_mem 컬럼과 주의깊게 살펴볼 필요가 있는 dba_hist_sqlstat 테이블의 컬럼(loaded_versions, version_count, fetches_total, fetches_delta, executions_total, executions_delta, invalidations_total, invalidations_delta, parse_calls_total, parse_calls_delta, buffer_gets_total, buffer_gets_delta, rows_processed_total, rows_processed_delta, elapsed_time_total, elapsed_time_delta) 등을 선정해 분석해 본다.
장애 시점에 sharable_mem 값이 상당이 높게 나왔다. 그러나 다른 날의 자료와 비교해 볼 때 상대적으로 특이사항은 보이지 않는다.
version_count 값을 조회해 보니 상당이 높게 나왔다. 다른 날 대비 약간의 이상 징후가 보인다.
parse_calls_delta 값의 추이도 특이사항이 보이지 않는다.
elapsed_time_delta 값의 추이도 장애 시점 상 특이사항이 보이지 않는다.
1차 dba_hist_sqlstat 으로 분석한 결과, version_count 에 대한 분석이 필요한 것으로 판단된다.
* 특이사항으로는 위 컬럼의 정보들이 수집되지 않았다. NULL 값들이 상당히 많다 --> 왜 정보를 수집하지 못했는지에 대한 확인이 필요해 보인다. 정보수집을 못했을 때에 version_count가 상대적으로 상당히 값이 크다.
<참고사항>
장애 시점에 서버 메모리 사용률이 100% 이었는데 이는 어떻게 설명되는가? 아래 이미지를 보면 이해할 수 있을 것이다.
(1) 커서란?
공유 커서 (shared cursor) : 라이브러리 캐시에 공유돼 있는 Shared SQL Area
세션 커서 (session cursor) : Private SQL AREA에 저장된 커서
애플리케이션 커서 (application cursor) : 세션 커서를 가리키는 핸들
추가적으로, 대기 이벤트들이 발생하면서 Active session이 급격히 증가하였고
이는 서버 프로세스를 생성하며 메모리를 소진시키는 원인이 되었다.
1차 결론은
version_count 때문에 장애가 발생한 것을 추정하고 이 값을 중심으로 분석해 본다.
version_count는 무엇인가? 왜 version_count가 높게 나오는 것일까?
version_count란
SQL은 한번 파싱되면 실행계획을 생성하고 재사용하기 위해서 실행정보를 생성한다. ( 이를 LCO: library cache object 형태로 저장되며 shared cursor 라고 합니다.)
그리고 메모리(Shared pool 안의 library cache 안의 Shared SQL Area)에 저장합니다.
동일한 SQL 이더라도 여러가지 이유(주1)로 실행정보를 공유하지 못하면 추가적인 Chlid LCO ( child cursor )를 생성합니다.
즉, 새로운 버전의 child cursor 가 생성되는 것입니다. 이를 version count 가 증가한다고 표현합니다.
하나의 SQL(parent cursor)에 대해서 여러 child cursor 가 생기면 가장 문제가 되는 것은
SQL 수행시에 어떻게 실행할지 실행정보를 탐색하는데 오래걸리고,
경합이 발생할 수 있다는 점과 (이 때 발생하는 Wait Event를 library cache latch 라고 합니다.)
메모리의 공간을 차지한다는 점입니다.
아래 MOS 문서도 참고할 만합니다.
Troubleshooting: High Version Count Issues (Doc ID 296377.1)
https://support.oracle.com/epmos/faces/DocumentDisplay?id=296377.1
High SQL Version Counts - Script to determine reason(s) (Doc ID 438755.1)
https//support.oracle.com/epmos/faces/DocumentDisplay?id=438755.1
하나의 SQL 문장이 여러 개 Child 커서를 갖게 되는 이유
1. SQL에서 참조하는 오브젝트명이 같지만 SQL을 실행한 사용자에 따라 다른 오브젝트를 가리킬 때 - N/A
2. 참조 오브젝트가 변경돼 커서가 무효화되면 이후 그 커서를 처음 사용하려는 세션에 의해 다시 하드파싱돼야 하는데
, 특정 세션이 아직 기존 커서를 사용 중(Pin)일 때 - N/A
3. 옵티마이저 모드를 비롯해 옵티마이저 관련 파라미터가 다를 때
Optimizer mismatch : The optimizer environment does not match the existing child cursor
[ Optimizer Mode 외에 옵티마이져 관련 파라미터 불일치시 ]
4. 입력된 바인드 값의 길이가 크게 다를 때
5. NLS 파라미터를 다르게 설정했을 때 - NA
6. SQL trace를 활성화했을 때 - N/A
위의 사유 중 해당 사항을 찾기 위해
version_count가 높게 나온 이유를 파악하기 위해서 V$SQL_SHARED_CURSOR 조회한다.
mismatch 컬럼이 약 61개 정도라 일일이 'Y'인 값을 파악하는 것이 쉽지 않다.
아래 SQL을 수행하면 sql 문장이 출력되는데
출력된 SQL의 '&v_sql_id' 에 자신의 'sql_id' 를 입력한 후 query를 수행하면 mismatch 컬럼값이 'Y'인 것을 count 해서 보여준다.
select q'<select reason_not_sharing, count(*)
from gv$sql_shared_cursor
unpivot ( flag for reason_not_sharing in (>' || listagg(column_name, ', ') within group (order by null) || q'<) )
where sql_id = nvl('>' || '&' || q'<v_sql_id', sql_id)
and flag = 'Y'
group by reason_not_sharing>' x
from dba_tab_columns
where owner = 'SYS'
and table_name = 'V_$SQL_SHARED_CURSOR'
and data_type = 'VARCHAR2'
and data_length = 1;
-------- Results ------
REASON_NOT_SHARING:COUNT(*)
USE_FEEDBACK_STATS:47775
BIND_EQUIV_FAILURE:47787
LOAD_OPTIMIZER_STATS:6커서가 공유되지 않은 이유로 USE_FEEDBACK_STATS, BIND_EQUIV_FAILURE 로 조회되었다.
위의 query에서 찾은 컬럼으로 다시 아래 SQL로 reason까지 같이 조회해 본다.
SQL>
select BIND_EQUIV_FAILURE, use_feedback_stats, substr(s, instr(s, '<reason>')+8, instr(s, '</reason>') - (instr(s, '<reason>') + 8) ) res, count(*)
from
(
select BIND_EQUIV_FAILURE, use_feedback_stats, DBMS_LOB.substr(reason, 100, 1) s
from v$sql_shared_cursor where sql_id = '69v32zxbv1mzk'
)
group by BIND_EQUIV_FAILURE, use_feedback_stats, substr(s, instr(s, '<reason>')+8, instr(s, '</reason>') - (instr(s, '<reason>') + 8) )
order by 1;
------- Results --------------------------------
BIND_EQUIV_FAILURE:USE_FEEDBACK_STATS:RES:COUNT(*)
Y:N:Bind mismatch(24):6
Y:N:Bind mismatch(25):6
Y:Y:Bind mismatch(22):564
Y:Y:Bind mismatch(24):1145
Y:Y:Optimizer mismatch(13):46183커서가 공유되지 않은 이유로 USE_FEEDBACK_STATS, BIND_EQUIV_FAILURE이고 reason은 Bind mismatch와 Optimizer mismatch 로 조회되었다.
우선 bind mismatch가 발생한 사유를 알아보자.
BIND_MISMATCH : The bind metadata does not match the existing child cursor.
Oracle은 varchar2 TYPE을 32, 128, 2000, 4000 구간으로 나누어 bind 값을 사용하기 때문에 bind값의 길이에 따라 bind mismatch 가 발생한다. 그러나, 우리의 경우에는 bind를 4개 사용했고 각각 varchar2(27), varchar2(27), varchar2(1000), varchar2(1000) 이었다. 경우의 수를 따져도 9개(1*1*3*3)이다. 즉, 순수 bind 값의 길이 때문에 child cursor 가 새로 생겼다고 보기는 어려울 것 같다.
커서가 공유되지 않은 원인으로 도출된 두 개의 값에 대해 분석해 본다.
BIND_EQUIV_FAILURE = 'Y'
USE_FEEDBACK_STATS = 'Y'
이 두 값이 의미하는 것이 무엇인지 확인해 본다.
- USE_FEEDBACK_STATS : 카디널리티 피드백. 카디널리티 피드백이 사용 중이고 현재 실행에 대한 새 계획이 생성될 수 있다.
- BIND_EQUIV_FAILURE : 바인드 값의 선택도가 기존 자식 커서를 최적화하는 데 사용된 선택도와 일치하지 않습니다. adaptive cursor sharing이 설정되어 있고 커서가 바인드를 인식할 때 선택도가 현재 범위를 벗어나 새로운 Plan이 더 요구되는 경우 이전 Plan을 공유하지 않고 새로운 child cursor 생성합니다. 오라클 문서 836256.1을 참조하십시오.
- ... once the cursor is marked as bind aware and a second plan is seen then the following will be the resultant output:
SQL_ID ADDRESS CHILD_ADDRESS CHILD_NUMBER BAs can be seen, the new version is created due to BIND_EQUIV_FAILURE
------------- ---------------- ---------------- ------------ -
19sxt3v07nzm4 000000007A1C0DE0 000000007A1BF980 0 N
19sxt3v07nzm4 000000007A1C0DE0 000000007A10DDB0 1 Y - select sql_id, address, child_address, child_number, BIND_EQUIV_FAILURE from v$sql_shared_cursor where sql_id='19sxt3v07nzm4';
v$sql_cs_selectivity 조회
select count(*)
from v$sql_cs_selectivity
where sql_id='69v32zxbv1mzk' ;
--> 102052
select predicate, range_id, low, high, count(*)
from V$SQL_CS_SELECTIVITY where sql_id = '69v32zxbv1mzk'
group by predicate, range_id, low, high;
PREDICATE RANGE_ID LOW HIGH COUNT(*)
--------------------------------------------------
=1 0 0.301835 0.368910 2800
=1 0 0.296330 0.368910 1
=2 0 0.301827 0.368899 10633
=1 0 0.296330 0.368899 1
=1 0 0.296330 0.362181 32339
=2 0 0.296330 0.362181 32339
=2 0 0.296330 0.368910 1
=1 0 0.301827 0.368899 10633
=2 0 0.301835 0.368910 2800
=2 0 0.296330 0.368899 1선택도 범위(V$SQL_CS_SELECTIVITY)가 많으며 겹친다.
BIND_EQUIV_FAILURE 상세 설명
커서가 바인드를 인식하게 되면 이 커서가 실행될 때마다 확장 커서 공유 레이어 코드(Extended Cursor Sharing layer code)가 바인드 변수 값(본 문서의 경우에는 4개의 바인드 변수가 있음)을 보고(Peeking) v$sql_cs_selectivity에 대한 select를 실행한다. 기존 child 커서가 Peeking한 바인드 변수의 선택도를 수용하고 있는지 확인하기 위해서이다. 자식 커서가 발견되면 공유하고 그렇지 않은 경우 새 child 커서가 바인드 변수 값 선택성의 새 범위와 함께 v$sql_cs_selectivity에 입력된다.
이 경우 확장 커서 공유 레이어 코드(Extended Cursor Sharing layer code)가 v$sql_cs_selectivity에서 적절한 선택 범위(BIND_EQUIV_FAILURE)를 가진 자식 커서를 찾지 못하면 새로운 실행계획을 컴파일하고 다수의 "optimal" plan으로 v$sql 뷰를 채운다.
체크사항 :
- V$SQLAREA에서 커서의 VERSION_COUNT가 높다.
- 커서를 공유하지 않는 이유가 V$SQL_SHARED_CURSOR에 BIND_EQUIV_FAILURE로 표시된다.
- 쿼리에는 커서 공유와 관련된 바인드 변수를 사용했다.
- 선택도 범위(V$SQL_CS_SELECTIVITY)가 많으며 겹친다.
- 동시성이 높은 경우 문제가 "커서: 핀 S는 X에서 대기"로 표시되며 커서에 대해 대기한다.
위의 경우에 해당될 경우 버그로 의심할 수 있다. 그럴 경우 workaroud로 다음 설정을 권고한다. 본 문서가 오라클 공식 문서가 아니기에 적용 시 반드시 Oracle의 지원을 받아 진행해야 한다.
Workaround : _optimizer_extended_cursor_sharing_rel = none 으로 설정
결국은 optimizer_adaptive_cursor_sharing 때문인 것 같다.
DB 전체에 대해 사용하지 않도록 설정하던지, 아니면 문제를 일으키는 SQL 관련 테이블의 컬럼에 대해서만 설정하던지.
일단, 후자를 선택해 진행해 본다.
대상 테이블 컬럼의 histogram 을 삭제하고, 더 이상 histogram을 생성하지 않도록 설정한다.
상기 장애와 관련하여 최선의 선택이 아닐까 한다. 물론 다른 부작용도 검토를 해야 한다.
Disable the Adaptive cursor sharing in Oracle
alter system set "_optimizer_adaptive_cursor_sharing"=false scope= both;
--Disable bind variable or other parameter
alter system set "cursor_sharing"=exact scope=both;
alter system set "_optimizer_extended_cursor_sharing_rel"=none scope=both;
alter system set "_optimizer_extended_cursor_sharing"=none scope= both;
Three 11g features of cost-based optimization and SQL execution to consider when upgrading from 10g:
Cardinality feedback. This feature, enabled by default in 11.2, is intended to improve execution plans for repeated executions. See Support note 1344937.1 and documentation for additional info. You can be disable cardinality feedback with an underscore parameter which can be set at session or instance level. Usual caveats on setting underscore parameters apply:
alter session set "_OPTIMIZER_USE_FEEDBACK"=FALSE;
This can also be done with a hint, therefore at statement level, using the opt_param syntax: /*+ opt_param('_OPTIMIZER_USE_FEEDBACK','FALSE') */
Adaptive cursor sharing. This was introduced in 11gR1 to address SQL performance consistency issues related to bind variable peeking. See support note 740052.1 and documentation for details. For the purposes of this doc, if you want to get the 10g behavior with an Oracle version higher than 10g and overall if you want to disable this feature, you may want to add the hint:
/*+ NO_BIND_AWARE */.
According to support note 11657468.8 adaptive cursor sharing can be disabled by setting the following 2 parameters (say at session level): _optimizer_adaptive_cursor_sharing = false, _optimizer_extended_cursor_sharing_rel = "none"
For more details on this bug, the Document ID of MOS is 14176247.8
참조 : https://www.linkedin.com/pulse/oracle-cursor-sharing-bug-diego-zucca
위에서 발생한
kksfbc child completion 이벤트에 대해 _kks_use_mutex_pin = false 로 설정하라는 글들이 있는데
이 hidden parameter는 Oracle 동의가 있어야만 사용해야 하며 이 매개변수는 Oracle 12c에서 설정하면 안 됩니다." 라는 글도 있으니 참고하기 바랍니다. 본 문서에서는 이 이벤트는 다루지 않는다.
- Version Count가 큰 SQL 확인
SQL>SELECT SQL_ID , VERSION_COUNT , EXECUTIONS , INVALIDATIONS
FROM v$sqlarea
where sql_id = '위에서 찾은 sql_id'
ORDER BY version_count desc;
69v32zxbv1mzk 4097 54132 0
USE_FEEDBACK_STATS이 'Y' 인 경우,
(Y|N) A hard parse is forced so that the optimizer can reoptimize the query with improved cardinality estimates
옵티마이저가 향상된 카디널리티 추정으로 쿼리를 다시 최적화할 수 있도록 하드 구문 분석이 강제 실행됩니다.
AWR Report 확인
AWS RDS Oracle Enterprise version에서만 제공한다.
ASH Report 확인
alert log 파일 확인
tarce 파일 확인
<참고>
semaphore vs mutex 란?
mutex : object, 자물쇠, locking mechanism, multiple program threads 이 single recource에만 접근 가능(동시 접근 불가), 오직 mutex를 acquire/release 할 수만 있다(Locked or unlocked)
화장실 열쇠
semaphore : sgnaling mechanism, 신호동, integer(couting semaphore), semaphore value는 update할수 있다.
signal and wait.
'ORACLE' 카테고리의 다른 글
| Parent Cursors and Child Cursors (0) | 2022.01.01 |
|---|---|
| 컬럼에 히스토그램을 삭제하고 자동 통계가 생성되지 않도록 하려면? (0) | 2021.12.30 |
| cardinality란 ? (0) | 2021.12.28 |
| 도커(docker) container로 오라클 사용하기 (0) | 2021.12.22 |
| Oracle ADG AFFIRM/NOAFFIRM VS SYNC/ASYNC (0) | 2021.12.21 |