[이창원]넓은 시야에 대한 성찰

모 고객사에 2주 동안 가서 컨설팅 지원을 하라는 팀장님의 엄명이 급하게 내려졌다.

나는 이에 순한 양마냥 넵 하고 사전 탐사를 떠났다.

담당자도 이미 뵈었던 분이셔서 인사를 드리고 잠깐 시스템을 점검하고, 우리 회사의 Oracle 모니터링 툴인 Maxgauge를 구동시켰다. 그리고 Real time Monitor를 이용하여 살짝 상황을 지켜봤다.

그런데 이게 왠일인가.

Database밖에 없다던 서버는 CPU가 100%를 꾸준히 유지하고 있었다. 그리고 담당자께서도 CPU를 증설해도 상황이 나아지지 않는다고 설명해주셨다. 그래서 Database의 일량을 살며시 살펴보았다.

어머…

Session Logical Reads가 초당 50000 블록을 넘지 않고 있었다. 무언가 정체를 알 수 없는 Process가 구동 중인가 해서 Topas를 이용하여 살펴 보았다. (시스템이 I00 이었다.=_=;;)  그러나 없었다. Process는 Oracle Server Process 밖에..

그래서 나는 우리 회사의 분석 방법론인 숲을 보고 나무를 보는 방식을 실행했다.

Oracle Server Process면 Active Session이 무엇을 하는지 확인해 보기로 했다. 그랬더니 다수의 Active Session이 cursor : pin S라는 이벤트를 대기하는 것이었다.
 

아!!! 많이 보았던 Wait Event였다.

그리고 김한도 과장님께서 예전에 알려주신 버그가 생각이 났고, RISC 방식에서는 mutex 방식의 문제가 있다는 오라클 문서가 생각이 났다. 그리고 임시 방편인 히든 파라미터인 _kks_use_mutex_pin를 false로 수정하여 문제를 해결할 수 있다는 생각까지 정말 순식간에 스쳐갔다.

컨설팅이 시작된 날, 현상 및 파라미터 변경에 대해 권고를 하였다. 그리고 이 상황으로 계속 두시면 CPU를 아무리 증설을 해도 Process는 좋다면서 CPU를 팍팍 사용하여 100%를 유지할 것이라는 상황 설명도 잊지 않았다. 담당자께서는 그 날 저녁에 바로 파라미터를 수정하자고 하셨다.

그 날 저녁, 파라미터를 수정한 후 나는 모니터링을 하면서 점점 이상한 느낌을 받기 시작했다.

Session 하나가 latch : library cache 이벤트를 대기하면서 CPU를 1장 다 사용하기 시작한 것이었다.

분명히 library cache latch는 posting 방식으로 획득 대기하기 때문에 CPU를 과다하게 사용하지 않을 것인데, 이 Session은 왜 CPU를 혼자서 다 사용하는가… 이런 의문이 들기 시작했다. 히든 파라미터 수정에 의한 Side Effect인가 해서 담당자에게 말씀드리고 kill session을 수행했다. 그 후 그 날은 아무 이슈 없이 넘어갔다.

다음 날이었다.

출근하고 상황을 지켜보는데 어제 저녁처럼 latch: library cache 이벤트를 대기하는 Session이 5개 정도 생긴 상태였다. CPU도 전체 60%정도 사용하고 있었다. 어설프게 생각하고 제대로 분석하지 않고 선택한 임시 방편이 문제를 일으키는 것인가 하는 생각이 퐉 들었다. 일단 Session이 수행하는 SQL과 일량을 지켜보았다.

수행 중인 SQL은 변하지 않았으나 이에 대한 Logical I/O는 아예 발생하지 않고 있었다. 그런데 Execute Count가 초당 5000회 이상으로 나타나는 것이었다.

이게 왠일인가… 우리 Maxgauge에서 잘못 보여주는 것인가.. 아님 내 눈이 비정상 작동을 시작한 것인가..

Session이 수행한 SQL을 다시 자세히 살펴보았다. Select list에 function이 호출되는 것을 확인하였다. 그래서 이 Function이 어떤 일을 하는가를 살펴 보았다. Function은 날짜를 인수로 받아서 종료일을 구하기 위해 루프 돌면서 add_month를 하는 것이었다. 그런데 왜 Execute Count가 5000회 이상이나 나타나는가? 이것만으로는 원인을 알 수 없었다. 그래서 Session에 10046 Trace를 수행하였다. 한 5분 정도 수행한 후, Trace file을 열었다. 엄청 놀랐다. Function에 입력된 값을 살펴보고 있었는데 null값을 입력받아 add_month를 하는 것이었다.

그리고 특정 값을 얻을 때까지 루프를 돌고 있었다. =_=;; 그랬던 것이다.

cursor : pin S 라는 이벤트, mutex에 대한 버그가 아니라 function에 넘어오는 인수 값이 문제였던 것이었다. 담당자에게 말씀드리고 개발자를 찾아 Function을 수정하였다. 그리고 그 이후 해당 시스템은 30%이상의 CPU 사용률을 보이지 않았다.

아… 점점 넓어지는 시야를 가지고 컨설팅을 해야 하는데, 이렇게 박혀있는 시야로 컨설팅을 하려고 했다니...
왠지 나 자신에 대해 다시 한 번 심각하게 생각해 보는 계기가 되었다. 넓은 시야로 상황 분석 및 원인 파악을 더 연마해야겠다는 생각을 하게 되었다.