LGWR 대기에 따른 원인 분석 및 튜닝

1. LGWR 기록 지연 현상

 - Disk I/O 지연으로 오라클이 대기하는 경우 발생하는 이벤트 세가지중 하나.

 - 백그라운드 프로세스의 대기 이벤트, log file parallel write(로그 파일에 로그 기록)의 시간이 길어짐.

 - 서버 프로세스의 커밋을 기다리는 이벤트, log file sync(LGWR에 기록을 요청하고 회신을 기다림)의 시간이 길어짐.


2. DB의 성능과 디스크I/O

 - 우선 OS성능과 I/O성능은 별개임을 알아야 한다.

 - I/O성능은 단순하게 분석 할 수 없으며, 여러가지 상황을 고려 해야한다.

 - 디스크는 용량이 커지다보니 사용되는 디스크의 숫자는 줄어들고 있으나, IOPS(1초당 IO횟수)는 향상되지 않아, RDBMS의 관점에서 물리적 I/O는 거의 향상되지 않는다. 디스크의 개수가 줄어들다보니 병행액세스를 이용한 I/O성능을 향상하지 못하고, 사이즈당 I/O성능도 떨어지게 된다.

 - RDBMS에서 디스크에 기록할때, OS의 버퍼캐쉬, 스토리지의 캐쉬, 디스크의 캐시 순으로 기록한다. 그렇기 때문에 OS나 스토리지, 디스크의 캐시 성능에 의해서도 속도가 좌우되며, I/O의 구조상 오라클에 가까운 계층에서 캐시에 히트할수록 고속으로 처리한다.

 - I/O에서 특히 주의 하지않으면 안되는 것이 병렬도인데, 처리할 때 병렬도가 높아 순간적으로 큐가 생겼다가 사라짐을 반복해서 응답시간이 나빠지는 경우가 있다. 

 - I/O지연이 발생하는 것은 오라클에서도 알수 있지만, OS에서도 반드시 정보를 수집해야 한다. 세션수가 많거나, 대기시간이 길거나, 응답시간이 짧아도 처리량은 동일하기 때문에 RDBMS의 I/O는 인큐가 쌓여 대기시간이 늘어나도, 실제 OS에서는 I/O가 많지 않다고 나오는 경우도 있다.


3. I/O 성능의 판단

 - AWR 또는 Statspack, OS의 sar, iostat 같은 명령어를 사용하여 분석한다.

 - log file parallel write의 경우 같은 이벤트가 v$session_wait에 반복되어 표시되므로, P1,P2,P3가 같은지 확인해서 대기 여부를 판단해야 한다.

 - 부하가 없던 시간대의 응답시간에 비해 크게 나빠지지 않았는가 여부를 확인해야 한다.

  

4. LGWR의 대기 원인 분석

 - AWR이나 Statspack을 통해 LGWR의 대기 이벤트가 어디에서 부터 발생하는지 찾아야 한다.

 - 다음은 Statspack의 60분간의 top 5 time Events 이다.

  

  Top 5 Timed Events

  ~~~~~~~~~~~~~~~~~~                                       % Total

  Event                        Waits          Time (s) Ela Time

  --------------------------- ------------    -------- --------

  log file sync                1,350,499      27,021    50.04

  db file sequential read      1,299,154      13,633    25.25

  CPU time                                     7,034    13.03

  io done                      3,487,217       3,225     5.97

  latch free                     115,471       1,325     2.45

  

  Statspack은 1800초 가량 돌면서, 8 CPU에서 거의 14,400 CPU seconds를 사용 할 수 있다.

  이 서버안에 하나의 DB만 존재한다면, CPU의 사용량은 7034/14,400 : 50% 이다. 

  (statspack CPU Time/total CPU time)

  또 한, 60분간 log file sync가 27021 초의 대기시간을 가졌고, 27021/3600 = 7.5 평균 7.5프로세스들이 log file sync 이벤트를 발생했다. 이것은 중심이 되는 병목현상임을 나타낸다.

  

  만약에 SID 3이 LGWR를 발생했다면,

  

  select sid, event, time_waited, time_waited_micro

  from v$session_event where sid=3 order by 3

  SQL> /

  

     SID EVENT                          TIME_WAITED TIME_WAITED_MICRO

  ------ ------------------------------ ----------- -----------------

  ..

       3 control file sequential read        237848  2378480750

       3 enqueue                             417032  4170323279

       3 control file parallel write         706539  7065393146

       3 log file parallel write             768628  7686282956

       3 io done                           40822748  4.0823E+11

       3 rdbms ipc message                208478598  2.0848E+12

  

   rdbms ipc message가 가장 높게 나타나지만 일반적으로 무시할수있는 이벤트이고, 

   그 다음으로 높게 나타난 io done의 경우, LGWR의 I/O call complete와 LGWR의 기록이 동기식 기록를 하고난 후의 비동기식 I/O요청이다.

   oracle session snapper.sql 을 이용하면 SID 3 세션의 1초동안 일어난 LGWR을 확인할수 있다.

   

   ------------------------------------------------------------------

   SID, SNAPSHOT START  ,SEC, TYPE, STATISTIC            ,    DELTA,

   ------------------------------------------------------------------

   3, 20080513 11:44:32,   1, STAT, messages sent        ,        9,

   3, 20080513 11:44:32,   1, STAT, messages received    ,      153,

   3, 20080513 11:44:32,   1, STAT, redo wastage         ,    39648,

   3, 20080513 11:44:32,   1, STAT, redo writes          ,      152,

   3, 20080513 11:44:32,   1, STAT, redo blocks written  ,     1892,

   3, 20080513 11:44:32,   1, STAT, redo write time      ,       82,

   3, 20080513 11:44:32,   1, WAIT, rdbms ipc message    ,   169504,

   3, 20080513 11:44:32,   1, WAIT, io done              ,   813238,

   3, 20080513 11:44:32,   1, WAIT, log file parallel write ,  5421,

   3, 20080513 11:44:32,   1, WAIT, LGWR wait for redo copy ,     1,

   

   아니면 Level 12의 10046 trace를 통해 확인 할 수 있다.

   

   WAIT #0: nam='rdbms ipc message' ela= 7604 p1=223 p2=0 p3=0

   WAIT #0: nam='log file parallel write' ela= 35 p1=2 p2=16 p3=2

   WAIT #0: nam='io done' ela= 0 p1=0 p2=0 p3=0

   WAIT #0: nam='io done' ela= 639 p1=0 p2=0 p3=0

   WAIT #0: nam='io done' ela= 0 p1=0 p2=0 p3=0

   WAIT #0: nam='io done' ela= 605 p1=0 p2=0 p3=0

   WAIT #0: nam='io done' ela= 1 p1=0 p2=0 p3=0

   WAIT #0: nam='io done' ela= 366 p1=0 p2=0 p3=0

   

   다음은 Statspack의 특정 컬럼만을 조회한 항목이다.

   

   Statistic                             Total     per Second

   ------------------------------- ----------- --------------

   redo blocks written                 230,881        2,998.5

   redo buffer allocation retries            0            0.0

   redo entries                        285,803        3,711.7

   redo log space requests                   0            0.0

   redo log space wait time                  0            0.0

   redo ordering marks                       0            0.0

   redo size                       109,737,304    1,425,159.8

   redo synch time                      40,744          529.1

   redo synch writes                    38,141          495.3

   redo wastage                      5,159,124       67,001.6

   redo write time                       6,226           80.9

   redo writer latching time                 4            0.1

   user calls                          433,717        5,632.7

   user commits                         38,135          495.3

   user rollbacks                            1            0.0

   workarea executions - multipass           0            0.0

   

   1) 5,632 user calls / 495.3 user commits 의 값으로 초당 실행시간 평균을 구할 수 있다.

   2) LGWR에 의해 3000 redo block 을 썼다는 걸 알수 있는데, 솔라리스처럼 1block에 512bytes라면 초당 1.5mb/s 인것이다.

   3) redo가 1.4mb/s로 갱신 된다면 16mbps에 근접한다.

   4) 3000 redo block에서 38,155 commit이 일어났다.

   

   위의 redo 사이즈는 일반적으로 작은 사이즈가 아니지만, 초당 500 commit을 처리하기 위해서는 더 커야한다.

   

   적절한 사이즈의 redo 인가 확인 한 후, 다음으로 고려해야 할 사항은 CPU에 의한 LGWR 대기 현상이다.

   커밋 빈도 확인을 하고, 높다면 foreground 프로세스에서 일어나는 log file sync 이벤트만을 찾아 OS에서 LGWR의 CPU사용량을 체크한다.

   

   그다음은 아주 적게 발생하는 것중 하나인데, 인스턴스 프리징현상이 있는 경우 v$sysstat을 20초 간격으로 캡쳐하고, Oracle-supplied tool, LTOM을 이용하여 iostat를 캡쳐 한다.


   23-MAR-2007-04:29:43:Redo blocks written:1564176614:Delta: 8253

   23-MAR-2007-04:30:14:Redo blocks written:1564176614:Delta:    0

   23-MAR-2007-04:30:44:Redo blocks written:1564205771:Delta:29157   

  

   위와 같이 Commit 처리량이나, redo 사이즈 CPU사용량에 영향이 없음에도 log file parallel write, log file sync 가 크게 나타난다면 하드웨어의 I/O문제라고 파악 할 수 있다.

   

   r/s  w/s kr/s kw/s wait actv wsvc_t asvc_t %w  %b device

   0.0  0.0  0.0  0.0  0.0  1.0    0.0    0.0  0 100 d6

   0.0  0.0  0.0  0.0  0.0  1.0    0.0    0.0  0 100 d2

   0.0  0.0  0.0  0.0  0.0  1.0    0.0    0.0  0 100 d1

   0.0  0.0  0.0  0.0  0.0  9.0    0.0    0.0  0 100 d0

   0.0  0.0  0.0  0.0  0.0  3.0    0.0    0.0  0 100 d13

   0.0  2.0  0.0 24.0  0.0  2.0    0.0 1000.7  0 100 d12

   0.0  0.0  0.0  0.0  0.0  1.0    0.0    0.0  0 100 d11

  

   %b는 I/O가 디스크에 의존한 %를 알려주는데 요즘엔 디스크의 여러 이유로 인해 비지율을 전적으로 신뢰 할 수 없다.

      

   r/s     reads per second

   w/s     writes per second

   Kr/s    kilobytes read per second

   Kw/s    kilobytes written per second

   wait    average number of transactions waiting for service

           (queue length)

   actv    average number of transactions  actively  being serviced

           (removed  from  the queue but not yet completed)

   svc_t   average service time, in milliseconds

   %w      percent of time there are transactions  waiting for service

           (queue non-empty)

   %b      percent of time the disk is busy  (transactions in progress)

   

   wsvc_t  average service time in wait queue, in milliseconds

   asvc_t  average service time active transactions, inmilliseconds


   I/O를 체크했을때 LGWR이 발생할 당시 I/O의 속도가 15ms 보다 크게 나온다면 디스크 속도가 떨어진다고 할 수 있다.

   I/O자체가 늦어 LGWR에 대기가 발생하는 경우는 I/O 대역폭을 올려 해결 하는 수 밖에 없다.

   OS와 스토리지 간의 지연을 찾거나, 그밖의 디스크I/O문제, 여러 상황을 고려하고 문제를 풀어나가야 한다.

   스토리지 cache의 히트율이나, OS버퍼 cache의 영향도 고려 해야 하기 때문에 단순히 RDBMS 엔지니어 혼자 판단하기는 쉽지 않다. 

   

   

Log file sync check.sql

oracle session snapper.sql


  1. 안녕하세요

    만나서 반갑습니다

    안녕하세요

    만나서 반갑습니다

티스토리 툴바