태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

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

엑셈 사람들 2009.02.13 17:36

모 고객사에 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 사용률을 보이지 않았다.

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

  • Favicon of https://ukja.tistory.com 욱짜 2009.02.14 08:17 신고 ADDR 수정/삭제 답글

    ㅋㅋ
    진짜 재미있는 문제였네요. 무한루프 @_@

    몇가지 정도 짚어봤으면 하는게 있는데...

    1. 정확한 버전이? (예: 10.2.0.4)

    2. _kks_use_mutex_pin을 true->false로 바꾸었더니 cursos: pin S 이벤트가 없어졌다는거죠? 그리고 CPU 사용률은 내려가고?
    이 현상을 무한루프와 연결해서 생각해보면, "Cusor를 실행하기 위해 Cursor를 보호하는 Mutex를 획득해야하는데 이 과정에서 Mutex 경합이 생겼다" 이렇게 해석할 수 있겠네요? Oracle의 Mutex는 *아마도* 매우 가볍게 구현되었을텐데 이런 특수한 경우처럼 획득이 지나치게 잦으면 오히려 더 성능이 느려지는 경우도 있다라고 볼 수 있겠네요.

    3. latch: library cache를 대기하면서 CPU를 100% 사용했다면, 아마 대기 이벤트의 상태가 WAITING이 아니라, WAITED SHORT TIME 정도였을겁니다. 즉 latch: library cache를 잠깐 대기했다가 CPU를 점유하는 현상이었을 겁니다. latch를 잠깐 대기하고 다시 CPU를 점유하고 이런 현상이 반복되었을 수도 있을 것이고... 시스템 전체 레벨에서 latch: library cache의 대기 시간을 보면 검증할 수 있겠네요.

    11g부터는 libary cache latch 자체가 사라지고 모든 것을 Mutex로 대치했는데, 11g에서는 어떤 현상들이 생길지 사뭇 기대가 되네요. ^^

  • 창대리 2009.02.16 11:09 ADDR 수정/삭제 답글

    ~_~ 재미있게 봐주셔서 감사합니다..
    1. 정확한 버전은 OS AIX 5.3에 Oracle 10.2.0.2였습니다.
    2. Event는 없어졌으나 CPU 사용률은 다시 증가하는 현상이 나타났습니다.
    latch: library cache나 cursor: pin S 이벤트의 대기 현상으로 인한 CPU 사용률 증가가 아니라 Function의 무한루프 실행으로 인한 CPU사용률 증가가 원인이었습니다. 그래서 mutex 경합으로 인해 CPU사용률이 증가한다고 보기는 힘들 것 같습니다.
    아직 Oracle에서도 AIX에 대한 버그 리포트는 올라와 있지 않고 있고요.. HP PA-RISC나 IA64는 현재 나와 있으며 OS Patch 및 Oracle Patch 가 릴리즈 되어 있는 것으로 알고 있습니다.
    참으로 뜻깊은 경험을 했었습니다. ~_~a

  • 귀차나... 2009.02.16 14:49 ADDR 수정/삭제 답글

    latch가 mutex보다 무거우니
    latch를 쓸때는 오히려 경합 때문에 수행이 더디게 진행되었고
    이 족쇄를 풀어버리고 가벼운 mutex를 쓰니까
    문제가 확 부각 되어버린 셈이었네요...
    역시 상황을 해결하는 팁보다는 비정상적인 function이라는 근본 원인에 대한
    정공법적인 대처가 중요하다는 것을 일깨워준 사례인것 같습니다..

  • Favicon of https://ukja.tistory.com 욱짜 2009.02.16 15:26 신고 ADDR 수정/삭제 답글

    > {quote} latch: library cache나 cursor: pin S 이벤트의 대기 현상으로 인한 CPU 사용률 증가가 아니라 Function의 무한루프 실행으로 인한 CPU사용률 증가가 원인이었습니다. 그래서 mutex 경합으로 인해 CPU사용률이 증가한다고 보기는 힘들 것 같습니다. {quote}

    내가 의미했던게 이거예요.
    latch: library cache 이벤트를 대기하면서 CPU를 100% 사용할 수는 없거든요. 그러니까 CPU를 100% 사용하고 있던 세션은 이 이벤트를 대기하고 있던게 아니라 아주 잠깐 대기한 후 CPU를 점유한게 아닌가 하는거죠. v$session_wait.status가 'WAITING'이 아니라 'WAITED SHORT TIME' 정도로 나타난게 아닌가하는거죠. Maxgauge로 모니터링할 때 이 정보가 안보여서 착각하는 경우가 많거든요.