Perf/Blktrace 툴을 이용하여 시스템분석하기 (Case 1 - Async I/O)

모 고객이 신규 프로젝트를 위해 여러가지 운영준비를 하다가,
거의 실 생산라인에 적용하려는 파이날 테스트 과정에서
Oracle RDBMS 의 REDO log 지연의 메시지가 보고되고 있다는 문의가 발생하였다.

Application 쪽에서는 해당 이슈는 OS 와 Disk 성능에 관련된 부분이므로, 해당 부분을 확인해야 한다고 가이드 했고,

OS level 에서는 해당 부분은 Async/Direct I/O 이므로 어플리케이션과 하드웨어(스토리지 사이드) 의 이슈라고 하였으나,
이를 검증하라는 황망한 요구를 받고 strace 를 통해 어떤 시스템콜에서 문제가 걸리는지를 확인 해 보기로 하였다..

문제의 지연 함수는 io_submit/io_getevents 였고, 특히 io_getevents 의 지연이 90퍼센트 이상을 차지함이 확인되어,
OS (커널) 의 문제로 집중이 되기 시작했기에, Kernel Profiling 을 통해 OS level 의 문제가 아님을 증명하는 과정과 방법을 간략히 공유하기로 한다.

1. 시스템 및 준비사항

 System : HPe Superdome Flex
 OS version : Oracle Linux 7.6
 Kernel : kernel-uek-5.4.17-2036.100 ( UEKr6 )
 Storage : Pure Storage / Hweii Storage etc.

 준비사항 : Perf-tools, blktrace

2. perf profiling - 수집

현재 친절하게도 Oracle DB team 에서 Strace 를 통해
지연이 발생하는 부분에 대한 Call trace 를 아래와 같이 잡아주어,
Perf 에서 모니터링할 system call 을 io_submit, io_getevents 로 좁혀 진행했다 :

17203 10:40:04.850440 io_submit(0x7ffff7fed000, 2, [{aio_data=0x7ffff2756630,
aio_lio_opcode=IOCB_CMD_PWRITE, aio_fildes=309,
aio_buf="\1\"\0\0\276.\27\0Y\1\0\0\20\200\271\245|\0\0\0\6L\v\17\305e\352\21\1
\0\0000"..., aio_nbytes=512, aio_offset=97662106624},
{aio_data=0x7ffff19a5e38, aio_lio_opcode=IOCB_CMD_PWRITE, aio_fildes=311,
aio_buf="\1\"\0\0\276.\27\0Y\1\0\0\20\200\271\245|\0\0\0\6L\v\17\305e\352\21\1
\0\0000"..., aio_nbytes=512, aio_offset=96269597696}]) = 2 <0.000115>
17203 10:40:04.850621 io_getevents(0x7ffff7fed000, 2, 128,
[{data=0x7ffff19a5e38, obj=0x7ffff19a5e38, res=512, res2=0},
{data=0x7ffff2756630, obj=0x7ffff2756630, res=512, res2=0}], {tv_sec=600,
tv_nsec=0}) = 2 <0.995326>

Perf 의 수행 내용 :

# time=`date +"%m-%d-%T"`;perf record -e syscalls:sys_enter_io_submit -e syscalls:sys_exit_io_submit \
-e syscalls:sys_enter_io_getevents -e syscalls:sys_exit_io_getevents  -e syscalls:sys_enter_pread64 \
-e syscalls:sys_exit_pread64 -T -o io_getevents-${time}.perf  -p <pid>

3. Perf profiling - 분석

문제의 I/O 는 io_submit 이후, io_getevents 에서 0.99 초가 걸렸고,
아래와 같은 Perf data 를 확인 할 수 있었다 :

# perf script
Process          PID    TS     Nsec  Elaps. Event(syscall)                               ctx_id     min_nr           Events
ora_lgwr_ic**** 24441 4220511 449636        syscallssys_enter_io_getevents 0x7ffff7fed000 0x00000004 0x7fffffff7ba8
ora_lgwr_ic**** 24441 4220511 450284 648    syscallssys_exit_io_getevents  
ora_lgwr_ic**** 24441 4220511 450396        syscallssys_enter_io_getevents 0x7ffff7fed000 0x00000004 0x7fffffff7ba8                 <<<
ora_lgwr_ic**** 24441 4220511 451413 1017   syscallssys_exit_io_getevents
ora_lgwr_ic**** 24441 4220511 451557        syscallssys_enter_io_getevents 0x7ffff7fed000 0x00000004 0x7fffffff7ba8                    <<<
ora_lgwr_ic**** 24441 4220511 452751 1194   syscallssys_exit_io_getevents   

위 데이타는 perf record 로 수집된 내용을 perf script 를 통해 읽기 쉬운 데이타로 변환한 것을

다시 구분을 하여 보기 쉽게 변환한 것이다.

위에서 보면 Elaps 가 나오는데 실제 io_getevents 의 enter -> exit 구간은 0.11 nano seconds 정도 밖에
걸리지 않았음이 확인된다.

이로써 커널의 Async I/O 를 담당하는 io_submit 과 io_getevents 자체의 성능 문제는
전혀 없음이 확인되었고, 그렇다면 대체 지연이 왜 발생하는 것인지 확인이 필요하여,
Block layer 추적 도구인 blktrace 를 통해 내용을 짚어보기로 했다.

4. Blktrace - Block layer trace tool

Blktrace 는 Kernel 과 Block layer 의 동작을 분석해주는 Sector 기반 데이타 추적 도구이다.

Blktrace 를 통해 어플리케이션이 요청한 Write 내용을
Application - Kernel - Driver - H/W ( Storage ) 단계로 구분하여 Data Unit 단위로 추적한다.

아래와 같은 Step 을 통해 문제가 될 만한 시스템을 모니터링 하였다 :

1. create a temp directory and cd to it:
    mkdir /tmp/test1 && cd /tmp/test1
2. /dev/sd* 와 같은 Log writer 의 Block device 의 풀 패스를 리스트한 lgwr-paths 라는 파일을 만든다.
3. logwriter 의 strace 를 출력 :
    strace -vfttT -o lgwr-strace.txt -p <pid_of_lgwr> &
4. blktrace 수행:
    blktrace -w 300 -d $(cat lgwr-paths)

blktrace 는 -w 옵션을 따라 300초 동안의 idle 시간을 대기하는 조건을 갖고 lgwr-paths 를 읽어 해당 path 의 상태를 수집하게 된다.

해당 추적도구는 High-end 또는 mission critical 한 시스템에서 부하를 유발 할 수 있으므로,
조심스럽게 사용해야 한다.

Strace 에서 해당 지연 request 를 찾아 block/sector 값을 통해 해당 Data unit 을 찾아내었고,
다음과 같은 내용을 확인 할 수 있다 :

* Strace :

17203 10:40:04.850440 io_submit(0x7ffff7fed000, 2, [{aio_data=0x7ffff2756630,
aio_lio_opcode=IOCB_CMD_PWRITE, aio_fildes=309,
aio_buf="\1\"\0\0\276.\27\0Y\1\0\0\20\200\271\245|\0\0\0\6L\v\17\305e\352\21\1
\0\0000"..., aio_nbytes=512, aio_offset=97662106624},
{aio_data=0x7ffff19a5e38, aio_lio_opcode=IOCB_CMD_PWRITE, aio_fildes=311,
aio_buf="\1\"\0\0\276.\27\0Y\1\0\0\20\200\271\245|\0\0\0\6L\v\17\305e\352\21\1
\0\0000"..., aio_nbytes=512, aio_offset=96269597696}]) = 2 <0.000115>
17203 10:40:04.850621 io_getevents(0x7ffff7fed000, 2, 128,
[{data=0x7ffff19a5e38, obj=0x7ffff19a5e38, res=512, res2=0},
{data=0x7ffff2756630, obj=0x7ffff2756630, res=512, res2=0}], {tv_sec=600,
tv_nsec=0}) = 2 <0.995326>

* Blkparse ( blktrace 에서 얻어진 결과를 읽기 쉽게 Parsing 해 준다. :

# blkparse -i XXXX.trc
[ Device ] [CPU ID] [Sqc] [ timestamp ]     [ PID ] [ Action ] [ RWBS ]
70,592      69       11 1266874873.591919042 17203      A        W 190748350 + 1 <- (252,169) 190748350  
70,592      69       12 1266874873.591923257 17203      D        WS 190748350 + 1 [ora_lgwr_m1***] 
135,576     69       16 1266874873.591957499 17203      A        W 188028606 + 1 <- (252,160) 188028606 
135,576     69       17 1266874873.591960590 17203      D        WS 188028606 + 1 [ora_lgwr_m1***] 
135,576     69       18 1266874873.592728464 31256      C        WS 188028606 + 1 [0]

OL8 에서의 blkstat 은 조금 보기 편한다 :

[ Device ] [CPU ID] [Sqc] [ timestamp ]  [ PID ] [Action] [ RWBS ]
 67,720       69      9    4.451300687    17203    A      W 190715679 + 1 <-(252,154) 190715679
 67,720       69     10    4.451305539    17203    D      WS 190715679 + 1 [ora_lgwr_m1***]
 67,720       71      5    5.722159729    26194    C      WS 190715679 + 1 [0]  <<<

보면 A->D 까지는 상당히 짧은 시간이 소요된 반면 ( 0.000005 sec 이하 )

D->C 로 넘어가는 구간에서 1.2 초정도라는 상당힌 시간을 소요함을 알 수 있다.
( Strace 의 데이타는 일치하는 데이타가 아닌 다른 테스트의 데이타를 썼는데, 귀찮으니 넘어가자.. ㅋ )

5. 결론

A->D 는 간단하게 Application 의 요청을 받아 Driver 에 전달한 것으로 보면 되고 ( ISSUED ),

C 는 Complete 로 I/O request 가 완전히 종료되었음을 알리는 액션이다.

이 Complete 가 확인되어야만 io_getevents 는 디스크 쓰기가 완전히 종료되었음을 Application 에 알리고,

Application 은 자신이 요청한 I/O request 가 완료했음을 이해하고 다음 동작을 수행할 수 있게 된다.

즉, 실제 Driver 에 커널이 해당 섹터의 데이타를 기록요청 한 후,

Disk level 또는 HBA 의 레벨에서 H/W 적으로 시간이 소요되었음을 나타내는 결과이다.

현재 본 이슈는 다소 다른 양상으로 흘러가고 있긴 하지만,

이로 인해 데이타의 지연이 발생하는 부분은 하드웨어레벨에서 발생하고 있음을 확인 할 수 있었고,

하드웨어레벨에서 해당 부분을 분석하도록 유도 할 수 있었다.

6. 참고사이트

아래 링크는 Linux 에서의 I/O 종류별 설명을 담은 블로그이며 매우 유용하니 확인해 보도록 하자 :

www.scylladb.com/2017/10/05/io-access-methods-scylla/

Blktrace 에 대해 상세한 사용 및 설명이 나와있는 유용한 사이트이다 :

www.scylladb.com/2017/10/05/io-access-methods-scylla/

Perf 를 통해 DB 성능을 확인할 수 있도록 도와주는 사이트이다 :

db-blog.web.cern.ch/blog/luca-canali/2016-01-linux-perf-probes-oracle-tracing