CH03.오라클 성능 관리 - 03.SQL 트레이스

SQL을 튜닝할 때 가장 많이 사용되는 강력한도구 입니다.

 

(1) 자기 세션에 트레이스 걸기

아래는 현재 자신이 접속해 있는 세션에만 트레이스를 설정하는 방법입니다.

 

SQL> alter session set sql_trace=true;

SQL 문 수행

SQL> alter session set sql_trace=false;

 

위와 같이 트레이스를 설정하고 SQL을 수행하면 user_dump_dest 파라미터로 지정된 디렉토리 밑에 프레이스파일(.trc)가 생성됩니다. 가장 최근에 생성되거나 수정된 파일을 찾아 분석하면 됩니다.

 

TKProf 유틸리티

 

트레이스 파일을 보기 쉬운 형태로 포맷팅하면 유틸리티입니다. 사용법은 tkprof를 치면 확인할 수 있습니다.

 tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]

 

아래와 같은 형식으로 사용합니다. sys=no옵션은 SQL을 파싱하는 과정에서 내부적으로 수행되는 SQL문장을 제외시켜줍니다.

 

$tkprof orcl11g_ora_6918_ysbae.trc test.prf sys=no

TKPROF: Release 11.2.0.4.0 - Development on Wed Jan 1 01:00:36 2020

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

 

트레이스 결과분석

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.04          1          1          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch        4      0.00       0.02          8          4          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       11      0.00       0.06          9          5          0           2

Misses in library cache during parse: 3
Misses in library cache during execute: 1

위와 같은 형식으로 되어 있으며 call통계 각각의 의미를 살펴보겠습니다.

 

항목설명

call	커서 상태에 따라 Parse, Execute, Fetch 세 개의 Call로 나누어 각각에 대한 통계정보를 보여줌 - Parse : 커서를 파싱하고 실행계획을 생성하는 데 대한 통계 - Execute : 커서의 실행 단계에 대한 통계 - Fetch : 레코드를 실제로 Fetch하는 데 대한 통계
count	Parse, Execute, Fetch 각 단계가 수행된 횟수
cpu	현재 커서가 각 단계에서 사용한 cpu time
elapsed	현재 커서가 각 단계를 수행하는 데 소요된 시간
disk	디스크로부터 읽은 블록 수
query	Consistent 모드에서 읽은 버퍼 블록 수
current	Current모드에서 읽은 버퍼 블록수
rows	각 단계에서 읽거나 갱신한 처리건수

Autotrace 결과와 일치하는 항목과 비교해보면 다음과 같습니다.

 

실행 통계Call

db block gets	current
consistent gets	query
physical reads	disk
SQL*Net roundtrips to/from client	fetch count
rows processed	fetch rows

 

이벤트 트레이스

오라클은 오래전부터 다양한 종류의 이벤트 트레이스를 제공해왔고, 이를 통해서도 SQL트레이스를 걸 수 있습니다.

 

SQL> alter session set events '10046 trace name context forever, level 1';

SQL> alter session set events '10046 trace name context off';

 

이 방식을 사용하면 레벨 설정을 통해 바인드 변수와 대기 이벤트 발생 현황까지 수집할 수 있습니다. 설정할 수 있는 레벨 값은 1, 4, 8, 12이며, 레벨 1은 지금까지 살펴본 일반적인 SQL트레이스와 같습니다.

10046 트레이스를 걸때 레벨을 4이상으로 설정하면 트레이스 파일이 급격하게 커지므로 주의가 필요합니다. 계속 모니터링하다가 적정시점에 정지시키는 것을 잊지말아야 합니다.

 

Elapsed time=CPU time + Wait time

Elapsed time= Response시점 - Call 시점

Elapsed time은 Call 단위로 측정이 이루어집니다. 사용자로부터 데이터베이스 Call을 받은 순간부터 Response를 보내는 순간까지의 소요시간을 말합니다.

또 애플리케이션 커서 캐싱기법을 사용하지 않는 한 하나의 SELECT문을 수행하는 동안 최소 3번의 Call이 발생하고, DML문은 단 2번의 Call이 발생합니다.

SELECT문 = Parse Call + Execute Call + Fetch Call

DML문 = Parse Call + Execute Call

 

SELECT문에서 다량의 데이터를 사용자에게 전송할 때는 Fetch Call이 전송 레코드건수/Array Size 만큼 여러번 발생합니다. 따라서 하나의 SQL을 수행할 때의 Total Elapsed time은 수행시 발생하는 모든 Call의 Elapsed time을 더해서 구합니다.

 

SQL> set timing on
SQL> set arraysize 100
SQL> alter session set events '10046 trace name context forever, level 8';

SQL> alter session set tracefile_identifier='ysbbb';

SQL> select * from dba_objects where rownum <= 1000;

...
1000 rows selected.

Elapsed: 00:00:00.57

 

사용자가 느끼는 쿼리를 받는데 걸린 시간은 0.57초입니다.

 

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       11      0.00       0.00          0         30          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.03       0.03          0         30          0        1000

 

call 통계를 보면 DB 구간에서의 소요시간은 0.03초입니다.

Fetch가 11번 발생한 이유는 arraysize가 100이기 때문에 100건 -> 다시 fetch 후 100건 형식으로 Fetch했기 때문이고, one-row fetch까지 합쳐서 11번이 되는것입니다.

DB는 0.03초만 일을 했고 나머지 기산은 IDLE로 대기한 시간이 됩니다.

 

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

 

대기이벤트를 보면 SQL*Net message from client이벤트에서 대부분의 시간을 대기하였습니다.

 

이론적으로는 Elapsed time이 CPU time과 Wait time을 더한 값이지만 반올림하여 수치를 사용하기 때문에 항상 오차가 발생합니다.

 

10046 이벤트 트레이스 다음으로 많이 사용하는 것이 10053 트레이스입니다. 이는 실행계획을 생성하는 CBO의사결정 과정을 추적하는 것을 가능케 하며 이를 통해 옵티마이저가 이상한 돌출 행동을 보이는 원인을 찾아낼 수 있는 경우가 있습니다.

 

(2) 다른 세션에 트레이스 걸기

성능 문제가 발생한 튜닝 대상 SQL목록을 이미 확보했다면 앞의 방법처럼 자신의 세션에 걸어서 정보를 수집해 분석을 진행하면 됩니다. 아직 튜닝 대상 SQL이 수집되지 않은 상황이라면 커넥션 Pool에 놓인 세션 또는 시스템 레벨로 트레이스를 걸어 SQL수행정보를 수집해야 합니다.

dbms_system을 사용하거나 dbms_monitor를 이용하여 사용할 수 있습니다.

 

serial 번호가 39번인  21번 세션에 대해 10046이벤트 트레이스를 레벨 12로 거는 명령어입니다.

SQL> exec dbms_system.set_ev(21,49,10046,12,'');

해제는 레벨 0으로 설정하면 됩니다.

SQL>  exec dbms_system.set_ev(21,49,10046,0,'');

 

dbms_monitor의 session_Trace_enable을 사용하여 트레이스를 활성화할 수 있습니다.

SQL>  begin
  2  dbms_monitor.session_trace_enable(
  3  session_id => 21,
  4  serial_num => 49,
  5  waits => TRUE,
  6  binds => TRUE);
  7* end;
 /

session_trace_disable을 사용하여 비활성화 할 수 있습니다.

SQL> begin
  2  dbms_monitor.session_trace_disable(
  3  session_id => 21,
  4  serial_num => 49);
  5  end;
  6  /

PL/SQL procedure successfully completed.

 

oradebug 명령어를 통해서도 트레이스를 걸 수 있으며, OSPID를 통해 걸 수 있습니다. OSPID가 6872번이라고 가정하겠습니다.(v$process의 spid입니다)

SQL> oradebug setospid 6972
Oracle pid: 36, Unix process pid: 6972, image: oracle@orcl (Q001)
SQL> oradebug unlimit <-- 트레이스 파일 크기 제한 없앰
Statement processed.
SQL> oradebug event 10046 trace name context forever, level 8

SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/orcl11g/orcl11g/trace/orcl11g_q001_6972.trc

 

트레이스를 해제하는 방법입니다.
SQL> oradebug event 10046 trace name context off
Statement processed.
SQL> oradebug close_trace
Statement processed.

 

시스템레벨로 전체 세션에 트레이스를 거는 방법입니다.

SQL> alter system set sql_trace=true

SQL> alter system set sql_trace=false

 

 

(3) Service,Module,Action 단위로 트레이스 걸기

10g부터 사용가능한 dbms_monitor 패키지를 통해 service,module,action 별로 트레이스를 설정하고 해제할 수 있게 되었습니다.

 

  1  select sid,service_name,module,action
  2  from v$session
  3* where service_name <> 'SYS$BACKGROUND'
SQL> /

       SID SERVICE_NAME MODULE ACTION 
---------- ----------------------------------------------------------------
        44 SYS$USERS sqlplus@orcl (TNS V1-V3)

 

접속 중인(백그라운드제외) 세션 확인 쿼리입니다. 현재 1개의 세션이 접속되어 있습니다.

 

service_name이 'CRM'인 세션에 모두 트레이스를 걸고 앞으로 새로 커넥션을 맺는 세션중에서 service_name이 CRM이면 자동으로 트레이스가 설정되는 명령어입니다.

SQL> begin
  2  dbms_monitor.serv_mod_act_trace_enable(
  3  service_name => 'CRM',
  4  module_name => dbms_monitor.all_modules,
  5  action_name => dbms_monitor.all_actions,
  6  waits => true,
  7  binds => true);
  8  end;
  9  /

PL/SQL procedure successfully completed.

 

제대로 설정됬는지 확인하는 쿼리입니다.

SQL> select primary_id service_name, qualifier_id1 module,qualifier_id2 action,waits,binds
  2  from dba_enabled_traces;

SERVICE_NAME MODULE ACTION   WAITS BINDS
----------------------------------------------------------------
CRM                                         TRUE  TRUE

 

 

트레이스를 해제하는 쿼리입니다.

 

SQL> begin
  dbms_monitor.serv_mod_act_trace_disable(
  service_name => 'CRM',
  module_name => dbms_monitor.all_modules,
  action_name => dbms_monitor.all_actions
  );
  end;
  / 

PL/SQL procedure successfully completed.

 

특정 module에만 트레이스를 거는 방법을 소개하겠습니다. 

우선 모듈을 임의로 설정합니다.

SQL> begin
  2  dbms_application_info.set_module(
  3  module_name => 'emp manager',
  4  action_name => 'select emp');
  5  end;
  6  /

 

1  select sid,service_name,module,action 
  2  from v$session 
  3* where service_name <> 'SYS$BACKGROUND' 
SQL> / 

       SID SERVICE_NAME MODULE ACTION 
---------- ---------------------------------------------------------------- 
        44 SYS$USERS emp manager select emp

 

현재 접속한 세션의 정보가 변경되었습니다.

이제 module emp manager인 세션에만 트레이스를 걸겠습니다. 건 후에는 emp manager인 이름의 세션에는 모두 트레이스가 자동 설정됩니다.(새로 커넥션을 맺는 세션 포함)

 

SQL>  begin
  dbms_monitor.serv_mod_act_trace_enable(
  service_name => 'CRM',
  module_name => 'emp manager',
  action_name => dbms_monitor.all_actions,
  waits => true,
  binds => true
  );
  end;
  / 

PL/SQL procedure successfully completed.

 

 

SQL> select primary_id service_name, qualifier_id1 module,qualifier_id2 action,waits,binds 
  2  from dba_enabled_traces; 

SERVICE_NAME MODULE ACTION   WAITS BINDS 
---------------------------------------------------------------- 
CRM       emp manager                 TRUE  TRUE

 

해제하는 쿼리입니다.

 

SQL> begin 
  dbms_monitor.serv_mod_act_trace_disable( 
  service_name => 'CRM', 
  module_name => 'emp manager', 
  action_name => dbms_monitor.all_actions
  ); 
  end; 
  / 

 

이제 action만 트레이스를 걸고 싶을때 쿼리입니다.(update emp라는 action)

 

action은 dbms_application_info.set_action('update emp') 와 같은 형식으로 지정해줘야 합니다.

 

SQL> begin 
  dbms_monitor.serv_mod_act_trace_enable( 
  service_name => 'CRM', 
  module_name => 'emp manager', 
  action_name => 'update emp',
  waits => true,
  binds => true
  ); 
  end; 
  / 

 

 

SQL> select primary_id service_name, qualifier_id1 module,qualifier_id2 action,waits,binds 
  2  from dba_enabled_traces; 

SERVICE_NAME MODULE ACTION   WAITS BINDS 
---------------------------------------------------------------- 
CRM       emp manager   update emp  TRUE  TRUE

 

지금까지 설명한 기능을 효과적으로 사용하기 위해서는 모든 프로그램 모듈 수행전에 dbms_application_info.set_module 프로시저를 한번씩 노출하도록 프로그램을 변경해야 합니다. 

SQL 단위로 set_action을 자주 수행하는 것은 시스템에 다소 부하를 줄 수 있으므로 배치프로그램에만 적용하는 것을 권장합니다

v$session 뷰에서 client_identifier 컬럼이 특정 값으로 설정된 세션에만 트레이스를 걸 수도 있습니다.

 

SQL> exec dbms_session.set_identifier('ysbae');

 

client_identifier가 ysbae로 설정된 세션에만 트레이스를 거는 쿼리입니다.

SQL> begin
  2  dbms_monitor.client_id_trace_enable(
  3  client_id => 'ysbae',
  4  waits => true,
  5  binds => true);
  6* end;
 /

PL/SQL procedure successfully completed.

 

dbms_monitor 패키지를 이용해 row source operation과 대기 이벤트 발생현황만 수집할 수 있는게 아니라 service,module,action 단위로 v$sesstat 통계정보를 수집하는 기능도 제공됩니다.

어떤 단위로 정보수집이 진행중인지 확인하려면 dba_enabled_aggregations 뷰를 이용합니다. service,module,action 별로 수집된 수행통계를 확인하려면 v$serv_mod_act_stats뷰를 이용합니다.

참고로 v$session에서 client_identifier 별로 수행통계를 수집할 때는 client_id_stat_enable과 client_id_stat_disable프로시저를 이용하고 확인은 v$client_Stats뷰를 이용합니다.