동시접속급증에의한 log file sync 대기과다로인한성능저하현상분석 EXEM CO., LTD www.ex-em.com 2006.06 오라클프로세스의접속이순간적으로급증할경우, 접속시에필요한리소스확보및 recursive SQL 수행후의내부 Commit 수행으로인한순간적인서비스중단이발생하게된다. OLTP 및 WEB 환경에서는이러한순간적인서비스장애역시비즈니스가동률을떨어뜨리는요소임에틀림없다. 따라서이번 Case Study 에서는, Oracle DBMS 의성능진단 / 분석툴인 MaxGauge( 맥스게이지 ) 를활용하여, 동시접속과다에의해발생한성능저하문제의원인을규명해보고자한다. 본사례에서사용한문제원인분석의 Flow(Performance Analyzer / MaxGauge) Drill-Down Flow Menu & Data 1. 성능저하구간의확인 [Trend Analysis] 메뉴에서 CPU 사용률의급변, Active Session 의증가, Wait Events 의급증등성능저하구간을확인함. 3. Wait Event 의검출및분석 4. Wait Event 발생원인의조사 5. 세션및 SQL 의분석을통한문제원인의규명 [Trend Analysis] 메뉴에서, 문제원인이되는 Wait Events 를특정하고, 그내용을분석함. [Trend Analysis] 메뉴에서, log file writing 과관련된 redo write time, redo synch time, user commits 등 STAT 지표와 Logon 과관련된 logons current, logons cumulative 추이를분석함. [Session List] 메뉴에서, log file sync 를대기하고있는프로세스및, LGWR 프로세스에대한세션정보및 SQL 을분석하여문제원인을규명함. 1
1. 성능저하구간의확인 성능문제가발생한 HGJ 인스턴스에서수집된가동이력로그로부터일간추이그래프를확인해보면, CPU 사용률에는뚜렷한변화가없어보이지만, 16 시 47 분에 Active Session 이급증하였고 16 시 46 분에 Wait 수치가급증하는것을쉽게확인할수있다. CPU 사용률의추이그래프 Active Session 수의추이그래프 Wait Events 의추이그래프 (Wait Time) 2. Wait Events 의검출및분석 Active Session 의급증으로인한성능저하 (Performance Slow-Down) 의원인을규명하기위해, 문제시점 (16 시 46 분및 16 시 47 분 ) 의 Wait Events 발생내용을확인해본다. 2
Value 탭에서동시점의 Top Wait Event 를확인한결과, Idle Event(= SQL*Net message from client) 를제외한 Top Wait Event 는 log file sync 이며, 16 시 46 분에 log file sync 이벤트의대기시간이가장높았으며 ( 초당 309 초 ) Active Session 의 Peak 시점인 16 시 47 분에는 log file sync 이벤트의대기시간이감소 ( 초당 18 초 ) 하였다. Active Session 의급증에대한 log file sync 대기이벤트의연관성을규정하기위해, 대기이벤트와의발생패턴을비교해본결과, Active Sessions 의발생추이와상당히유사하고, 문제시점에발생한 Wait Events(Wait Time) 의약 97%( 전체 317.88 초중에서, 307.75 초를점유함 ) 를차지하고있다. 즉, Active Session 의급증은 log file sync 대기이벤트의급격한발생과연관이있음을추측할수있다. <<16:46:58 초화면으로 Dump 함 작업시참조하세요 >> 3
실제로, 같은시점의세션상세데이터를표시하는 세션 Grid 화면에서도, log file sync 대기이벤트가많이발생해있음을확인할수있으며, 세션들의접속시간이대부분동시간대임을확인할수있다. 3. Wait Event(log file sync) 발생원인의조사 ( 출처 :Oracle performance tuning for 10g Oracle) log file sync 대기이벤트는일반적으로 User Commit 또는 Rollback 시에수행되는 LGWR 프로세스의 sync write 에의해발생되며, 주로과다한 Commit 또는 LGWR 프로세스의 I/O 처리속도의문제로인해발생하게된다. 따라서, 우선적으로 Commit 및 LGWR 프로세스의활동성과관련있는지표인 user commits, redo write time, redo synch time, redo entries 의추이를확인해본다. 4
추이그래프의분석결과, log file sync 이벤트의대기시간이급증한시점에서 user commits 수치는초당 259 회로다른시점과비교하여높지않으며, redo 발생개수를나타내는 redo entries 수치또한다른시점에비해높지않게나타나고있다. 하지만이시점에 User Commit 에의해발생되는 redo synch writes 에대한처리시간을나타내는지표인 redo synch time 수치는 31727 centi-seconds (317 초 ) 이며, LGWR 프로세스가 LOG BUFFER 내의 redo record 를 REDO LOG FILE 에기록하는데소요된시간을나타내는 redo write time 수치는 35 centi-seconds (0.35 초 ) 이므로 - 대기시간이길지않음 -, LGWR 프로세스의 I/O 성능저하로인한문제라기보다는 redo synch writes 에대한처리시간이높게나타난다는것이가장큰문제원인이라고할수있다. 위의세션상세데이터를통해 log file sync 이벤트를대기하는세션들의접속시간이대부분동시간대임에착안하여, Logon 과관련된 logons current, logons cumulative 지표와 active sessions, log file sync 지표를비교분석해보기로한다. 추이그래프의분석결과를시간순으로정리하면다음과같다. 16:44 분동시접속자수를나타내는 logons current 수치가 5689 로 peak 를나타냄 16:46 분초당접속자수를나타내는 logons cumulative 수치가 17 로 peak 를나타냄이시점에 log file sync 지표도 peak 임 16:47 분 Active Session 지표가 Peak 임 4. 세션및 SQL 의분석을통한문제원인의규명 log file sync 이벤트대기가극심했던 16 시 46 분 ~16 시 47 분구간에서 log file sync 를대기하는세션을검색해본결과, 일반프로그램에서 Logon 처리를위해 SYS Schema 로 recursive sql (SEQ$ Update) 를수행하고있는것을확인할수있다. 5
Logon 시에는 V$SESSION.AUDSID 칼럼에값을설정하기위해 SYS.AUDSES$ 라는시퀀스의값을획득해야하며, 만일해당시퀀스의 CACHE size 가작아서, dictionary cache (DBA_SEQUENCES.LAST_NUMBER) 를변경하여야할경우에 SYS.SEQ$ 를 UPDATE 하는 recursive sql 이수행되고, 내부적인 COMMIT 이발생하게된다. 이러한 COMMIT 은 User 가직접수행한 COMMIT 이아니기때문에, user commits 지표의수치에반영되지않게된다. 6
5. 결론및해결방안 Performance Slow-Down 현상 ( 동시접속과다시점에 log file sync 대기에의한 Active session 의급증 ) SYS.AUDSES$ 시퀀스의 CACHE Size 가작아서 SYS.SEQ$ 를 UPDATE 하는내부 SQL 수행및 COMMIT 과다 SYS.AUDSES$ 시퀀스의 CACHE 값을크게조정 SQL> alter sequence sys.audses$ cache 10000; 7