현상

• 13시 25분에 업무 1팀이 담당하는 몇 개의 어플리케이션의 성능이 약 5분전부터 저하되고 있다는 연락을 받았다.
• AWR 스냅샷이 한 시간 주기로 수행되므로 수동으로 AWR스냅샷을 생성하고 분석하려는 와중에 성능 저하 현상이 종료되었다.

25분 구간의 AWR DB보고서의 Top 5 Timed Events

• latch: cache buffers lru chain 대기 이벤트가 문제를 유발하였으리라는 짐작이 가지만 대기 이벤트가 차지하는 비중이 낮으며 성능 저하가 발생한 시간에 해당 이벤트가 발생하였는지에 대한 확신을 가질 수 없다.
• latch: cache buffers chains 대기 이벤트 발생 시간을 알아보기 위해 Activity Over Time 단위 보고서의 시간 분석 간격을 1 초로 설정하여 성능 저하 현상이 발견된 시간대인 13:20- 13: 28의 ASH 보고서를생성하였다.

ASH 보고서 : Top User Events

• 버퍼 캐시 관련 래치 이벤트가 주요 발생 대기 이벤트이며 다른 경합 관련 이벤트가 없음을 확인할 수 있다.

Activity Over Time 단위 보고서

• 13시 21분 9초부터 latch: cache buffers lru chain 대기 이벤트가 발생하고 있다.
• 성능 저하 시점과 성능 저하 현상이 없어진 시점이 latch: cache buffers lru chain 대기 이벤트 발생 시작 시점과 종료 시점이 거의 일치한다.
• 대략 13:21- 13:26 사이에 버퍼 캐시 관련 래치 경합으로 성능 저하가 발생하였음을 예상할 수있다.

Top SQL Statements 단위 보고서

• 버퍼 캐시 관련 래치 경합을 유발시킨 SQL 확인
  
• SQL ID가 5nkxmmjOqu5g0과 8vt3rd6tnp6n2인 SQL에서 버퍼 캐시 관련 렛치 경합이 발생하고 있으며，경합이 발생하고 있는 SQL이 사용하는 테이블이 COMM_CUST_INFO와 SCV_INV_TF임을 확인할 수있다

Top DB Objects 단위 보고서

• 래치 경합이 발생하고 있은 오브젝트를 파악
  
• latch : cache buffers lru chain 대기 이벤트는 보통의 경우 대 량 1/0로 인해 발생한다. COMM_CUST_INFO와 SCV_INV_TF 두 테이블이 모두 포함되어 있으나, COMM_CUST_INFO 테이블이 제일 상위에 있으며 전체 테이블 스캔시 발생하는 이벤트인 ddb file scattered read 이벤트가 같이 발생한 것으로 보아 이 테이블이 렛치 경합을 유발시킨 테이블일 가능성이 높다.

AWRDB 보고서의 SQL ordered by Gets 단위 보고서

• SQL 수행 시 발생하는 버퍼 캐시 1/0를 확인
  
• SQL ID가 8vt3rd6tnp6n2인 SQL이 1회 수행당 473290.2회의 1/0를 발생시키면서 스냅삿 구간 버퍼 캐시 1/0의 78%를 차지하며 과도한 버퍼 캐시 1/0를 발생시키고 있다.

문제 구간에 SQL ID가 8vt3rd6tnp6n2 수행 여부 확인

• 13:20:00-13:21:00 구간과 13:26:30-13:28:00 구간의 ASH 보고서를 생성한 뒤， Top SQL Statements 단위 보고서에 기록된 SQL을 확인하면 파악할 수 있다.
• 확인 결과 SQL ID:8vt3rd6tnp6n2는 13:21 :00- 13:26:30 구간에서만 수행되었다.

결론

• 문제 원인은 악성 SQL 수행으로 인한 대량 1/0 발생이다.
• 재발 방지를 위해 해당 SQL문이 왜 문제 구간에만 수행되었는지 확인한다.