SQL 트레이스와 실행 통계

예상 실행계획만으로는 SQL이 실제로 몇 건을 처리했고, 몇 블록을 읽었으며, 어디서 시간을 썼는지 알 수 없다. 이 문서는 실제 수행 통계를 확인하는 AutoTrace, SQL 트레이스(TKPROF), DBMS_XPLAN.DISPLAY_CURSOR와 응답 시간 분석의 기본 개념을 정리한다.

AutoTrace

SQL*Plus에서 SET AUTOTRACE를 설정하면 SQL 수행 후 실행계획과 실행 통계를 함께 보여 준다.

SQL> SET AUTOTRACE TRACEONLY
SQL> SELECT * FROM EMP WHERE EMPNO = 7900;

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          2  consistent gets
          0  physical reads
          0  redo size
        825  bytes sent via SQL*Net to client
        523  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

• 논리적 I/O = db block gets + consistent gets, 물리적 I/O = physical reads다.
• 옵션별 동작(ON, TRACEONLY, EXPLAIN, STATISTICS)은 실행계획 분석의 AutoTrace 표를 참고한다.

시험 포인트: AutoTrace는 실행 통계를 SQL 전체 합계로만 보여 준다. 어느 오퍼레이션에서 블록을 많이 읽었는지는 SQL 트레이스나 DISPLAY_CURSOR로 확인한다.

SQL 트레이스 수집

-- 현재 세션에 트레이스 설정
ALTER SESSION SET SQL_TRACE = TRUE;
SELECT * FROM EMP WHERE EMPNO = 7900;
ALTER SESSION SET SQL_TRACE = FALSE;

-- 트레이스 파일 위치 확인 (11g 이후)
SELECT VALUE FROM V$DIAG_INFO WHERE NAME = 'Default Trace File';

-- 대기 이벤트·바인드 값까지 수집 (10046 이벤트)
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

다른 세션은 DBMS_MONITOR.SESSION_TRACE_ENABLE, 서비스·모듈·액션 단위는 DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE로 설정할 수 있다.

트레이스 파일은 그대로 읽기 어려우므로 TKPROF 유틸리티로 포맷팅한다.

$ tkprof ora19c_ora_12345.trc report.prf sys=no

sys=no는 SYS 유저가 수행한 재귀 SQL을 리포트에서 제외한다.

TKPROF 리포트 읽기

SELECT * FROM EMP WHERE ENAME = :B1

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        2      0.01       0.35        180        214          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.35        180        214          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL EMP (cr=214 pr=180 pw=0 time=350121 us)

Call 구분

통계 항목

Row Source Operation 통계

Rows     Row Source Operation
-------  ---------------------------------------------------
 300000  TABLE ACCESS BY INDEX ROWID 고객 (cr=301245 pr=280512 time=...)
 300000   INDEX RANGE SCAN 고객_X01 (cr=1245 pr=980 time=...)

시험 포인트: TKPROF의 query는 consistent gets, current는 db block gets, disk는 physical reads에 대응한다. 논리적 I/O는 query + current다. Row Source의 cr·pr·time은 자식 값을 포함한 누적치다.

Fetch Call과 Array Size

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Fetch     3334      0.25       0.31          0       3592          0       50000

5만 건을 Fetch Call 3,334번으로 가져왔으므로 한 번에 약 15건씩(SQL*Plus 기본 arraysize = 15) 전송했다. arraysize를 키우면 Fetch Call 수가 줄고, 같은 블록을 반복해서 읽는 횟수도 줄어 query 값이 감소한다. 자세한 내용은 고급 SQL 활용과 배치 프로그램 튜닝을 참고한다.

DBMS_XPLAN.DISPLAY_CURSOR

라이브러리 캐시에 남아 있는 커서의 실제 실행계획과 오퍼레이션별 수행 통계를 보여 준다. 트레이스 파일을 만들 필요가 없어 편리하다.

-- 1. 수행 통계를 수집하며 실행
SELECT /*+ GATHER_PLAN_STATISTICS */ *
FROM   EMP E, DEPT D
WHERE  D.DEPTNO = E.DEPTNO
AND    E.SAL >= 2000;

-- 2. 직전에 수행한 SQL의 실제 계획과 통계 조회
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL, NULL, 'ALLSTATS LAST'));

-- 특정 SQL 지정: SQL_ID, CHILD_NUMBER
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('9babjv8yq8ru3', 0, 'ALLSTATS LAST'));

출력 예와 항목

-----------------------------------------------------------------------------------------
| Id  | Operation                    | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |      1 |        |     12 |00:00:00.01 |      15 |     2 |
|   1 |  NESTED LOOPS                |         |      1 |        |     12 |00:00:00.01 |      15 |     2 |
|   2 |   NESTED LOOPS               |         |      1 |      9 |     12 |00:00:00.01 |       5 |     1 |
|*  3 |    TABLE ACCESS FULL         | EMP     |      1 |      9 |     12 |00:00:00.01 |       3 |     0 |
|*  4 |    INDEX UNIQUE SCAN         | DEPT_PK |     12 |      1 |     12 |00:00:00.01 |       2 |     1 |
|   5 |   TABLE ACCESS BY INDEX ROWID| DEPT    |     12 |      1 |     12 |00:00:00.01 |      10 |     1 |
-----------------------------------------------------------------------------------------

E-Rows와 A-Rows 비교

E-Rows(×Starts)와 A-Rows가 크게 차이 나면 옵티마이저의 카디널리티 추정이 잘못된 것이다. 잘못된 추정은 잘못된 조인 순서, 조인 방식, 인덱스 선택으로 이어진다. 원인으로는 오래된 통계정보, 히스토그램 부재, 컬럼 간 상관관계, 바인드 변수 등이 있다. 옵티마이저에서 자세히 다룬다.

시험 포인트: DISPLAY_CURSOR로 오퍼레이션별 실측 통계를 보려면 gather_plan_statistics 힌트(또는 statistics_level = all)가 필요하다. E-Rows는 예상치, A-Rows는 실측치이며 Buffers는 논리적 I/O다.

도구 비교

응답 시간 분석과 대기 이벤트

대기 이벤트란

프로세스가 일을 계속하지 못하고 다른 무언가를 기다려야 할 때, 그 원인과 시간을 기록한 것이 대기 이벤트(Wait Event)다. 디스크 I/O, 락, 래치, 네트워크 등 공유 자원을 기다리는 시간이 여기에 해당한다. Oracle은 대기 이벤트를 V$SYSTEM_EVENT, V$SESSION_EVENT, V$SESSION_WAIT 등의 뷰로 제공한다.

응답 시간 분석 (Response Time Analysis)

Response Time = Service Time + Wait Time
              = CPU Time     + Queue Time

TKPROF에서 elapsed가 cpu보다 훨씬 크면 대기 시간이 많은 것이다. 10046 트레이스 레벨 8 이상으로 수집하면 리포트에 대기 이벤트 내역이 나온다.

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
  db file scattered read                         24        0.03          0.33
  SQL*Net message from client                     2        0.01          0.01

위 예는 Full Scan의 Multiblock I/O 대기(db file scattered read)가 전체 시간의 대부분을 차지한다.

대표적인 대기 이벤트

AWR와 Statspack

시스템 전체의 대기 이벤트와 성능 지표는 AWR(Automatic Workload Repository) 또는 Statspack으로 분석한다. 일정 주기로 동적 성능 뷰를 스냅샷으로 저장하고, 두 시점 사이의 차이(Delta)를 리포트로 만든다. 리포트의 Top 5 Timed Events(Top Timed Foreground Events)가 응답 시간 분석의 출발점이다.

시험 포인트: db file sequential read는 Single Block I/O, db file scattered read는 Multiblock I/O다. 응답 시간 = CPU 시간(Service Time) + 대기 시간(Queue Time)이며, 응답 시간 분석은 가장 많은 시간을 차지한 대기 이벤트부터 해결한다.

핵심 요약

• AutoTrace는 실행계획과 SQL 전체 실행 통계를 보여 준다. 논리적 I/O = db block gets + consistent gets, 물리적 I/O = physical reads.
• SQL 트레이스는 ALTER SESSION SET SQL_TRACE = TRUE 또는 10046 이벤트로 수집하고 TKPROF로 포맷팅한다.
• TKPROF는 Parse·Execute·Fetch Call별로 count, cpu, elapsed, disk, query, current, rows를 보여 준다.
• query = consistent gets, current = db block gets, disk = physical reads이며 논리적 I/O는 query + current다.
• Misses in library cache during parse가 1이면 하드 파싱이 발생한 것이다.
• Row Source의 cr·pr·time, DISPLAY_CURSOR의 A-Rows·Buffers·A-Time은 자식 값을 포함한 누적치다.
• DISPLAY_CURSOR로 실측치를 보려면 gather_plan_statistics 힌트 또는 statistics_level = all이 필요하고, 'ALLSTATS LAST'는 마지막 실행 통계다.
• E-Rows는 1회당 예상 건수이므로 Starts를 곱해 A-Rows와 비교한다. 차이가 크면 카디널리티 추정 오류다.
• 응답 시간 = CPU 시간 + 대기 시간이며, 대기 이벤트를 분석해 병목 원인을 찾는다.