Basic Info
사용자가 Commit 또는 Rollback 명령을 요청하면 Server Process는 LGWR에게 요청을 전달한다. LGWR는 Redo Buffer에서 가장 마지막에 기록이 이루어진 이후 시점부터 Commit 지점까지의 모든 Redo Entry를 Redo Log File에 기록한다. 이것을 "sync write"라고 부르며 redo synch writes 통계값을 통해 조회 가능하다. Server Process는 Commit 명령을 내린 후 LGWR가 성공적으로 기록을 할 때까지 기다리게 되는데, 이때 log file sync 이벤트를 대기하게 된다.
다시 말해 로그 동기화(log synchronization)를 수행하는 동안, LGWR 프로세스는 “sync write” 가 완료할 때까지 log file parallel write 대기이벤트를 대기하게 되고, Server Process는 log file sync 대기이벤트를 대기하는 것이다.
Server Process는 2가지 이유로 인해 log file sync 대기이벤트를 겪게 된다. 하나는 로그 동기화가 완료되기를 대기하는 것이다. 다른 하나는 대기가 타임아웃(일반적으로 1초)되는 경우이다. 타임아웃이 발생하면 Server Process는 Commit 정보가 디스크에 기록되었는지를 확인하기 위해 현재 로그 SCN (System Change Number)을 확인한다. 만일 Commit 정보가 디스크에 기록되었다면 대기를 그만두고 작업을 진행하며, 그렇지 않을 경우 계속 log file sync 대기 이벤트를 지속하게 된다.
만일 세션이 동일한 buffer#를 대기한다면 V$SESSION_WAIT의 SEQ# 컬럼의 값은 매초마다 증가한다. SEQ# 컬럼의 값이 증가할 경우의 블로킹 프로세스는 LGWR 이다. 이러한 경우 LGWR 프로세스가 다른 이유로 인해 대기 중 인지를 확인해야 한다.
일반적으로, log file sync는 매우 평범한 대기이벤트이다. 사용자가 인식하기 힘들만큼 매우 단시간에 발생한다. 하지만, log file sync 대기이벤트의 과다 현상은 응답시간을 상당히 지연시키게 되며, V$SYSTEM_EVENT 및V$SESSION_EVENT 뷰에서 눈에 띌 만한 대기통계정보를 나타내게 된다. 아래의 쿼리를 사용하여 접속 후부터 현재까지 log file sync 대기이벤트를 극심하게 대기한 세션을 찾을 수 있다. 아래 예제를 보자.
select a.sid,
a.event,
a.time_waited,
a.time_waited / c.sum_time_waited * 100 pct_wait_time,
d.value user_commits,
round((sysdate - b.logon_time) * 24) hours_connected
from v$session_event a, v$session b, v$sesstat d,
(select sid, sum(time_waited) sum_time_waited
from v$session_event
where event not in (
'Null event',
'client message',
'KXFX: Execution Message Dequeue - Slave',
'PX Deq: Execution Msg',
'KXFQ: kxfqdeq - normal deqeue',
'PX Deq: Table Q Normal',
'Wait for credit - send blocked',
'PX Deq Credit: send blkd',
'Wait for credit - need buffer to send',
'PX Deq Credit: need buffer',
'Wait for credit - free buffer',
'PX Deq Credit: free buffer',
'parallel query dequeue wait',
'PX Deque wait',
'Parallel Query Idle Wait - Slaves',
'PX Idle Wait',
'slave wait',
'dispatcher timer',
'virtual circuit status',
'pipe get',
'rdbms ipc message',
'rdbms ipc reply',
'pmon timer',
'smon timer',
'PL/SQL lock timer',
'SQL*Net message from client',
'WMON goes to sleep')
having sum(time_waited) > 0 group by sid) c
where a.sid = b.sid
and a.sid = c.sid
and a.sid = d.sid
and d.statistic# = (select statistic#
from v$statname
where name = 'user commits')
and a.time_waited > 10000
and a.event = 'log file sync'
order by pct_wait_time, hours_connected;
SID EVENT TIME_WAITED PCT_WAIT_TIME USER_COMMITS HOURS_CONNECTED
---- ------------- ----------- ------------- ------------ ---------------
423 log file sync 13441 84.9352291 62852 15
288 log file sync 13823 85.3535042 63007 15
422 log file sync 13580 85.7648099 62863 15
406 log file sync 13460 87.0239866 62865 15
260 log file sync 13808 87.0398386 62903 15
[편집]Parameter & Wait Time
[편집]Wait Parameters
log file sync 대기이벤트의 파라미터는 다음과 같다.
- P1 : 로그Buffer내의 buffer#
- P2 : 사용되지 않음
- P3 : 사용되지 않음
[편집]Wait Time
1초
[편집]Check Point & Solution
Transaction이란 결국 데이터를 변경하는 것이 목적이기 때문에 Commit이 수반되는 것은 당연하다. 자연스럽게 log file sync 대기이벤트는 오라클에서 가장 보편적인 대기 이벤트 중 하나이다. 보통 sync write가 수행되는 시간은 매우 짧다. 그래서 log file sync 대기는 문제가 되지는 않지만 다량으로 발생하게 되면 상당히 해결하기 어려운 대기현상이다. 만일 log file sync 대기가 광범위하게 나타난다면 다음과 같은 사실을 의심해보아야 한다.
- Commit 회수가 지나치게 많지 않은가?
- I/O 시스템이 느리지 않은가?
- Redo 데이터가 불필요하게 생성되지는 않는가?
- Redo Buffer가 지나치게 크지 않은가?
[편집]Commit 회수와 log file sync
Commit을 과다하게 발생하는 것이 log file sync 대기의 가장 대표적인 원인이다. 만일 세션이 오랜 시간 log file sync 대기이벤트를 대기한다면, 해당 세션이 배치 프로세스인지, OLTP 프로세스인지 또는 미들티어(Tuxedo, Weblogic 등)와 같은 영구 커넥션(persistent connection)인지 확인해야 한다.
만일 세션이 배치 프로세스라면, 루프 내에서 반복적으로 Commit을 수행할 수 있다. 이 경우 모듈의 이름을 확인한 후 Commit의 횟수를 줄일 수 있는지를 점검하기 위해서 개발자에게 코드를 점검하라고 요청해야 한다. 이것은 어플리케이션 이슈이며, 해결 방안은 단순히 불필요한 Commit을 제거하여 전체적인 Commit 발생률을 줄이는 것이다. 일반적인 경우 Commit을 한번 수행할 때마다 한번의 log file sync 대기가 발생한다. 따라서 여러 세션에서 동시에 대량의 Commit을 수행하면 log file sync 대기가 광범위하게 나타날 수 있다.
아래 테스트 결과를 보면 Update를 수행하고 Commit을 수행할 때마다 log file sync 대기이벤트의 대기회수와 대기시간은 비례해서 증가하는 것을 확인할 수 있다.
SQL> select event, total_waits, time_waited from v$session_event SQL> where sid = (select sid from v$mystat where rownum = 1) SQL> and event = 'log file sync'; EVENT TOTAL_WAITS TIME_WAITED ------------------------------ ----------- ----------- log file sync 4 3 SQL> update redo_test set id = 1 where rownum = 1; SQL> commit; SQL> select event, total_waits, time_waited from v$session_event SQL> where sid = (select sid from v$mystat where rownum = 1) SQL> and event = 'log file sync'; EVENT TOTAL_WAITS TIME_WAITED ------------------------------ ----------- ----------- log file sync 5 4 SQL> update redo_test set id = 1 where rownum = 1; SQL> commit; SQL> select event, total_waits, time_waited from v$session_event SQL> where sid = (select sid from v$mystat where rownum = 1) SQL> and event = 'log file sync'; EVENT TOTAL_WAITS TIME_WAITED ------------------------------ ----------- ----------- log file sync 6 5
PL/SQL 블록을 사용하는 경우 Group Commit으로 인해, Commit에 의한 성능저하현상이 어느 정도 해소되기는 하지만 잦은 Commit은 여전히 많은 문제를 일으키며 특히 짧은 Transaction에 의해 동시다발적인 Commit이 자주 발생하는 경우에는 log file sync 대기에 의해 심각한 성능저하가 발생할 수 있다. 따라서 가능하면 Transaction 단위를 합리적으로 묶어서 Commit이 이루어지게끔 하며, PL/SQL을 활용하는 것이 바람직하다.
[편집]Commit 회수와 롤백(언두) 세그먼트의 관계
많은 어플리케이션 개발자들은 Commit을 자주 수행하지 않으면, 롤백 세그먼트의 공간 부족으로 인해 작업이 실패한다고 알고 있다. Deadlock에 의한 문제를 겪은 사람들도 더 자주 Commit을 수행하라고 말하곤 한다. 하지만 가장 올바른 방법은 Transaction을 명확히 정의한 후 각각의 Transaction 단위로 Commit을 수행하는 것이다. Transaction은 업무의 단위(unit)이다. 단위 업무는 그 안의 모든 내용이 성공하거나 실패해야 한다. Commit 또는 롤백의 적절한 위치는 단위 업무의 마지막 부분이다. 롤백 세그먼트 공간이나 Deadlock 방지를 위해 추가적인 Commit을 수행하지 마라. 이것은 진정한 문제 해결 방법이 아니기 때문이다. 만일 단위 업무를 처리할 수 있는 롤백 세그먼트가 존재하지 않는다면, DBA 에게 적절한 롤백 세그먼트를 요청해야 한다. 만약 오라클 9i부터 소개된 Automatic Undo Management 방식을 사용한다면, UNDO 테이블스페이스를 위해 충분한 공간을 할당하고 적절한 undo retention 시간을 설정해야 한다.
불필요한 Commit은 또 다른 문제를 발생시킨다. 그 중 하나가 ORA-01555: 에러이며 이것은 롤백(또는 언두) 데이터가 겹쳐 쓰여져서 발생된다. 또한 높은 Commit 발생률은 Transaction의 시작과 종료와 관련된 부하를 가중시킨다. 각 Transaction이 시작할 때, 오라클은 롤백 세그먼트를 할당하고(롤백 세그먼트 바인딩이라고 불림) 롤백 세그먼트 헤더 내의 Transaction 테이블을 업데이트한다. 또한 Transaction 테이블은 각 Transaction의 종료 시에도 업데이트된다. 롤백 세그먼트 헤더에 대한 변경 사항은 반드시 로그 Buffer에 기록 되야 한다. 따라서 단위 업무 단위로 Commit을 수행하게끔 어플리케이션을 수정하여야 한다. 만일 루프 내의 Commit은 루프 밖으로 이동하여 반복적인 Commit 수행 대신 업무 단위로 한번 만 수행하게끔 해야 한다.
만일 세션이 Connection Pool과 같은 미들티어 레이어의 영구 커넥션에서 과다한 log file sync 대기이벤트를 대기한다면, 많은 사용자에 대한 서비스 수행으로 인해 발생하는 경우이다. 해당 세션에 대한 10046 이벤트 Trace를 설정하여 어플리케이션을 점검해야 한다. Trace 파일에서 log file sync 대기이벤트를 찾아봄으로써 Commit 발생률을 확인할 수 있다. 대안으로는, 오라클 로그 마이너(Log Miner)를 사용하여 Redo Log File을 조사할 수 있다. 이것은 시스템 레벨의 Commit 발생을 확인할 수 있다.
[편집]I/O 시스템의 성능과 log file sync
Redo Log File이 위치한 I/O 시스템의 성능이 느린 경우에는 LGWR의 sync write를 수행하는 시간이 늘어나고 이로 인해 log file sync 대기시간이 증가할 수 있다. 이 경우, 서버 프로세스가 log file sync 이벤트를 대기하는 동안 LGWR는 log file parallel write 이벤트를 대기하게 된다. V$SYSTEM_EVENT뷰를 조회하여 LGWR의 평균대기시간 즉 log file parallel write이벤트의 대기 시간을 확인해보자. 평균대기시간이 10ms(1 centiseconds)가 이하이면 문제가 되지 않는다.
select *
from v$system_event
where event in ('log file sync','log file parallel write');
EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT
------------------------ ----------- -------------- ----------- ------------
log file parallel write 6411138 0 3936931 .614076783
log file sync 6597655 9819 6534755 .99046631
Commit 회수가 적절하거나, 시스템의 특성상 Commit 회수를 줄일 수 없는 상황에서 log file sync 대기가 광범위하게 나타난다면 I/O 시스템의 성능을 개선시키는 것에 대한 검토가 필요하다. 시스템 I/O처리량이 높을수록 log file sync 와log file parallel write의 평균대기시간은 향상될 수 있기 때문이다. 하지만, 어플리케이션 설계가 잘못되어 있고 Commit이 너무나 빈번하게 수행된다면 어플리케이션을 수정하지 않고는 문제를 해결할 수 없다.
일반적으로 LGWR가 log file parallel write 이벤트를 대기하는 평균시간이 높거나 전체 시스템에서 대기시간 대비 차지하는 비중이 높다면 Redo Log File이 위치한 I/O 시스템의 성능에 문제가 있다고 파악할 수 있다. 이것은 SAN(Storage Area Network)상의 데이터베이스를 광 채널(Fiber Channel)로 연결, NAS(Network Attached Storage)상의 데이터베이스를 기가비트 이더넷(Gig-E : Gigabit Ethernet)또는 Infiniband로 연결, DAS(Direct Attached Storage)상의 데이터베이스를 울트라와이드 SCSI (untrawide SCSI)또는 광 채널로 연결, 프라이빗 네트워크, 초 고속 스위치, 전용 I/O 컨트롤러, 비동기식 I/O, 로그 파일을 raw 디바이스에 위치시키고 RAID 5 대신 RAID 0 또는 RAID 0+1로 LUN을 바인딩 시키는 것과 같은 많은 방법을 포함한다.
일반적인 가이드는 Redo Log File을 가장 빠른 디바이스에 위치시키라는 것이다. 그리고 디스크 경합을 피하기 위해 서로 다른 그룹의 Redo Log File은 서로 다른 디스크에 분산시켜야 한다. Redo Log File을 데이터파일이나 컨트롤 파일과 다른 디스크에 배치시키는 것 또한 필요하다.
[편집]Redo 데이터의 양과 log file sync
Commit 수행시 Redo Log File에 기록해야 할 데이터 양을 줄이면 log file sync 대기시간 또한 줄일 수 있다. 특히 크고 긴 Transaction에서 Redo 데이터 양을 줄이게 되면 LGWR의 Background Writes 작업이 줄게 되고 자연스럽게 Redo와 관련된 경합이 해소될 수 있다. ERP나 DSS와 같이 백그라운드로 데이터를 생성하는 작업이 많은 시스템의 경우에는LGWR이 Background Writes을 많이 수행하게 되고 이로 인해 사용자 세션은 log file sync 이벤트를, LGWR는 log file parallel write 이벤트를 장시간 대기할 수 있다. LGWR의 성능 저하는 곧바로 시스템 전체의 성능 저하로 연결된다.
다행히 오라클에서는 Redo 데이터의 생성을 최소화할 수 있는 많은 방법들을 제공한다. 대량의 데이터를 생성하는 작업에서는 항상 다음과 같은 기법을 활용할 수 있는지 검토해 보아야 한다.
- Nologging 옵션을 사용할 수 있는가? Nologging 옵션을 사용하면 Redo 데이터를 극적으로 줄일 수 있다. Direct load 기능과 Create ..., Alter .. 류의 작업들은 대부분 Nologging 옵션을 제공한다. 이런 기능들을 잘 활용하면 Redo 데이터의 양을 극적으로 줄일 수 있다.
- SQL*Loader로 대량의 데이터를 적재할 때는 Direct load option을 사용한다.
- 임시작업이 필요할 때는 가능하면 임시 테이블(Temporary Table)을 사용한다. 임시 테이블을 사용하면 비록 Undo에 의한 Redo는 생성되지만 데이터에 대한 Redo는 생성되지 않는다. 따라서 Redo 데이터의 양이 전반적으로 줄어드는 효과가 있다.
- 인덱스가 있는 테이블에 대해 Direct load 작업을 수행할 때는 "1) 인덱스를 Unusable 상태로 변경 2) 데이터 생성 3) 인덱스를 Nologging 모드로 재구성" 과 같은 절차를 사용해서 인덱스에 의해 Redo가 생성되는 것을 방지한다.
- LOB 데이터의 경우 데이터의 크기가 크다면 가급적 Nologging 속성을 부여한다.
[편집]Redo Buffer의 크기와 log file sync
일반적으로 Redo Buffer의 크기가 지나치게 큰 경우에 log file sync 대기가 증가하는 경향이 있다. 커다란 Redo Buffer는 ackground writes 횟수를 감소 시키고, LGWR 프로세스의 활동성을 낮추게 되므로 Redo Buffer에는 많은 양의 Redo Entry가 저장되는 현상을 야기 시킨다. 프로세스가 Commit을 수행할 때, LGWR 프로세스는 더 많은 양의Redo Entry를 디스크에 기록해야 하므로 sync write 시간은 더 오래 소요된다. Redo Buffer 사이즈를 너무 작게 설정할 경우, 세션들은 log buffer space 대기이벤트에 대한 대기를 하게 되며, 너무 크게 설정할 경우 log file sync 대기이벤트를 대기하게 된다. 한편으로, Redo 생성이 과다한 시점(특히 로그 스위치 직후)의 Redo Buffer 공간에 대한 요구 사항을 만족하기 위해서는 커다란 Redo Buffer가 필요하다. 반면에, ackground writes횟수를 증가시키고 log file sync 대기시간을 줄이기 위해서는 작은 로그 Buffer가 필요하다.
그렇다면 Redo Buffer의 크기는 어느 정도가 적당할까? 정확한 답은 없는 것으로 보인다. 이전에는 1M 정도의 Buffer도 크다고 여겼지만, 요즘은 5M 이상의 Redo Buffer도 아무런 문제없이 많이 사용되고 있다. 일반적인 가이드는 1~5M 사이의 크기를 부여하고 시스템을 관찰하는 것이다. 만일 log file sync 대기가 증가하는 경향을 보인다면 Redo Buffer의 크기를 줄이는 것이 좋다. 또한 log buffer space 대기가 증가하는 경향을 보인다면 Redo Buffer의 크기를 늘리는 것이 일반적인 해결책이다. 대량의 Redo를 생성하는 소수의 Transaction과 짧고 잦은 Commit을 수행하는 많은 수의 Transaction으로 이루어진 하이브리드 시스템인 경우에는 이 두 개의 대기가 동시에 나타나는 경우가 많다. 이런 경우의 해결책은 _LOG_IO_SIZE 히든 파라미터를 이용하는 것이다. _LOG_IO_SIZE 파라미터는 LGWR이 Redo Buffer의 내용을 Redo Log File에 저장하는 임계치값을 나타낸다. 가령, _LOG_IO_SIZE 값이 128K라면 LGWR은 Redo Buffer가 최종 기록 이후 128K만큼 쌓이면 다시 기록을 수행하게 된다. 따라서 log buffer space 대기를 줄이기 위해 Redo Buffer의 크기를 키우고 이와 동시에 log file sync 대기를 줄이기 위해 _LOG_IO_SIZE 값을 적당히 작은 크기(가령 64K 정도)로 조정하면 된다.
적절하게 설정된 _LOG_IO_SIZE 는 2가지 장점을 동시에 제공한다. 다시 말하면, 커다란 Redo Buffer에_LOG_IO_SIZE를 작게 설정할 경우에는 background writes횟수는 증가하게 되며, 결과적으로 log file sync 대기시간은 감소한다. 하지만, 이 방법이 부하가 없는 것은 아니다. LGWR의 활동성을 증가시키게 되어 redo copy 래치와 redo writing 래치에 부하가 발생할 수 있다.
오라클 10g에서 _LOG_IO_SIZE 파라미터의 기본 설정값은 LOG_BUFFER의 1/6이다. 이는 COMPATIBLE이 10.0이상으로 설정되어 있을 때 _LOG_PARALLELISM_MAX 파라미터의 기본 설정값은 2이기 때문이다. 아래에서 보여지는 것처럼, 오라클 10g에서 _LOG_IO_SIZE의 기본 설정값은 LOG_BUFFER를 로그 블록 사이즈(LEBSZ)와 kcrfswth로 나눈 값이다.
orcl> oradebug setospid 14883
Oracle pid: 5, Unix process pid: 14883, image: oracle@aoxn1000 (LGWR)
orcl> oradebug unlimit
Statement processed.
orcl> oradebug call kcrfw_dump_interesting_data
Function returned 90F42748
orcl> oradebug tracefile_name
/orahome/admin/orcl/bdump/orcl_lgwr_14883.trc
orcl> !grep kcrfswth /orahome/admin/orcl/bdump/orcl_lgwr_14883.trc
kcrfswth = 1706
orcl> select value from v$parameter where name = 'log_buffer';
VALUE
---------------
5242880
orcl> select max(LEBSZ) from x$kccle;
MAX(LEBSZ)
----------
512
orcl> select 5242880/512/1706 from dual;
5242880/512/1706
----------------
6.00234467
[편집]Event Tip
[편집]REDO
REDO는 오라클 SGA에 있는 Redo Buffer와 Redo Log File로 이루어져 있는데 이는 Database의 복구를 목적으로 하고 있다.
이 REDO는 Database에 적용된 모든 변경사항에 대한 이력을 저장한다. 여기에 포함되는 정보는 DML, DDL, Recursive SQL에 의해 변경된 모든 Data의 이력들이며 DDL의 경우는 SQL Text도 저장된다. 그러나 nologging option을 부여한 상태에서의 Data 변경 이력과 DML SQL Text는 저장되지 않는다.
Redo Log File은 Redo Buffer의 내용을 그대로 저장하게 되는데 이 작업은 LGWR에 의해 이루어진다. Redo Buffer의 내용이 Redo Log File에 기록하는 시점은 보통 4가지 경우이다. 첫 번째는 매 3초마다 자동적으로 기록되고 두 번째는_LOG_IO_SIZE의 설정값에 이르렀을 때 이다. 이 히든 파라메터는 Redo Buffer의 사이즈에 의해 자동으로 설정되는 데 보통 LOG_BUFFER의 1/3 또는 1MB로 설정된다. 세 번째는 사용자의 Commit또는 Rollback이라는 명시적인 명령에 의해 강제적으로 기록되는 경우인데 이를 Log Force at Commit으로 부르는 경우도 있다. 이 경우 해당 Transaction과 관계된 모든 Redo 정보를 Log File에 저장하고 나서 Commit을 완료하게 된다. 마지막으로 DBWR에 의해 신호를 받았을 경우이다. 이 경우를 Write Ahead Log라고도 하는데 DBWR이 Data Buffer Block을 Disk로 기록하기 전에 Redo Buffer Log를 먼저 기록하기 때문에 발생하는 경우이다.
[편집]Sync Writes
유저에 의해 Commit 또는 Rollback에 의해 발생한 것을 Sync Writes라고 하며 그 이외의 경우는 Background Writes라고 한다. 장시간의 Transaction을 수행하면서 대량의 Redo Entry를 발생시키는 유저 프로세스는 Redo Buffer의 공간을 할당 받기 위해 LGWR를 호출하여 Background Writes 를 수행하게 한다. 이 경우 유저 프로세스는 Background Writes 의 완료를 기다리지 않기 때문에 성능 이슈는 없다.
그러나 Commit에 의해 매번 sync writes를 수행하는 경우 시스템 전체 성능에 악영향을 줄 수 있기 때문에 오라클은 가능하면 Commit 요청을 모아서 한꺼번에 Sync Writes를 수행한다. 이것을 그룹 Commit(group commits)라고 부른다. PL/SQL 블록에서 반복적으로 Commit이 이루어지거나, Recursive SQL에 의해서 Commit이 이루어지는 경우, 여러 세션에서 동시에 Commit 요청이 오는 경우 등에서 그룹 Commit 기능이 사용된다. 그룹 Commit이 사용되는 경우에는 user commits 통계 값은 Commit 명령을 호출한 회수와 동일하게 증가하지만 log file sync 대기는 한번만 발생하게 된다. 아래 테스트결과를 보면 그룹 Commit으로 인해 users commits 회수는 3회만큼 증가했지만 redo synch writes 회수와 log file sync 이벤트 대기회수는 1회만 증가했음을 확인할 수 있다.
-- Commit을 수행하기 전의 통계값 및 대기이벤트 SQL> select n.name, sum(s.value) from SQL> v$sesstat s, v$statname n SQL> where n.name like '%&stat_name%' SQL> and s.statistic# = n.statistic# SQL> and s.sid = (select sid from v$mystat where rownum = 1) SQL> group by n.name; ... user commits 11 redo synch writes 12 SQL> select event, total_waits, time_waited from v$session_event SQL> where sid = (select sid from v$mystat where rownum = 1) SQL> and event = 'log file sync'; EVENT TOTAL_WAITS TIME_WAITED ------------------------------ ----------- ----------- log file sync 8 8 -- PL/SQL 블록 내에서 3번 commit 수행 SQL> begin for idx in 1 .. 3 loop update redo_test set id = id where rownum = 1; commit; end loop; end; / -- Commit을 수행한 후의 통계값 및 대기이벤트 SQL> select n.name, sum(s.value) from SQL> v$sesstat s, v$statname n SQL> where n.name like '%&stat_name%' SQL> and s.statistic# = n.statistic# SQL> and s.sid = (select sid from v$mystat where rownum = 1) SQL> group by n.name; ... user commits 14 ? user commits는 commit 회수와 동일하게 증가 redo synch writes 13 ? redo synch writes는 "1"만 증가 SQL> select event, total_waits, time_waited from v$session_event SQL> where sid = (select sid from v$mystat where rownum = 1) SQL> and event = 'log file sync'; EVENT TOTAL_WAITS TIME_WAITED ------------------------------ ----------- ----------- log file sync 9 8
[편집]Commit
Commit은 Transaction을 구분하며 Database에서 발생한 변경 작업의 저장 여부를 오라클에 지정해 주는 역할을 한다. 만약 Commit이 제대로 수행되지 않을 경우는 PMON 등에 의해서 Rollback 처리가 이루어지게 된다. Commit은 3가지 종류로 나누어 볼 수 있는데 가장 쉬운 예가 사용자가 직접 Commit이라는 SQL문을 수행하는 경우이다. 그 밖에도 Automatic Commit과 Group Commit이 있다. Automatic Commit이란 DDL이나 Grant, Revoke와 같은 DCL문을 수행할 경우, 그리고 SQL*Plus와 같은 일부 Application에서 Exit명령으로 정상적으로 종료한 경우 자동으로 Transaction을 종료하고 내부적으로 Commit명령이 수행된다. 그러나 비정상 종료인 경우 보통 Automatic Rollback이 수행된다.Group Commit은 여러 Sync Writes를 Commit요청 때마다 수행하는 것이 아니고 한꺼번에 모아서 Sync Writes를 수행하는 것으로 이는 위의 Sync Writes를 참조 바란다.
오라클 10gR2부터 COMMIT_WRITE 명령에 의해 Redo Buffer를 Redo Log File에 기록하는 방식을 사용자가 제어할 수 있게 되었다. 이는 ALTER SESSION SET COMMIT_WRITE 또는 ALTER SYSTEM SET COMMIT_WRITE 명령으로 가능한데 이 기록 시점에 대한 값은 대기 여부와 기록 방식을 설정하게 되어 있다.
| 대기여부 | WAIT | 기존의 Commit과 같이 Redo Buffer가 Redo Log File에 기록을 완료 할 때 까지 Session은 대기함 |
| NOWAIT | Redo Buffer가 Redo Log File에 기록이 완료시 까지 대기하지 않고 다른 작업을 수행할 수 있음 | |
| 대기여부 | IMMEDIATE | Redo Log File에 쓰기 작업을 바로 바로 수행함 |
| BATCH | Redo Log File에 쓰기 작업을 Batch 형태로 몰아서 수행함 |
예) ALTER SYSTEM SET COMMIT_WRITE = NOWAIT,BATCH
User가 Commit명령을 수행하게 되면 Transaction Table에 해당 Transaction에 대한 Commit을 적용하고 나서 Commit 메시지를 Redo Buffer에 기록한다. 그 후에 Redo Buffer의 내용을 Disk에 기록하고 나서야 모든 관련된 Lock의 정보를 해제 하게 되는데 이때 주의할 것은 Redo Buffer의 모든 내용이 Redo Log File에 기록된다는 점이다.
만약 Session 1과 Session 2가 각기 다른 대상에 대해 DML을 수행한다고 가정하자. Session 1이 Row 1의 값을 2로 변경하는 작업을 하게 되면 Redo Buffer에는 Before 1, After 2라고 기록이 된다. 그리고 Session 2가 Row 5의 값을 6으로 변경하는 작업을 수행하면 Redo Buffer에는 Session 1의 작업 내용 바로 뒤에 Before 5, After 6이라고 기록이 된다. 그 이후 Session 1이 Commit을 수행하면 Commit 메시지가 Redo Buffer에 기록되고 Before 1, After 2라는 기록하는 것뿐만 아니라 Before 5, After 6, Commit이라는 기록 모두가 Redo Log File에 기록이 되고 나서 Lock을 해제하고 Commit이 완료된다는 것이다.
Commit이 발생하면 일반적으로 Data Block에 대해 Cleanout을 수행하게 된다. Cleanout이란 Transaction 정보를 갱신하고 해당 Row에 대한 lock을 해제하는 작업을 의미한다. 그러나 대량의 Block에 대해 변경이 이루어지고 이를 Commit하게 될 경우 오라클을 이 변경 사항을 기록하기 위해 일부 Block들만 Cleanout하고 나머지는 해당 Block들을 재방문 하지 않고 누군가가 이 Block을 재 방문할 것을 기대하며 그냥 놓아둔다. 이를 Fast Commit이라 한다.
오라클은 Data Block을 변경시킬 때 마다 Block Header에 해당 변경 정보를 기록한 Undo Segment Pointer를 가지고 있게 된다. Commit이 수행될 때 Cleanout되지 않는 Block들은 Undo Segment Header에 Committed라는 표시를 수행하는 것으로 작업을 완료한다. 이렇게 Fast Commit에 의해 남아있는 Data Block들은 다음에 해당 Block을 읽기 위해 오는 Session에 의해 Cleanout된다. 이것을 Delayed Block Cleanout이라 한다.
Delayed Cleanout은 Read Session이 Cleanout되지 않는 Block을 방문 하였을 때 아직 정리되지 않는 Transaction정보를 보고 해당 Block의 Before Image를 찾기 위해 Undo Segment Header를 찾아가게 된다. 그러나 이미 Undo Segment Header에는 Commit되었다는 기록이 있기 때문에 다시 해당 Block을 찾아가 Cleanout을 수행하고 Current Read를 하게 되는 것이다.
[편집]Sequence와 log file sync
Sequence를 생성할 때 NOCACHE 옵션을 주는 경우가 종종 있다. NOCACHE 속성의 시퀀스는 많은 성능 문제를 야기하는데 대표적인 경우가 row cache lock 대기를 증가시키는 것이다. 재미있게도, NOCACHE 속성의 Sequence는 log file sync 대기를 유발하는 원인이 될수도 있다. NOCACHE 속성의 Sequence에 대해서 Sequence.nextval을 호출하면 매번 Dictionary 테이블의 정보를 갱신하고 Commit을 수행해야 하기 때문이다. Sequence를 사용할 때는 Transaction의 양을 고려하여 반드시 적절한 크기의 CACHE 속성을 부여해야 한다
[편집]PROCESSES 파라미터와 log file sync
PROCESSES 파라미터 수치를 크게 설정할 경우 log file sync 대기현상이 증가하게 된다. 모든 동기화 작업(sync operation)동안, LGWR 프로세스는 어떠한 세션들이 해당 이벤트를 대기하고 있고 어떠한 세션의 Redo를 디스크로 기록해야 하는지 확인하기 위해서 프로세스의 데이터 스트럭처를 스캔해야 한다. PROCESSES 파라미터 수치를 작게 설정할 경우 log file sync 대기현상을 감소시키는데 도움이 된다. 적정한 값을 알기 위해서는 V$RESOURCE_LIMIT 뷰를 사용하면 된다. 이러한 문제는 오라클 9i R2에서 해결되었다.
[편집]Analysis Case
[편집]1. IO 성능으로 유발된 log file sync 분석 예
MaxGauge로그를 분석해 본 결과 22시경부터 발생한 I/O관련 이벤트로 인해 Active Session이 급격하게 증가함을 볼 수 있었다. 이중 log file sync도 다량 발생하고 있는데 우선적으로 User commit에 의한 log file sync를 의심해 볼 수 있으나 Commit의 추이와 log file sync 이벤트의 추이가 일치하지 않는다. 게다가 22시 35분을 전후하여 Commit의 양이 변함이 없음에도 불구하고 log file sync의 이벤트 발생은 눈에 띄게 줄어듦을 보이고 있기 때문에 Commit이 log file sync의 발생에 직접적인 원인은 아니라고 분석이 가능하다.
또한 이 시점에 DBWR 프로세스들이 Warning: lio_listio returned EAGAIN Performance degradation may be seen 에러를 겪고 있음을 감지 하였다. 이것은 Asunchronous IO를 사용하여 File에 Write를 수행할 때 발생할 수 있는 에러로lio_listio() 함수가 EAGAIN이라는 값을 반환하여 성능이 떨어질 수 있음을 경고하는 것이다. lio_listio() 함수는 IO 요청에 대해 초기화를 수행하는 함수인데 Asunchronous IO에서 이 함수를 사용한다고 한다.
그런데 이 요청 큐에 대해 시스템 리소스를 제대로 할당 받지 못하는 경우 EAGAIN을 반환하는데 이는 시스템 차원에서 허용 가능한 프로세스의 수를 넘거나 개별 사용자가 동시에 사용할 수 있는 프로세스 수를 넘을 경우인데 이 경우는 후자에 해당한다. 이는 IO를 담당하는 AIO서버의 개수의 추이를 보면 알 수 있다.
이러한 분석을 통하여 다음과 같은 해결책을 제시하여 적용하였다.
| O/S | I/O 관련 Parameter 수정 maxreqs (12288->24576) maxservers (32->64) (kproc = maxservers*cpu count) | LGWR, DBWR의 lio_listio system call 에 대한 EAGAIN 에러 발생 제거 |
| File system I/O 방식 수정 DB file이 저장된 File System 에 대해 CIO (Concurrent IO) 로 변경 | DB File들에 대한 전반적인 I/O 성능 향상 | |
| File 분산 특정 영역의 File들을 최대한 분산 | 해당 File들에 대한 I/O 대기시간 감소 | |
| Oracle | DB_KEEP_CACHE_SIZE = 3GB로 설정 후 Product 관련 테이블 캐싱 |
해당 테이블에 대한 Disk I/O 요청 감소를 통한 성능 향상 |
적용전과 적용 후에 다음과 같은 개선 효과가 나타났다.
| 항목 | 수정 전 | 수정 후 | 개선율 |
| LGWR, DBWR의 lio_listio system call 에 대한 EAGAIN 에러 발생빈도 | LGWR 프로세스 : 두 달 동안 총 143,379회 발생(일 평균 2,560회 발생) | 발생하지 않음 | 100% |
| DBWR 프로세스 : 두 달 동안 총 135,542회 발생 (일 평균 2,336회 발생) | 발생하지 않음 | 100% |
Log file sync 대기 이벤트의 경우 가장 직접적인 원인은 바로 사용자에 의한 의도적인 Commit이 집중될 때 발생한다고는 하지만 실제 사이트에 나가보면 이러한 경우가 발견되는 것은 극히 드물고 오히려 그 밖의 경우로 인해 발생하는 사례가 더 많기 때문에 log file sync는 다루기 쉽지 않은 이벤트 중에 하나이다. 이러한 점에서 이 분석 내용은 log file sync의 아주 좋은 사례라 생각한다.
[편집]2. 동시접속 급증에 의한 log file sync 대기 과다 분석 예
오라클 프로세스의 접속이 순간적으로 급증할 경우, 접속 시에 필요한 리소스 확보 및 recursive SQL 수행 후의 내부 Commit 수행으로 인한 순간적인 서비스 중단이 발생하게 된다. OLTP 및 WEB 환경에서는 이러한 순간적인 서비스 장애 역시 비즈니스 가동률을 떨어뜨리는 요소임에 틀림없다. Oracle DBMS의 성능진단/분석 툴인 MaxGauge(맥스게이지)를 활용하여, 동시 접속 과다에 의해 발생한 성능저하 문제의 원인을 규명해 보고자 한다.
[편집]성능저하구간의 확인
성능문제가 발생한 인스턴스에서 수집된 가동이력로그로부터 일간 추이그래프를 확인해 보면, CPU사용률에는 뚜렷한 변화가 없어 보이지만, 16시47분에 Active Session이 급증하였고 16시46분에 ｢Wait｣ 수치가 급증하는 것을 쉽게 확인할 수 있다.
■CPU사용률의 추이그래프 
■Active Session수의 추이그래프 
■Wait Events의 추이그래프（Wait Time） 
[편집]Wait Events의 검출 및 분석
Active Session의 급증으로 인한 성능저하（Performance Slow-Down）의 원인을 규명하기 위해, 문제시점(16시46분 및 16시47분)의 Wait Events 발생내용을 확인해 본다. 
｢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 대기이벤트의 급격한 발생과 연관이 있음을 추측할 수 있다.
실제로, 같은 시점의 세션 상세데이터를 표시하는 ｢세션 Grid｣ 화면에서도, log file sync 대기이벤트가 많이 발생해 있음을 확인할 수 있으며, 세션들의 접속시간이 대부분 동 시간대임을 확인할 수 있다.
[편집]Wait Event(log file sync)발생원인의 조사
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의 추이를 확인해 본다.
추이그래프의 분석결과, 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 임 |
[편집]세션 및 SQL의 분석을 통한 문제원인의 규명
log file sync 이벤트 대기가 극심했던 16시46분~16시47분 구간에서 log file sync를 대기하는 세션을 검색해 본 결과, 일반 프로그램에서 Logon 처리를 위해 SYS Schema로 recursive sql (SEQ$ Update)를 수행하고 있는 것을 확인할 수 있다.
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 지표의 수치에 반영되지 않게 된다.
[편집]결론 및 해결 방안
동시접속 과다시점에 log file sync 대기에 의한 Active session의 급증 →
SYS.AUDSES$ 시퀀스의 CACHE Size가 작아서 SYS.SEQ$ 를 UPDATE하는 내부 SQL 수행 및 COMMIT 과다
→ SYS.AUDSES$ 시퀀스의 CACHE 값을 크게 조정하여 해결
SQL> alter sequence sys.audses$ cache 10000;
[편집]Redo log File 위치에 의한 병목 현상
오라클은 특별한 경우를 제외하면, DML에 의해 생긴 모든 변화에 대해서 Redo Data를 생성한다. DML을 수행하면, 변경 내용은 버퍼 캐시에 저장되기 전에 먼저 Redo Buffer에 저장되며, 버퍼캐시의 더티 버퍼를 데이터파일에 기록하기 전에, 해당되는 Redo Data를 Redo Buffer로부터 Redo Log 파일로 기록한다. 이렇게 Writing이 빈번한 Redo Log File은 빠르게 작업이 이루어져야 한다.
다음은 Redo Log File과 Temp File이 같은 디스크에 위치하여 I/O를 처리하지 못해 문제가 된 경우이다.
아래의 그래프를 참조해보면, 평이하게 유지되고 있던 Active Session이 급상승하는 구간이 발생한다. 그리고 Active Session 그래프의 추이는 Direct Path Read/Write, Log File Sync, DB File Scattered Read, DB File Parallel Write 이벤트의 추이와도 일치함을 확인할 수 있다.
Direct Path read, Direct Path write 이벤트는 Temp 파일의 I/O 와 관련된 이벤트로써 Sorting 작업이나 Hash Join 으로 수행되는 SQL의 수행 시 발생한다.
Log File Sync는 LGWR가 Redo Log의 내용을 Redo Log File로 write 시 서버 프로세스가 LGWR의 작업이 끝날 때까지 기다릴 때 발생하는 이벤트이다.
DB File Parallel Write 이벤트는 DBWR가 더티버퍼를 Data File로 Write 시에 발생하는 이벤트이다.
Peak 시점의 세션의 현황을 확인해 보면, 전체적으로 Logical/Physical Reads가 0인 경우가 대부분이며, 거의 I/O가 이루어지지 않고 있음을 알 수 있다.
① LGWR는 Log File Parallel Write 이벤트를 대기하고 있다. 이 경우는 현재 기록해야할 Redo의 양이 많은 경우, Redo Log가 위치한 디스크의 I/O가 느린 경우, Redo Buffer의 크기가 큰 경우를 생각해 볼 수 있다. 위의 시스템은 Log_buffer의 크기가 1M로 일반적인 크기를 가지고 있다.
② Log File Sync 이벤트를 대기하는 세션은 DML문들을 수행하고 있다. DBWR는 DB File Parallel Write 이벤트를 대기하며, 이 경우는 체크포인트의 발생 시 버퍼캐시로부터 더티버퍼 를 내려 적는 작업을 하는 동안에 대기하는 것이다.
③ Direct Path Read/Write 이벤트를 대기하는 세션은 Sorting 작업으로 인해 발생하고 있다.
전반적으로 I/O의 속도가 느려서 문제가 발생되고 있다.
이 경우, 애플리케이션 즉 SQL의 튜닝을 고려해 볼 수 있고 기본적으로 시스템 I/O에 대하여 점검해 볼 필요가 있다. 각 파일의 위치는 v$datafile, v$logfile, v$tempfile 뷰를 통하여 확인해 본다.
위의 사례는 TEMP 파일과 REDO LOG FILE이 같은 위치에 위치하였기 때문에 변경 작업이 집중되는 시간에 경합이 발생하였다.
특히 REDO Log 파일은 Writing이 빈번하므로 가장 빠른 디바이스에 위치하여야 하며, 디스크의 경합을 피하기 위해 각각의 REDO Log 파일들은 서로 다른 그룹의 디스크에 분산시켜야 한다. 또한, REDO Log 파일은 데이터 파일이나 TEMP 파일, SYSTEM 파일과 다른 디스크에 배치시켜야 한다.
'참고글 및 문제해결 > 관련, 참고글' 카테고리의 다른 글
| VI에디터로 각줄의 처음 5글자 지우기(패턴에 관계없이) (0) | 2012.02.22 |
|---|---|
| 10g to 11g Upgrade (3) | 2012.02.21 |
| logmnr 간단명령어 (0) | 2012.02.08 |
| 3D업종을 그나마 2.5D로 바꿔주는 자동 script, 명령어들 (0) | 2012.02.08 |
| difference between ALTER SYSTEM and ALTER DATABASE (0) | 2012.02.07 |