오라클 성능 트러블슈팅의 기초 (2012년)
목록
대기 이벤트를 포함한 SQL 트레이스 0 0 41,544

by 구루비스터디 10046 DBMS_MONITOR 대기이벤트 sql_trace [2023.09.06]

대기 이벤트를 포함한 SQL 트레이스

대기 이벤트 정보 해석

  • 대기 이벤트를 포함한 SQL 트레이스를 수행하면 서버 프로세스의 트레이스 파일에 다음과 같은 형태의 정보가 기록됨


PARSING IN CURSOR #3 len=55 dep=0 uid=5 oct=3 lid=5 tim=5040802286 hv=3040155827 ad='3822919c' sqlid='6byknukuma65m'
SELECT /* 10046 */
       COUNT(*)
FROM   USER_OBJECTS
END OF STMT
PARSE #3:c=0,e=159566,p=0,cr=303,cu=0,mis=1,r=0,dep=0,og=1,plh=1218565518,tim=5040802282
EXEC #3:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1218565518,tim=5040802554
WAIT #3: nam='SQL*Net message to client' ela= 12 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5040802702
FETCH #3:c=46875,e=44796,p=0,cr=983,cu=0,mis=0,r=1,dep=0,og=1,plh=1218565518,tim=5040847567
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=983 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=534 pid=1 pos=1 obj=3187 op='VIEW  USER_OBJECTS (cr=983 pr=0 pw=0 time=42853 us cost=252 size=0 card=520)'
STAT #3 id=3 cnt=534 pid=2 pos=1 obj=0 op='UNION-ALL  (cr=983 pr=0 pw=0 time=39868 us)'
STAT #3 id=4 cnt=534 pid=3 pos=1 obj=0 op='FILTER  (cr=982 pr=0 pw=0 time=34431 us)'
STAT #3 id=5 cnt=556 pid=4 pos=1 obj=0 op='HASH JOIN  (cr=911 pr=0 pw=0 time=8658 us cost=252 size=58380 card=556)'
STAT #3 id=6 cnt=93 pid=5 pos=1 obj=47 op='INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=276 us cost=1 size=2046 card=93)'
STAT #3 id=7 cnt=556 pid=5 pos=2 obj=18 op='TABLE ACCESS FULL OBJ$ (cr=910 pr=0 pw=0 time=2775 us cost=250 size=46148 card=556)'
STAT #3 id=8 cnt=210 pid=4 pos=2 obj=19 op='TABLE ACCESS BY INDEX ROWID IND$ (cr=71 pr=0 pw=0 time=0 us cost=2 size=8 card=1)'
STAT #3 id=9 cnt=232 pid=8 pos=1 obj=41 op='INDEX UNIQUE SCAN I_IND1 (cr=25 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
STAT #3 id=10 cnt=0 pid=4 pos=3 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=29 card=1)'
STAT #3 id=11 cnt=0 pid=10 pos=1 obj=47 op='INDEX FULL SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)'
STAT #3 id=12 cnt=0 pid=10 pos=2 obj=39 op='INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=9 card=1)'
STAT #3 id=13 cnt=0 pid=3 pos=2 obj=137 op='INDEX RANGE SCAN I_LINK1 (cr=1 pr=0 pw=0 time=0 us cost=0 size=13 card=1)'
WAIT #3: nam='SQL*Net message from client' ela= 262 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5040848228
FETCH #3:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1218565518,tim=5040848266
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5040848290
WAIT #3: nam='SQL*Net message from client' ela= 2596 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5040850902


  • 트레이스 파일 해석 방법 정리
구분설명
수행단계SOL 트레이스 파일은 SOL 수행의 단계를 PARSE. EXEC. FETCH 로 나누고 각 단계에서의 시간 정보를 제공함
문장번호각 SOL 문장은 SOL 트레이스 파일내에서 번호를 부여받습니다 가령 PARSING IN CURSOR #6 은 6 번 커서에 대한 정보라는 것을 의미함
cCPU 사용 시간을 의미하며, 단위는 1/1 ,000,000 초
e수행 시간( Elapsed Time)을 의미하며, 단위는 1/ 1,000,000 초
p물리적 읽기 (Physical Reads)로 읽은 블록 수를 의미함
cr일관된 읽기 (Consistent Read)로 읽은 블록 수를 의미함
cu현재 읽기 (Current Read)로 읽은 블록 수를 의미함
mis공유 풀(Shared Poll)이에서 미스(Miss)가 발생한 회수를 의미하며, 가렁 하드 파스가 발생한다먼 mis=1 로 표헌됨
r페치한 로우 수(Rows)를 의미함
dep재귀 깊이 (Recursive Oepth)를 의미함
og옵티마이저 목표(Optimizer Goal)를 의미함
tim현재 시간을 의미함


  • SQL 트레이스 활성화 시 대기 이벤트 정보를 포함시키면, PARSE, EXEC, FETCH의 각 단계 를 실 행하는 도중에 대기가 발생할 때마다 WAIT 정보를 추가적으로 기록하는데, WAIT 정보를 해석하는 방법은 다음과 같음
구분설명
nam대기 이벤트 이름을 의미함
ela대기 시간을 의미함
p1, p2, p3p1 , p2, p3 에 해당하는 정보가 기록되며, direct path read 대기 이벤트라면 p1=file number, p2=first dba, p3=block cnt 가 됨
obj#현재 읽고 있는 오브젝트의 10 를 의미하며, 'direct path read' 대기 이벤트라면 읽기 대상이 되는 테이블의 데이터 오브젝트 아이디(DBA_OBJECTS.DATA_OBJECT_ID)를 의미함


SQL 트레이스 수행

  • 대기 이벤트를 포함한 SQL 트레이는 매우 중요하기 때문에, 다양한 방법으로 파일 생성이 가능하며, 대표적인 방법은 아래와 같음
▶ 10046 진단 이벤트
▶ sql_trace 진단 이벤트
▶ DBMS_MONITOR 패키지
▶ DBMS_SYSTEM 패키지


10046 진단 이벤트
  • 10046 진단 이벤트를 레벨 8 이상으로 수행하면 SQL 수행 시마다 대기 이벤트가 포함된 SQL 트레이스 정보가 트레이스 파일에 기록됨
소스코드

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

SELECT /* 10046 */
       COUNT(*)
FROM   USER_OBJECTS
;

alter session set events '10046 trace name context off' ;
수행내역

KENZO:xsoftdb:SYSTEM >
  1  alter session set events '10046 trace name context forever , level 8';

세션이 변경되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* 10046 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events '10046 trace name context off' ;

세션이 변경되었습니다.


sql_trace 진단 이벤트
  • 오라클 11g에서는 개선된 형태의 진단 이벤트 기능이 제공되는데, 10046 이라는 의미없는 숫자 대신 SQL_TRACE 라는 인식 가능한 이름을 사용할 수 있음
소스코드

alter session set events 'sql_trace level 8' ;

SELECT /* SQ1 TRACE_1 */
       COUNT(*)
FROM   USER_OBJECTS
;

alter session set events 'sql_trace off';
수행내역

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace level 8' ;

세션이 변경되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQ1 TRACE_1 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace off'
  2  ;

세션이 변경되었습니다.


  • 레벨 값 역시 의미없는 숫자 대신 WAIT=TRUE 와 같이 명시적인 파라미터 이름을 사용할 수 있음
소스코드

alter session set events 'sql_trace wait=true';

SELECT /* SQL TRACE_2 */
       COUNT(*)
FROM   USER_OBJECTS
;

alter session set events 'sql_trace off';
수행내역

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace wait=true';

세션이 변경되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL TRACE_2 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace off';

세션이 변경되었습니다.


  • WAIT=TRUE, BIND=TRUE 와 같이 WAIT 파라미터와 BIND 파라미터 값을 모두 TRUE로 지정하면, 10046 진단 이벤트를 레벨 12 로 수행한 것과 동일함.
소스코드

alter session set events 'sql_trace wait=true, bind=true';

SELECT /* SQL TRACE 3 */
       COUNT(*)
FROM   USER_OBJECTS
;

alter session set events 'sql_trace off';
수행내역

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace wait=true, bind=true';

세션이 변경되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL TRACE 3 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace off';

세션이 변경되었습니다.


  • Oracle l1g에서는, 특정 SQL 에 대해서만 SQL_TRACE 이벤트를 수행할 수도 있으며 SQL_ID 값으로 파일 생성 가능함
소스코드

-- 1. SQL_ID 수집
SELECT /* SQL TRACE 4 */
       COUNT(*)
FROM   USER_OBJECTS
;

SELECT /* SQL_TRACE_5 */
       COUNT(*)
FROM   USER_OBJECTS
;

col sql_id new_value sql_id1

SELECT SQL_ID
FROM   V$SQLAREA
WHERE  SQL_TEXT LIKE 'SELECT /* SQL_TRACE_4 */%'
;

col sql_id new_value sql_id2

SELECT SQL_ID
FROM   V$SQLAREA
WHERE  SQL_TEXT LIKE 'SELECT /* SQL_TRACE_5 */%'
;

-- 2. SQL_ID로 트레이스 수집
-- 여러 SQL 문장에 대해 수집하려면 "|" 문자를 이용해 SQL_ID를 열거함
alter session set events 'sql_trace [sql: &sql_id1 | &sql_id2] wait=true';

SELECT /* SQL TRACE 4 */
       COUNT(*)
FROM   USER_OBJECTS
;

SELECT /* SQL_TRACE_5 */
       COUNT(*)
FROM   USER_OBJECTS
;

alter session set events 'sql_trace off';
수행내역

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL TRACE 4 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL_TRACE_5 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

KENZO:xsoftdb:SYSTEM >
  1  col sql_id new_value sql_id1

KENZO:xsoftdb:SYSTEM >
  1  SELECT SQL_ID
  2  FROM   V$SQLAREA
  3  WHERE  SQL_TEXT LIKE 'SELECT /* SQL_TRACE_4 */%'
  4  ;

SQL_ID
-------------
fyc2kv3tz74dr

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  col sql_id new_value sql_id2

KENZO:xsoftdb:SYSTEM >
  1  SELECT SQL_ID
  2  FROM   V$SQLAREA
  3  WHERE  SQL_TEXT LIKE 'SELECT /* SQL_TRACE_5 */%'
  4  ;

SQL_ID
-------------
81d01sanfsxy2

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace [sql: &sql_id1 | &sql_id2] wait=true';

세션이 변경되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL TRACE 4 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* SQL_TRACE_5 */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  alter session set events 'sql_trace off';

세션이 변경되었습니다.


  • oradebug를 사용해서 트레이스 수집도 가능함
소스코드

-- 1. SPID 바인딩
CONNECT /AS SYSDBA

col spid new_value spid

SELECT P.SPID
FROM   V$PROCESS   P,
       V$SESSION   S,
       V$PARAMETER PARA
WHERE  P.ADDR = S.PADDR
AND    S.AUDSID = USERENV('SESSIONID')
AND    PARA.NAME = 'db_name'
;

-- 2. oradebug로 활성화
oradebug setospid &spid


  • oradebug event 명령을 이용해서 10046 이벤트를 레벨 8로 수행 가능
소스코드

oradebug event 10046 trace name context forever, level 8

...

oradebug event 10046 trace name context OFF


  • 오라클 11g부터 SQL_TRACE 이벤트 사용 가능
소스코드

oradebug event sq1 trace wait=true ;

...

oradebug event sql_trace off;


DBMS_MONITOR 패키지
  • 오라클이 공식적으로 추천하는 SQL 트레이스 수행방법은 DBMS_MONITOR 패키지를 이용하는 것
소스코드

-- 1. 트레이스 활성화
col sid new_value sid

col serial# new_value se

SELECT SID,
       SERIAL#
FROM   V$SESSION
WHERE  SID = USERENV('SID')
;

exec dbms_monitor.session_trace_enable (&sid, &se, waits=>true, binds=>true);

SELECT /* DBMS MONITOR */
       COUNT(*)
FROM   USER_OBJECTS
;

-- 2. 트레이스 비활성화
exec dbms_monitor.session_trace_disable (&sid, &se);
수행내역

KENZO:xsoftdb:SYSTEM >
  1  col sid new_value sid

KENZO:xsoftdb:SYSTEM >
  1  col serial# new_value se

KENZO:xsoftdb:SYSTEM >
  1  SELECT SID,
  2         SERIAL#
  3  FROM   V$SESSION
  4  WHERE  SID = USERENV('SID')
  5  ;

       SID    SERIAL#
---------- ----------
        27        130

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  exec dbms_monitor.session_trace_enable (&sid, &se, waits=>true, binds=>true);

PL/SQL 처리가 정상적으로 완료되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* DBMS MONITOR */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
       534

1 개의 행이 선택되었습니다.

KENZO:xsoftdb:SYSTEM >
  1  exec dbms_monitor.session_trace_disable (&sid, &se);

PL/SQL 처리가 정상적으로 완료되었습니다.


DBMS_SYSTEM 패키지
  • 오라클 10g 이전에는 현재 세션이 아닌 다른 세션에 대해 SQL 트레이스를 수행하려면 DBMS_SYSTEM 패키지를 사용하거나 oradebug를 사용해야 함.
  • 문제는 DBMS_SYSTEM 패키지와 oradebug는 오라클이 공식적으로 지원하는 방법이 아니기 때문에, 문제가 될 경우 책임지지 않음
  • 그러므로, 가급적 DBMS_MONITOR 패키지 이용하는 것이 좋음
소스코드

-- 1. 트레이스 활성화
col sid new_value sid

col serial# new_value se

SELECT SID,
       SERIAL#
FROM   V$SESSION
WHERE  SID = USERENV('SID')
;

exec sys.dbms_system.set_ev (&sid, &se, 10046, 8, null) ;

-- 2. 트레이스 수행
SELECT /* DBMS MONITOR */
       COUNT(*)
FROM   USER_OBJECTS
;

-- 3. 트레이스 비활성화
exec sys.dbms_system.set_sql_trace_in_session(&sid, &se, false) ;
수행내역

KENZO:xsoftdb:SYSTEM >
  1  col sid new_value sid

KENZO:xsoftdb:SYSTEM >
  1  col serial# new_value se

KENZO:xsoftdb:SYSTEM >
  1  SELECT SID,
  2         SERIAL#
  3  FROM   V$SESSION
  4  WHERE  SID = USERENV('SID')
  5  ;

       SID    SERIAL#
---------- ----------
      9690         85

1 row selected.

KENZO:xsoftdb:SYSTEM >
  1  exec sys.dbms_system.set_ev (&sid, &se, 10046, 8, null) ;

PL/SQL procedure successfully completed.

KENZO:xsoftdb:SYSTEM >
  1  SELECT /* DBMS MONITOR */
  2         COUNT(*)
  3  FROM   USER_OBJECTS
  4  ;

  COUNT(*)
----------
    273754

1 row selected.

KENZO:xsoftdb:SYSTEM >
  1  exec sys.dbms_system.set_sql_trace_in_session(&sid, &se, false) ;

PL/SQL procedure successfully completed.
"데이터베이스 스터디모임" 에서 2012년에 "오라클 성능 트러블슈팅의 기초 " 도서를 스터디하면서 정리한 내용 입니다.

- 강좌 URL : http://www.gurubee.net/lecture/4299

- 구루비 강좌는 개인의 학습용으로만 사용 할 수 있으며, 다른 웹 페이지에 게재할 경우에는 출처를 꼭 밝혀 주시면 고맙겠습니다.~^^

- 구루비 강좌는 서비스 제공을 위한 목적이나, 학원 홍보, 수익을 얻기 위한 용도로 사용 할 수 없습니다.

목록
댓글등록
SQL문을 포맷에 맞게(깔끔하게) 등록하려면 code() 버튼을 클릭하여 작성 하시면 됩니다.
로그인 사용자만 댓글을 작성 할 수 있습니다. 로그인, 회원가입