버퍼 I/O vs 직접 I/O 환경에서의 오라클 Logwriter 분석

소개 / 동기

SAP 과 Oracle 은 이미 문제 진단 및 퍼포먼스 이슈를 다룰 수 있는 강력한 툴들을 제공하고 있습니다. 그와는 별개로 DTrace 는 시스템에 대한 무한한 접근성을 제공 합니다. 그러므로 필자는 DTrace 를 SAP/Oracle 환경에서 사용하는 케이스에 대한 시리즈의 글을 작성하기로 결정하였습니다. 이미 작성해 놓은 Oracle 와 I/O 에 관한 글이 있기 때문에 일단 저는 이것을 DTrace 의 관련 글의 시작점으로 삼을 생각입니다:

비록 버퍼 I/O 대신에 직접 I/O 를 통해서 파일에 접근 하는 것이 베스트프랙티스로 여겨지고 있지만, 여전히 많은 분들이 이러한 조언을 따르지 않고 있습니다. 고객은 보통 버퍼 I/O 가 훨씬 좋고 / 빠르다고 알고 있을 수도 있고 혹은 10.2.0.2 와 10.2.0.3 (후자는 SAP 환경에서 지원되지 않음) 에 오라클 버그 5752399 에 영향을 받아서일 수도 있습니다.

배경

오라클 데이타파일에 대한 버퍼 I/O 접근이 직접 I/O 보다 좀 더 나은 퍼포먼스를 제공하는 몇몇 상황들이 있습니다. 어떠한 경우에서든지 온라인 리두로그 파일 시스템은 반드시 직접 I/O 로 설정되어야 합니다. 이 글은 해당 주제에 대한 통찰력을 DTrace 를 통해서 드리려고 합니다.
참고:
테스트 환경은 오라클 10.2.0.1 을 'forcedirectio' 마운트 옵션을 이용하여 사용하였습니다. 대부분의 경우에 오라클 레벨의 파라미터 'filesystemio_options' 을 통해서 직접 I/O 를 활성화 하는 것을 추천 드립니다. 이것은 다른 어플리케이션 / 유틸리티 (예를 들어 백업 툴 같은) 이 파일시스템 캐시의 이득을 얻을 수 있도록 합니다.

접근

테스트 시나리오는 오라클 10g 데이타베이스 (10.2.0.1) 를 사용하여, 특히 imp 유틸리티를 약 100만 레코드가 존재하는 덤프 파일과 함께 사용합니다. 각각의 테스트 후에, 해당되는 테이블은 버려지고, 체크포인트가 수행됩니다. 직접 및 버퍼 I/O 를 바꾸기 위해서 각각의 테스트 마다 마운트 옵션이 변경될 것입니다 (remount 를 통한 온라인 작업). 이 과정은 커밋에 대한 빈도와 커밋 사이즈(imp parfile 설정을 통한), 그리고 아주 안정적인 결과(재연가능한) 를 얻을 수 있는 제어권을 가질 수 있도록 합니다. 저희는 전체 실행시간만 재는 것이 아니라 DTrace 스크립트를 통해서 I/O 와 ufs 내부를 들여다 볼 것입니다.

buffer=1024
commit=Y
file=my_sales.dump
rows=y

이 파라미터파일은 imp 유틸리티가 자주 커밋을 수행하고 각각의 커밋은 오직 소량의 데이타만을 쓰도록 합니다.

리두로그를 'noforcedirectio' 로 마운트 하여 임포트 합니다:

Import terminated successfully without warnings.
 
real        2:24.41
user          11.04
sys            1.66


리두로그를 'forcedirectio' 로 마운트 하여 임포트 합니다:

Import terminated successfully without warnings.
 
real        1:48.09
user          11.03
sys            1.62

결과로 봤을때 'forcedirectio' 를 사용함으로써 평균 약 36 초 (~30%) 정도의 이득을 얻었음을 볼 수 있습니다. 먼저 I/O 를 살펴 봅시다. Brendan Gregg 의 DTrace 툴킷 은 'iosnoop.sh' 이라고 하는 스크립트를 제공합니다. LogWriter 프로세스(lgwr) 을 추적하면 다음과 같은 정보를 얻을 수 있습니다:

forcedirectio:

./iosnoop.sh -aD -p 4162
STRTIME              DEVICE  MAJ MIN DELTA        UID   PID D    BLOCK   SIZE                     PATHNAME ARGS
2009 May 27 11:42:56 sd0      32   4 3772         215  4162 W 22293311    512                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3874         215  4162 W 22293312   2560                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3600         215  4162 W 22293317   3072                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3733         215  4162 W 22293323   2560                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3814         215  4162 W 22293328    512                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3322         215  4162 W 22293329   3072                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3193         215  4162 W 22293335   3072                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3730         215  4162 W 22293341   1536                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3813         215  4162 W 22293344   1536                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3615         215  4162 W 22293347   3072                       <none> ora_lgwr_DEM\0
2009 May 27 11:42:56 sd0      32   4 3556         215  4162 W 22293353   3072                       <none> ora_lgwr_DEM\0

임포트된 테이블은 VARCHAR 필드들을 가지고 있습니다. 그러므로 레코드의 길이는 다양할 것입니다. 모든 I/O 의 사이즈는 복수개의 512 바이트 블럭이고 상당히 작습니다 - 항상 4KB 보다 작습니다. 전체적으로 별로 놀라운 것은 없습니다: 데이타의 양에 따라 서로 다른 사이즈를 로그버퍼에서 리두로그 파일로 순차적으로 쓰는 것입니다. 오라클의 통계를 살펴 봅시다:

Event		
Statistic				Total		per Second	per Trans
redo size 				48,438,904 	267,760.27 	2,734.50
redo synch time 			7,384 		40.82 		0.42
redo synch writes 			17,864 	        98.75 		1.01
redo wastage 				5,559,348 	30,730.93 	313.84
redo write time 			7,381 		40.80 		0.42
redo writer latching time 		0 		0.00 		0.00
redo writes 				17,734 	        98.03 		1.00

좋습니다. 오라클은 평균 lgwr I/O 를 2731 바이트 (redo size / redo writes) 로 평균 서비스타임 4.2ms 에 처리 하였음을 보여주고 있습니다. 참고: v$sysstat 에서 나오는 시간들은 ms 가 아니라 cs 단위로 측정 됩니다!
이제 동일한 작업을 'noforcedirectio' 마운트 옵션으로 수행해 봅시다.
noforcedirectio:

./iosnoop.sh -aD -p 4162
STRTIME              DEVICE  MAJ MIN DELTA        UID   PID D    BLOCK   SIZE                     PATHNAME ARGS
2009 May 27 02:09:41 sd0      32   4 5848         215  4162 W 21946960  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 3667         215  4162 W 21946960  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 3690         215  4162 W 21946960  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 3650         215  4162 W 21946960  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 22498        215  4162 R 21949024 1048576 /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 23045        215  4162 W 21946976  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:41 sd0      32   4 3468         215  4162 W 21946976  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
					:
					:
2009 May 27 02:09:44 sd0      32   4 5855         215  4162 W 21949008  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:44 sd0      32   4 3333         215  4162 W 21949008  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:44 sd0      32   4 3690         215  4162 W 21949008  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:44 sd0      32   4 22519        215  4162 R 21951072 1048576 /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:44 sd0      32   4 23070        215  4162 W 21949024  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
2009 May 27 02:09:44 sd0      32   4 3675         215  4162 W 21949024  8192   /slice4/redolog/redo01.log ora_lgwr_DEM\0
					:
					:

두가지 흥미로운 관찰점이 있습니다:
LGWR 는 반복적으로 동일한 블럭을 씁니다! 저희의 테스트케이스에서 오라클은 아주 작은 커밋을 하고 있음을 알고 있는 상태 입니다. 만약 버퍼 I/O 가 사용되면 비록 512 바이트 만이 변경되었더라도 전체 OS 블럭이 매 커밋마다 쓰여져야 합니다. 이것은 이후에 쓰기 작업이 동일한 블럭을 디스크에 쓰도록 유도 합니다.
저희들은 자주 로그파일에 대한 대용량의 읽기 작업(1MB) 를 볼 수 있습니다. 블럭 주소를 살펴 보면 이것은, 프리페칭(prefetching) 과 유사해 보입니다. prefetched 데이타 (1MB) 의 직전에 8KB 블럭에 도달하면 또다른 1MB 가 읽힙니다. 데이타베이스 내부 측면으로 한번 살펴 봅시다:

Event		
Statistic				Total		per Second	per Trans
redo size 				50,214,248 	293,724.43 	2,832.48
redo synch time 			10,993 	   	64.30 		0.62
redo synch writes 			17,870 		104.53 		1.01
redo wastage 				5,609,796 	32,814.08 	316.44
redo write time 			10,999 		64.34 		0.62
redo writer latching time 		0 		0.00 		0.00
redo writes 				17,728 		103.70 		1.00

몇몇 분들은 '리두 사이즈' 가 이전에 저희가 얘기했던 대로 버퍼 I/O 의 쓰기 오버헤드 때문에 훨씬 클 것으로 예상했을 것입니다. 그러나 기억하시기 바랍니다:이것은 오라클의 관점입니다. 작은 데이타 블럭의 전체를 8KB 파일시스템 블럭으로 채우는 것은 UFS 레이어에서 일어나고 오라클에서 일어나지는 않습니다! 그러므로 저희들은 거의 동일한 리두 데이타(리두 사이즈) 의 양을 볼 수 있고, 또한 거의 동일한 숫자의 리두 쓰기도 확인할 수 있습니다. 그러나 리두 쓰기 시간 (73.8s vs 110s) 에서는 엄청난 차이를 발견할 수 있는데 이것은 두 테스트의 전체 런타임에 해당 합니다.
이제 두개의 시나리오의 내부에 어떠한 일이 발생하는지에 대해서 좀 더 자세히 알아 봅시다. 작은 DTrace 스크립트의 커널 프로파일링이 이데 관련한 정보를 제공할 수 있습니다:

 
#!/usr/sbin/dtrace -s
#pragma D option flowindent
 
fbt:ufs::entry
/pid == $1/
{
        self->ts[probefunc] = timestamp;
}
 
fbt:ufs::return 
/pid == $1 && self->ts[probefunc] != 0/
{ 
        self->duration[probefunc] = (timestamp - self->ts[probefunc])/1000;
} 
 
fbt:ufs::
/pid == $1/
{
        trace(self->duration[probefunc]);
        self->duration[probefunc] = 0;
}

스크립트에 하나의 파라미터가 전달되는데 이것은 오라클 LGWR 프로세스의 pid 입니다. 스크립트는 (function boundary tracing) 프로바이더를 이용합니다. fbt 는 거의 대부분의 솔라리스 커널 함수의 진입 및 리턴 프로브를 제공 합니다. 이번에 저희는 특히 UFS 모듈에 관심이 있습니다. 기본적으로 저희는 진입 및 리턴에 걸리는 시간을 추적합니다. 추가적으로 flowindent 옵션을 이용해서 좀더 읽기 쉬운 출력을 생성하고 이를 통해서 호출 구조에 대한 좀 더 명확한 그림을 제공합니다.
직접 I/O 는 비교적 간단한 코드패스를 가지고 있음을 보실 수 있습니다. 저희들은 각각의 호출에 대한 코드 레벨 까지 알아보지는 않을 것입니다. 그러나 호출의 횟수를 통해서 무슨일이 벌어지고 있는지는 알 수 있을 것입니다. 일단 제일 처음 시작부분에 'ufs_write' 호출이 있습니다.

forcedirectio (숫자들은 마이크로세컨드임):

root@ontario1:/opt/dtrace # ./ufs3.d 4162
 
  1          -> ufs_write                                     0
  1            -> ufs_check_rewrite                           0
  1              -> bmap_has_holes                            0
  1              <- bmap_has_holes                           28
  1            <- ufs_check_rewrite                          94
  1            -> ufs_lockfs_begin                            0
  1              -> ufs_lockfs_is_under_rawlockfs             0
  1              <- ufs_lockfs_is_under_rawlockfs            47
  1            <- ufs_lockfs_begin                          135
  1            -> ufs_directio_write                          0
  1              -> bmap_read                                 0
  1                -> findextent                              0
  1                <- findextent                             23
  1              <- bmap_read                                75
  1              -> directio_start                            0
  1              <- directio_start                           67
  1              -> directio_wait                             0
  1                -> directio_wait_one                       0
  1                <- directio_wait_one                    2914
  1              <- directio_wait                          2981
  1            <- ufs_directio_write                       3259
  1            -> ufs_itimes_nolock                           0
  1              -> ufs_imark                                 0
  1              <- ufs_imark                                21
  1            <- ufs_itimes_nolock                          78
  1            -> ufs_lockfs_end                              0
  1              -> ufs_lockfs_top_vop_return                 0
  1              <- ufs_lockfs_top_vop_return                42
  1            <- ufs_lockfs_end                            120
  1          <- ufs_write                                  3894


noforcedirectio (숫자들은 마이크로세컨드임):

  0  -> ufs_write                                             0
  0    -> ufs_check_rewrite                                   0
  0      -> bmap_has_holes                                    0
  0      <- bmap_has_holes                                   36
  0    <- ufs_check_rewrite                                 119
  0    -> ufs_lockfs_begin                                    0
  0      -> ufs_lockfs_is_under_rawlockfs                     0
  0      <- ufs_lockfs_is_under_rawlockfs                    59
  0    <- ufs_lockfs_begin                                  170
  0    -> ufs_itimes_nolock                                   0
  0      -> ufs_imark                                         0
  0      <- ufs_imark                                        29
  0    <- ufs_itimes_nolock                                 102
  0    -> wrip                                                0
  0      -> ufs_indirblk_sync                                 0
  0      <- ufs_indirblk_sync                                41
  0      -> ufs_getpage                                       0
  0        -> ufs_lockfs_begin_getpage                        0
  0        <- ufs_lockfs_begin_getpage                       52
  0        -> bmap_has_holes                                  0
  0        <- bmap_has_holes                                 36
  0      <- ufs_getpage                                     227
  0      -> ufs_putpage                                       0
  0      <- ufs_putpage                                      32
  0      -> ufs_putpages                                      0
  0        -> ufs_putapage                                    0
  0          -> bmap_read                                     0
  0            -> findextent                                  0
  0            <- findextent                                 34
  0          <- bmap_read                                    99
  0          -> lufs_write_strategy                           0
  0            -> deltamap_remove                             0
  0            <- deltamap_remove                            38
  0          <- lufs_write_strategy                         171
  0        <- ufs_putapage                                 4877
  0      <- ufs_putpages                                   4955
  0      -> ufs_check_rewrite                                 0
  0      <- ufs_check_rewrite                                41
  0      -> top_delta                                         0
  0        -> deltamap_add                                    0
  0        <- deltamap_add                                   33
  0      <- top_delta                                        98
  0      -> ufs_itimes_nolock                                 0
  0        -> ufs_imark                                       0
  0        <- ufs_imark                                      28
  0      <- ufs_itimes_nolock                               101
  0    <- wrip                                             5833
  0    -> ufs_lockfs_end                                      0
  0      -> ufs_lockfs_top_vop_return                         0
  0      <- ufs_lockfs_top_vop_return                        53
  0    <- ufs_lockfs_end                                    152
  0  <- ufs_write                                          6614

여러분이 오라클 statspack 혹은 AWR 리포트 (혹은 오라클 엔터프라이즈 메니저 diagnostics pack 에 대한 라이센스가 없는 경우에) 에 대한 접근 권한이 없을 경우에는 다음의 스크립트를 수행함으로써 LGWR 의 평균 리두 쓰기 시간에 대한 아이디어를 얻으실 수 있습니다:

 
#!/usr/sbin/dtrace -s
 
fbt:ufs:ufs_write:entry 
/pid == $1/
{ 
        self->ts = timestamp; 
} 
 
fbt:ufs:ufs_write:return 
/self->ts != 0 && pid == $1/ 
{ 
        @time[execname] = avg(timestamp - self->ts); 
        self->ts = 0; 
} 

이 스크립트는 집합(@time[]) 을 사용해서 리턴 프로브로 진입할때 까지의 걸리는 평균 시간을 계산합니다.

여러분은 다음의 명령으로 알아낼 수 있는 오라클 LGWR 의 pid 를 스크립트 실행시에 전달해 주어야 합니다

root@ontario1:/opt/dtrace # ps -ef | grep lgwr
  oradem  4162     1   0 02:01:29 ?           1:50 ora_lgwr_DEM
    root  9747  5417   0 15:53:39 pts/4       0:00 grep lgwr

테스트 임포트 작업이 끝난 후에 CTRL-c 를 누르면 다음과 같은 결과를 나노세컨드 단위로 보실 수 있습니다:

forcedirectio

root@ontario1:/opt/dtrace # ./avg_redo_write.d 4162
dtrace: script './avg_redo_write.d' matched 2 probes
^C
 
  oracle                                                      3932139


noforcedirectio

root@ontario1:/opt/dtrace # ./avg_redo_write.d 4162
dtrace: script './avg_redo_write.d' matched 2 probes
^C
 
  oracle                                                      5893665

이 스크립트를 통해서 LGWR ufs_write 호출의 평균 응답시간은 직접 I/O 의 경우 ~4ms, 버퍼 I/O 의 경우 5.9ms 임을 확인하실 수 있습니다. 이러한 결과는 AWR 리포트에 포함되어 있습니다.

이 글의 주제인 버퍼 vs 직접 I/O 사용에 대한 토론으로 돌아가서:
여러분은 아주 작은 단위의 커밋때문에 테스트 시나리오가 약간 이상한 것이 아니냐고 생각하실 수 있습니다. 좋습니다. 이제 imp parfile 의 버퍼사이즈를 16MB 로 바꿔서 테스트 해 보겠습니다.
먼저 noforcedirectio 를 사용했습니다

Import terminated successfully without warnings.
 
real          44.74
user          10.57
sys            0.60

iosnoop-출력결과:

STRTIME              DEVICE  MAJ MIN   UID   PID D    BLOCK   SIZE                     PATHNAME ARGS
2009 May 28 00:33:34 sd0      32   4   215  4162 W 36398016   8192   /slice4/redolog/redo03.log ora_lgwr_DEM\0
2009 May 28 00:33:34 sd0      32   4   215  4162 W 36398032   8192   /slice4/redolog/redo03.log ora_lgwr_DEM\0
2009 May 28 00:33:34 sd0      32   4   215  4162 W 36398048   8192   /slice4/redolog/redo03.log ora_lgwr_DEM\0
2009 May 28 00:33:34 sd0      32   4   215  4162 W 36398064   8192   /slice4/redolog/redo03.log ora_lgwr_DEM\0
2009 May 28 00:33:34 sd0      32   4   215  4162 W 36398080   8192   /slice4/redolog/redo03.log ora_lgwr_DEM\0

다시한번 8KB 의 순차적인 쓰기 작업을 볼 수 있습니다. 비록 오라클이 더 큰 덩어리의 데이타를 커밋하더라도 말입니다. 이것은 오라클의 통계를 통해서도 확인될 수 있습니다:

Event		
Statistic				Total		per Second	per Trans
redo size 				39,506,404 	314,606.56 	564,377.20
redo write time 			3,222 		25.66 		46.03
redo writes 				99 		0.79 		1.41

이것은 대략 400 KB/redo 쓰기를 나타 냅니다.

이제 동일한 테스트를 forcedirectio 를 이용해서 진행해 봅시다:

Import terminated successfully without warnings.
 
real          17.01
user          10.55
sys            0.59

이 것은 버퍼 I/O 보다 약 163% 빠른 결과 입니다 (17,01 초 vs. 44,74 초). 다시한번 iosnoop 결과를 봅시다:

STRTIME              DEVICE  MAJ MIN   UID   PID D    BLOCK   SIZE                     PATHNAME ARGS
2009 May 28 00:54:09 sd0      32   4   215  4162 W 27313955   6656                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 27313968 1048576                      <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 27316019 242176                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 27316492  34816                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34013328  93696                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34013511 1044992                      <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34015552   3584                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34015559   3072                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34015565 361984                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:10 sd0      32   4   215  4162 W 34016272   5632                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34016283 133632                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34018064 857600                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34013216  57344                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34019739 371200                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34020464    512                       <none> ora_lgwr_DEM\0
2009 May 28 00:54:11 sd0      32   4   215  4162 W 34020465 1048064                      <none> ora_lgwr_DEM\0 

여러분이 보시듯이 I/O 는 다양한 사이즈로 발생했는데, 512 바이트에서 1MB 까지 다양한 사이즈가 발견되었습니다. 평균적으로 이것은 작은 8KB 쓰기 보다 훨씬 효율적임이 발견되었습니다.

결론

필자는 AWR 과 DTrace 로 얻어진 결론이 아주 명확하다고 생각합니다. 여전히 여러분은 UFS 버퍼 I/O 를 선호 하십니까? 선택은 여러분의 몫입니다.....


[원문]
Analyzing Oracle Logwriter w/ buffered vs. direct I/O
http://wikis.sun.com/display/saponsun/g ··· part%2B1


"관리자코너" 카테고리의 다른 글

2009/12/17 15:26 2009/12/17 15:26

TRACKBACK :: http://blog.sdnkorea.com/blog/trackback/874

댓글을 달아 주세요

[로그인][오픈아이디란?]

◀ Prev 1  ... 3 4 5 6 7 8 9 10 11  ... 806  Next ▶