ORACLE SQL Trace & TKPROF 확인 방법

오라클은 어플리케이션(SQL)을 모니터링하고 튜닝하기 위한 기본적인 성능 진단 툴을 제공하고 있다.

요샌 Toad나 SQLGate 등 DBMS 관련 Tool들이 매우 잘 나와서 개발 단계에서 실행계획 분석이나 XPLAN.DISPLAY 정보는 쉽게 확인 가능하기는 하나 언제나 애로사항을 꽃피우는 곳은 운영환경이다.

장애상황이 아주 그냥 활짝 피셨다

특히나 DB쪽의 운영환경은 대부분 강력한 방화벽 정책에 의하여 리스너 포트가 오픈 되어 있다는건 꿈또 못 꿀 일(아니 꿈에서라도 일어나면 안되는 일이다)이니 되도록 커맨드라인에서 처리하는 방법을 익혀두는 편이 애로사항 제거에 조금이나마 도움이 될 것 같다.

또 최근 SI쪽에서 추세는 규모가 좀 있는 프로젝트라면 응당 DBA가 한명 이상은 꼭 참여를 하니 더욱더 개발자들은 SQL 작성에 예전보다 심혈을 기울이지 않는 편이다. 문제가 생기면 **"DBA에게 튜닝요청"**이라는 마법의 주문을 걸면 되니까 말이다.

RDMS를 사용하는 환경은 최근에 NoSQL 데이터베이스들이 많이 나온고 활성화 된다 해도 그리 쉽게 사그러질 환경은 아니므로 DBA에게 모든걸 맡기기보다 실행계획정도는 꼭 확인하고, 가능하다면 오픈전에 운영환경에서 성능상의 이슈가 있을만한 SQL은 Trace정보를 미리 확인해 보는 것도 좋을 것 같다.

이번 포스트는 오라클에서 제공되는 많은 툴 중에서 성능 분석 시 가장 많이들 사용하는 10046 debugging event를 사용해서 Trace 파일을 남기고 TKPROF를 사용하는 방법에 대해 간략히 정리해 본다.

Oracle Trace

Oracle의 Trace 기능은 수행되는 개별 SQL Statement의 다음과 같은 성능정보의 통계를 제공해 준다.

Parse, execute, and fetch counts
CPU and elapsed times
Physical reads and logical reads
Number of rows processed
Misses on the library cache
Username under which each parse occurred
Each commit and rollback

이외에도 사용자의 SQL 문제점 뿐만 아니라 DBMS 자체가 문제가 생길 경우에도 해당 정보를 Trace 파일로 생성해 준다.

debugging event 10046

10046 Event는 기본 Trace정보를 확장하여 더욱 더 세부적인 정보를 확인할 때 사용하는 이벤트다.

해당 이벤트 사용 시에는 부가 정보의 레벨을 설정할 수 있는데 보통 12(4+8) 레벨을 가장 많이 사용하고, 각 레벨 별 속성은 아래와 같다.

Level	Description
0	디버깅 이벤트를 비활성화 시킨다
1	디버깅 이벤트를 활성화 시킨다. 매 데이터베이스 요청마다 아래의 정보를 제공한다: SQL statement response time service time number of processed rows number of logical reads number of physical reads and writes execution plan little additional information.
4	Level 1 + Binding 정보 매 요청마다 정확한 데이터 타입이나 대입 값을 확인하기 위해서
8	Level 1 + Wait 정보 wait 이벤트 이름 지속 시간 wait이 걸려 있는 리소스를 확인하기 위한 부가적인 정보
16	Level 1 + 매 수행마다의 실행계획 포함 11.1 이상
32	Level 1 + 실행계획 미포함 11.1 이상
64	Level 1 + 마지막에 쓰여진 실행계획 기준으로 수행을 하는 것 같다. LEVEL 16의 실행계획 작성 오버헤드를 회피하거나 첫번째 수행 결과가 분석에 도움이 되지 않는 경우 쓰이는 것 같다. 정확한 정보는 검색해도 잘 나오지 않는다. 추가된건 맞는건지;; 11.2.0.2 이상에 추가

아래처럼 조합으로 사용 가능하고 보통 12레벨을 가장 많이 사용한다. 12레벨의 경우에는 바인딩 변수값이 TKPROF 변환된 내용에 나오지 않으므로 .trc 파일을 분석해야 한다.

Level 12 (4 + 8) 4레벨, 8레벨을 동시에 남기고 싶을 때
Level 28 (4 + 8 + 16) 4레벨, 8레벨, 16레벨을 동시에 남기고 싶을 때
Level 68 (4 + 64) 4레벨, 64레벨을 동시에 남기고 싶을 때

실제로 Trace 정보를 확인해 보자

Trace 파일을 남기는 방법은 세션 혹은 인스턴스 레벨로 설정할 수 있는데 인스턴스 레벨로 세션정보를 남길 경우 20~30% 정도의 오버헤드가 발생한다고 하니 정말 어떤 SQL이 문제가 되는지 파악조차 되지 않는 상황을 제외하고는 세션 레벨로 Trace를 남기는 것이 좋을 것 같다.

10046 이벤트를 통한 확장 트레이스 파일을 생성

세션 레벨로 Trace 정보를 남기는 방법은 아래와 같다.

SQL> ALTER SESSION SET SQL_TRACE = TRUE;
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

남겨지는 Trace파일의 위치는 오라클 서버 종류에 따라 user_dump_dest(dedicated server), background_dump_dest(shared server)에 남는다.

trace파일이 워낙 많이 남기 때문에 구분이 안되는 경우 Trace 파일에 구분자를 설정하면 된다.

SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER='파일_구분자';

샘플 SQL을 실행해보면

SQL> SELECT
  2      EMPNO,
  3      JOB,
  4      HIREDATE,
  5      SAL
  6  FROM
  7      EMP
  8  WHERE
  9      SAL > 100;

SQL> ALTER SESSION SET SQL_TRACE = FALSE;

sid_ora_프로세스ID_파일_구분자.trc 형식으로 Trace파일이 남게 된다.

TKPROF로 변환

trc파일 자체는 사용자가 보기 좋게 포맷팅 되어 있지 않기 때문에 TKPROF라는 툴로 보기 좋게 변환하여 볼 수 있다.

$ tkrpof 
Usage: tkprof tracefile  outputfile
       [explain=username/password]
       [table=schema.tablename]
       [print=integer]
       [insert=filename]
       [sys=no] 
       [sort=option]

Trace 파일을 변환해보면 아래와 같이 변환 결과를 확인 할 수 있다.

TKPROF: Release 10.2.0.4.0 - Production on Tue May 24 13:42:56 2016

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: /oracle1_iem/admin/Oraiem/udump/oraiem_ora_24008_hkwon.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

alter session set events '10046 trace name context forever,level 12'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: 29

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

SELECT
    EMPNO,
    JOB,
    TO_CHAR(HIREDATE, :"SYS_B_0") HIREDATE,
    SAL
FROM
    EMP
WHERE
    SAL > :"SYS_B_1"

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          8          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          8          0          14

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 29

Rows     Row Source Operation
-------  ---------------------------------------------------
     14  TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=47 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
********************************************************************************

DBMS_XPLAN.DISPLAY

TKPROF를 통해 분석된 내용이 SQL Statement에 대한 실제 실측 정보를 제공한다면 DBMS_XPLAN.DISPLAY는 예측정보를 제공한다.

예측정보이기 때문에 정확한 실행계획 확인이나 튜닝을 위해서는 Trace정보를 확인하는 것이 좋지만 10046 event에서 제공되지 않는 Predicate Information의 filter나 access path 정보는 튜닝 시 매우 중요한 정보 활용 할 수 있다.

DBMS_XPLAN.DISPLAY 확인 방법

SQL> ALTER SESSION SET STATISTICS_LEVEL=ALL;

SQL> SELECT
  2      EMPNO,
  3      JOB,
  4      HIREDATE,
  5      SAL
  6  FROM
  7      EMP
  8  WHERE
  9      SAL > 100;

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null, 0, 'ALLSTATS LAST'));

SQL_ID  7t3kd7j07yu9p, child number 0
-------------------------------------
SELECT     EMPNO,     JOB,     TO_CHAR(HIREDATE, :"SYS_B_0") HIREDATE,
   SAL FROM     EMP WHERE     SAL > :"SYS_B_1"

Plan hash value: 2872589290

---------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------
|*  1 |  TABLE ACCESS FULL| EMP  |      1 |     14 |00:00:00.01 |       8 |
---------------------------------------------------------------------------


Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('10.2.0.4')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('optimizer_dynamic_sampling' 0)
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      FIRST_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "EMP"@"SEL$1")

      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("SAL">:SYS_B_1)

좀 더 쉽게 활용해 보자

이번에 성능개선 프로젝트를 진행하면서 하도 Trace를 많이 참조하다보니 매번 타이핑 하는게 귀찮아서 간단한 쉘스크립트를 만들어봤다.

trace.sh 파일을 아래처럼 작성하고

#!/bin/sh

ARG_CNT=$#

echo "...argument count is $ARG_CNT"

if [ $ARG_CNT != "2" ]; then
    echo "Error- Invalid parameter"
    echo "Usage : trace.sh test.sql identifier"
    exit 1
fi

ORACLE_HOME=/oracle
DUMP_PATH=$ORACLE_HOME/admin/sid/udump
SQL_FILE=$1
TEM_SQL_FILE=$DUMP_PATH/$SQL_FILE
TRACEFILE_IDENTIFIER=$2

echo '.. set tracefile identifier'
sed -e 's/:TRACEFILE_IDENTIFIER:/'"$TRACEFILE_IDENTIFIER"'/g' $SQL_FILE > $TEMP_SQL_FILE

SQLPLUS_CMD="sqlplus user/pass < $TEMP_SQL_FILE"
echo $SQLPLUS_CMD
eval $SQLPLUS_CMD

echo "... run tkprof command"

cd $DUMP_PATH

TRACE_FILE=`ls -lrt *${TRACEFILE_IDENTIFER}* | tail -1 | awk -F " " '{print \$9}'`
PID=$$
OUTPUT_FILE=${TRACEFILE_IDENTIFIER}_${PID}.prof

tkprof $DUMP+APTH/$TRACE_FILE $DUMP_PATH/$OUTPUT_FILE.prof SYS=NO"

cat $DUMP_PATH/$OUTPUT_FILE.prof

if [ -f $TEMP_SQL_FILE ]
then
    rm -fr $TEMP_SQL_FILE
fi

수행할 SQL 파일은 아래처럼 구성하고

ALTER SESSION SET statistics_level=ALL;
ALTER SESSION SET sql_trace=true;
ALTER SESSION SET tracefile_identifier='';
ALTER SESSION SET events '10046 trace name context forerver,level 12';
set heading off;
set linesize 172;
set timing on;

-- 수행할 SQL
SELECT
    EMPNO,
    JOB,
    HIREDATE,
    SAL
FROM
    EMP
WHERE
    SAL > 100;

-- SHOW XPALN
SELECT
    *
FROM
    TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null, 0
        , 'ALLSTATS LAST -ROWS +OUTLINE +PREDICATE'));

이제 쉘스크립트를 실행하면

$ trace.sh test.sql hkwon

ARG_COUNT = 2
...set tracefile identifer
sqlplus edm/edm < /oracle1_iem/admin/Oraiem/udump/test.sql

SQL*Plus: Release 10.2.0.4.0 - Production on Tue May 24 13:57:44 2016

Copyright (c) 1982, 2007, Oracle.  All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
Session altered.

SQL>
Session altered.

SQL>
Session altered.

SQL>
Session altered.

SQL> SQL> SQL> SQL> SQL> SQL>   2    3    4    5    6    7    8    9
      7839 PRESIDENT 1981-11-17                                                                        5000
      7698 MANAGER   1981-05-01                                                                        2850
      7782 MANAGER   1981-06-09                                                                        2450
      7566 MANAGER   1981-04-02                                                                        2975
      7788 ANALYST   1987-04-19                                                                        3000
      7902 ANALYST   1981-12-03                                                                        3000
      7369 CLERK     1980-12-17                                                                         800
      7499 SALESMAN  1981-02-20                                                                        1600
      7521 SALESMAN  1981-02-22                                                                        1250
      7654 SALESMAN  1981-09-28                                                                        1250
      7844 SALESMAN  1981-09-08                                                                        1500
      7876 CLERK     1987-05-23                                                                        1100
      7900 CLERK     1981-12-03                                                                         950

      7934 CLERK     1982-01-23                                                                        1300

14 rows selected.

Elapsed: 00:00:00.00
SQL> SQL> SQL>   2    3
SQL_ID  7t3kd7j07yu9p, child number 0
-------------------------------------
SELECT     EMPNO,     JOB,     TO_CHAR(HIREDATE, :"SYS_B_0") HIREDATE,
   SAL FROM     EMP WHERE     SAL > :"SYS_B_1"

Plan hash value: 2872589290

---------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------
|*  1 |  TABLE ACCESS FULL| EMP  |      1 |     14 |00:00:00.01 |       8 |
---------------------------------------------------------------------------


Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('10.2.0.4')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('optimizer_dynamic_sampling' 0)
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      FIRST_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "EMP"@"SEL$1")

      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("SAL">:SYS_B_1)


34 rows selected.

Elapsed: 00:00:00.03
SQL> Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
...run tkprof command
trace file name is oraiem_ora_24522_hkwon.trc
tkprof /oracle1_iem/admin/Oraiem/udump/oraiem_ora_24522_hkwon.trc /oracle1_iem/admin/Oraiem/udump/hkwon_24519.prof SYS=NO

TKPROF: Release 10.2.0.4.0 - Production on Tue May 24 13:57:44 2016

Copyright (c) 1982, 2007, Oracle.  All rights reserved.


...tkprof result is

TKPROF: Release 10.2.0.4.0 - Production on Tue May 24 13:57:44 2016

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: /oracle1_iem/admin/Oraiem/udump/oraiem_ora_24522_hkwon.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

alter session set events '10046 trace name context forever,level 12'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: 29

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

SELECT
    EMPNO,
    JOB,
    TO_CHAR(HIREDATE, :"SYS_B_0") HIREDATE,
    SAL
FROM
    EMP
WHERE
    SAL > :"SYS_B_1"

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          8          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          8          0          14
---블라블라블라

XPLAN값과 TRACE정보를 손쉽게 볼 수 있을 것 같다.

정리

어플리케이션 개발자라도 일단은 Trace정보를 확인하는 법부터 시작해서 기본적인 실행계획의 분석과 테이블 풀스캔 회피, 부분범위처리, random access의 최소화, 인덱스 전략 등의 내용을 숙지하고 있어야 개발 단계에서부터 충분히 고민이 된 SQL 작성이 되지 않을 까 싶다.

참고로 gurubee나 database.sarang.net은 본인도 매우 즐겨 찾는 사이트로 고수들의 tip&tech, 강좌, Q&A등 알찬 정보들이 많으니 참고 바란다.