리눅스 perf 명령어를 이용한 오라클 Kernel Function 분석 방법

일반적으로 오라클 성능 분석 방법론은 대기 시간의 분석에 초점이 맞춰져 있습니다. 즉, 응답시간을 CPU 사용시간과 대기시간으로 구분하고 대기시간은 개별 대기이벤트의 대기시간으로 세분화함으로써 성능 저하의 원인을 빠르게 진단하는 방법을 사용합니다. 이러한 분석의 기본 전제는 대기시간보다 CPU 사용시간의 비율이 높다면 현재 수행되는 프로세스는 정상적으로 일을 잘하고 있다는 것입니다. 반대로 말하면 대기시간이 비중이 높을수록 성능 이슈가 있다는 것을 의미하기도 합니다.

그런데 간혹 “CPU 사용률(%)이 높은 프로세스가 정상적으로 일을 처리하고 있는지?” 라는 의문이 생길 때가 있습니다. 일반적으로 이런 경우에 사용할 수 있는 방법은 truss, tusc, strace등과 같은 유틸리티를 이용해서 OS 시스템 콜을 분석하는 것입니다. 하지만 이러한 툴들이 제공하는 최하위 레벨의 시스템 콜을 분석하는 것은 매우 어려운 일입니다.

이를 보완하기 위한 방법으로 리눅스의 경우에는 “perf” 툴을 이용해서 스택 트레이스를 확인할 수 있으며, 이를 통해 오라클 커널 function을 확인할 수 있습니다.

이를 이용해서 오라클 에이스 중의 한명인 Craig shallahamer는 2014년 OOW에서 아주 흥미롭고 유용한 기법을 발표합니다. 간단히 요약하면, perf 툴과 v$ 데이터를 이용해서 현재 수행중인 프로세스의 CPU Time과 대기 시간을 세분화해서 제공하는 방법입니다. 해당 툴의 이름은 fulltime.sh이며 여기에서 다운로드 받을 수 있습니다. 물론 perf 툴에서 제공하는 커널 function 명 또한 이해하기 쉽지는 않지만 몇 가지 잘 알려진 명명 규칙(예시-1 참조)을 통해 해당 function의 수행 내용을 유추하거나 오라클에 문의할 때 도움이 될 수 있을 것입니다.

예시-1. 몇 가지 커널 function 명명 규칙

  • kcb (kernel cache buffer)
  • kcbgtcr (kernel cache buffer get CR)
  • smb (sort merge buffer)
  • smbget (sort merge buffer get)

그럼 예제를 통해 확인해보겠습니다.

1. CPU를 과도하게 사용하는 쿼리 수행 후 WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼 값 확인


-- CPU를 과도하게 사용하는 쿼리
select count(*) from big_t, big_t;

-- 해당 쿼리의 예상 실행 계획
-----------------------------------------------------------------------
| Id  | Operation             | Name  | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |     1 |   580M  (1)| 06:17:51 |
|   1 |  SORT AGGREGATE       |       |     1 |            |          |
|   2 |   MERGE JOIN CARTESIAN|       |   250G|   580M  (1)| 06:17:51 |
|   3 |    TABLE ACCESS FULL  | BIG_T |   500K|  1163   (1)| 00:00:01 |
|   4 |    BUFFER SORT        |       |   500K|   580M  (1)| 06:17:51 |
|   5 |     TABLE ACCESS FULL | BIG_T |   500K|  1161   (1)| 00:00:01 |
-----------------------------------------------------------------------

--WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼 값 확인
SYS@OOW1:1> @mon_1_sess2 202

       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          716 direct path read                     100.0           .660        1,411.09
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          717 resmgr:cpu quantum                    97.2         14.700          516.28
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          717 resmgr:cpu quantum                    99.3         14.700        2,126.53
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          722 resmgr:cpu quantum                    90.8         29.970          294.57
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          723 resmgr:cpu quantum                    99.5           .760          158.56

해당 SQL 수행 시에 대기시간은 거의 없고 대부분 CPU를 사용하는 것을 알 수 있습니다. CPU를 과도하게 사용함에 따라 리소스 관리 정책에 의해 ‘resmgr:cpu quantum’ 대기이벤트를 대기하지만 대기 시간의 비율은 아주 낮습니다.

2. fulltime.sh를 이용한 CPU Time 분석


fulltime.sh의 사용법은 다음과 같습니다.
$ fulltime.sh

아래의 수행 결과를 보면 CPU 사용 시간의 비율이 99.66%, 대기시간의 비율이 0.34%인것을 알 수 있습니다. 또한 CPU 사용시간 중에서 smbget 커널 function의 사용 비율이 36.26%임을 알 수 있습니다.

예시-2. pert 수행 결과

PID: 3234  SID: 202  SERIAL: 44156  USERNAME: SCOTT  at 21-Aug-2016 07:57:33
CURRENT SQL:  select count(*) from big_t, big_t

total time: 2.123 secs,  CPU: 2.116 secs (99.66%),  wait: .007 secs (.34%)
                                                                   Time
Time Component                                                     secs       %
------------------------------------------------------------ ---------- -------
cpu : [.] smbget                                                  0.770   36.26
cpu : [.] sorgetqbf                                               0.589   27.74
cpu : [.] qersoFetchSimple                                        0.361   17.02
cpu : [.] rworupo                                                 0.178    8.40
cpu : [.] qeaeCn1Serial                                           0.147    6.94
cpu : [.] kskchk                                                  0.052    2.47
cpu : [?] sum of funcs consuming less than 2% of CPU time         0.017     .80
wait: resmgr:cpu quantum

모니터링 후 (CTRL+C로 종료)에 엔터를 입력하면 스택 트레이스에 대한 트리 구조의 perf report 결과를 확인할 수 있습니다. (예시-3 참조) 이를 통해 커널 function을 보다 더 세분화해서 분석할 수 있습니다.

예시-3. perf report 수행 결과

To see the Call Graph, press ENTER or to exit press CNTRL-C.
Samples remaining: 5
Gathering next 3 second sample...
^C

# Overhead          Command      Shared Object                         Symbol
# ........  ...............  .................  .............................
#
    37.21%  oracle_3234_oow  oracle             [.] smbget
            |
            --- smbget
               |
               |--94.84%-- sorgetqbf
               |          qersoFetchSimple
               |          qersoFetch
               |          qerjotFetch
               |          qergsFetch
               |          opifch2
               |          kpoal8
               |          opiodr
               |          ttcpip
               |          opitsk
               |          opiino
               |          opiodr
               |          opidrv
               |          sou2o
               |          opimai_real

 

글을 마치며


DB 인터널 관련 자료들을 보면 시스템 트레이싱 기법을 자주 접하게 됩니다. 이 글에서 언급된 fulltime.sh 뿐 아니라 Tanel Porder가 사용하는 몇 가지 스크립트에서도 시스템 트레이싱 기법이 소개됩니다. 물론, 과연 이렇게까지 세밀하게 볼 필요가 있을까? 또는 이렇게 자세히 분석할 필요가 있을까? 라는 의문이 들기도 합니다. 또한 대부분의 성능문제는 이러한 것을 모르더라도 충분히 해결 가능하기도 합니다. 하지만 아주 민감하고 어려운, 또는 누구도 풀지 못하는 성능 이슈를 처리해야할 때 이러한 기법은 큰 도움이 될 것입니다. 결국, 엔지니어의 길을 가기 위해서는 끝없는 정진이 필요한 것 같습니다.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s