2. V$SESSION_WAIT 뷰 & V$SESSION_EVENT 뷰
* 수행 시간 = CPU 사용 시간 + 대기 시간
Event Waits Time(s) (ms) time Wait Class
------------------------------- ---------- ------- -------- ------- ---------------
enq: TX - row lock contention 4 82 18007 47.9 Applicatio
db file scattered read 391 16 40 10.5 User I/O
db file sequential read 2,140 12 5 7.8 User I/O
DB CPU 2 1.2
control file sequential read 105 1 5 .3 System I
* V$EVENT_NAME 뷰
* V$SESSION_WAIT 뷰
* V$SESSION_EVENT 뷰
* V$EVENT_HISTOGRAM 뷰
* AWR view
* 대기 이벤트를 포함한 SQL 트레이스
DESC V$EVENT_NAME
;
Name Null? Type
--------------- -------- ---------------
EVENT# NUMBER
EVENT_ID NUMBER
NAME VARCHAR2(64)
PARAMETER1 VARCHAR2(64)
PARAMETER2 VARCHAR2(64)
PARAMETER3 VARCHAR2(64)
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
| NAME | 대기 이벤트의 이름을 의미함. 보통 기다리는 원인을 이름으로 사용함. |
| PARAMETER1 | 어떤 자원을 획득하려고 대기하는지에 대한 정보 #1 |
| PARAMETER2 | 어떤 자원을 획득하려고 대기하는지에 대한 정보 #2 |
| PARAMETER3 | 어떤 자원을 획득하려고 대기하는지에 대한 정보 #2 |
| WAIT_CLASS | 대기 이벤트의 분류 |
'PARAMETER1, PARAMETER2, PARAMETER3'으로 이루어진 자원을 획득하려고 하지만, NAME이라는 이유로 인해 획득하지 못하고 대기함.
| 소스코드 | {code:SQL} – 1. 오라클 버전 SELECT * FROM v$version; |
– 2. 대기이벤트 종류
SELECT WAIT_CLASS,
COUNT(*)
FROM V$EVENT_NAME
GROUP BY WAIT_CLASS
ORDER BY 2 DESC;
|
|수행내역|{code:SQL}
KENZO:xsoftdb:SYSTEM >
1 SELECT *
2 FROM v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
PL/SQL Release 11.2.0.1.0 - Production
CORE 11.2.0.1.0 Production
TNS for 32-bit Windows: Version 11.2.0.1.0 - Production
NLSRTL Version 11.2.0.1.0 - Production
KENZO:xsoftdb:SYSTEM >
1 SELECT WAIT_CLASS,
2 COUNT(*)
3 FROM V$EVENT_NAME
4 GROUP BY WAIT_CLASS
5 ORDER BY 2 DESC;
WAIT_CLASS COUNT(*)
---------------------------------------------------------------- ----------
Other 717
Idle 94
Administrative 54
Cluster 50
User I/O 45
Network 35
Concurrency 32
System I/O 30
Configuration 24
Application 17
Queueing 9
Scheduler 7
Commit 2
|
| 소스코드 | {code:SQL} BEGIN PRINT_TABLE('SELECT * FROM V$EVENT_NAME WHERE NAME = ''db file sequential read'''); END ; {code} |
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 BEGIN 2 PRINT_TABLE('SELECT * 3 FROM V$EVENT_NAME 4 WHERE NAME = ''db file sequential read'''); 5 END 6 ; 7 / EVENT# : 143 EVENT_ID : 2652584166 NAME : db file sequential read PARAMETER1 : file# PARAMETER2 : block# PARAMETER3 : blocks WAIT_CLASS_ID : 1740759767 WAIT_CLASS# : 8 WAIT_CLASS : User I/O --- {code} |
CREATE OR REPLACE PROCEDURE PRINT_TABLE(P_QUERY IN VARCHAR2) AUTHID CURRENT_USER IS
l_theCursor INTEGER DEFAULT DBMS_SQL.OPEN_CURSOR;
l_columnValue VARCHAR2(4000);
l_status INTEGER;
l_descTbl DBMS_SQL.DESC_TAB;
l_colCnt NUMBER;
BEGIN
DBMS_SQL.PARSE(l_theCursor, p_query, DBMS_SQL.NATIVE);
DBMS_SQL.DESCRIBE_COLUMNS(l_theCursor, l_colCnt, l_descTbl);
FOR i IN 1..l_colCnt LOOP
DBMS_SQL.DEFINE_COLUMN(l_theCursor, i, l_columnValue, 4000);
END LOOP;
l_status := DBMS_SQL.EXECUTE(l_theCursor);
WHILE(DBMS_SQL.FETCH_ROWS(l_theCursor) > 0) LOOP
FOR i IN 1..l_colCnt LOOP
DBMS_SQL.COLUMN_VALUE(l_theCursor, i, l_columnValue);
DBMS_OUTPUT.PUT_LINE(RPAD(l_descTbl(i).col_name, 30) || ': ' || l_columnValue);
END LOOP;
DBMS_OUTPUT.PUT_LINE('---------------------------------------------------------------------------');
END LOOP;
DBMS_SQL.CLOSE_CURSOR(l_theCursor);
EXCEPTION
WHEN OTHERS THEN
RAISE;
END;
/
DESC V$SESSION_WAIT
;
Name Null? Type
--------------------- -------- -----------------
SID NUMBER
SEQ# NUMBER
EVENT VARCHAR2(64)
P1TEXT VARCHAR2(64)
P1 NUMBER
P1RAW RAW(8)
P2TEXT VARCHAR2(64)
P2 NUMBER
P2RAW RAW(8)
P3TEXT VARCHAR2(64)
P3 NUMBER
P3RAW RAW(8)
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
WAIT_TIME NUMBER
SECONDS_IN_WAIT NUMBER
STATE VARCHAR2(19)
WAIT_TIME_MICRO NUMBER
TIME_REMANING_MICRO NUMBER
TIME_SINCE_LAST_WAIT_MICRO NUMBER
| EVENT | 대기 이벤트 ex) db file sequeitial read |
| P1, P1RAW | PARAMETER1의 값 |
| P2, P2RAW | PARAMETER2의 값 |
| P3, P3RAW | PARAMETER3의 값 |
| P1TEXT, P2TEXT, P3TEXT | V$EVENT_NAME 뷰의 PARAMETER1, PARAMETER2, PARAMETER3 값과 동일 |
| WAIT_CLASS | 대기 이벤트의 종류 ex) User I/O |
| WAIT_TIME | 가장 최근의 대기 시간. STATE 컬럼의 값이 WAITED KNOWN TIME 일 경우에만 의미를 가짐. 단위는 1/100초이며, 11g부터 WAIT_TIME_MICRO 컬럼으로 대체됨 |
| SECONDS_IN_WAIT | 현재 대기시간. STATE 컬럼의 값이 WAITING일 경우에만 의미를 가짐. 단위는 1초이며, 11g부터 WAIT_TIME_MICRO 컬럼과 TIME_SINCE_LAST_WAIT_MICRO 컬럼으로 대체됨 |
| STATE | 대기 상태. 이 컬럼의 값이 WAITING일 경우에만 실제 대기하고 있는 중임 |
| WAIT_TIME_MICRO | STATE 컬럼의 값이 WAITING일 경우에는 현재 대기 시간을, 그렇지 않을 경우에는 가장 최근의 대기 시간을 의미 |
| TIME_SINCE_LAST_WAIT_MICRO | 가장 최근의 대기 이후 지난 시간을 의미함. STATE 컬럼의 값이 WAITING이 아닐 경우에만 의미가 있으며, 단위는 1/1,000,000 초임 |
| WAITING | 현재 실제로 대기하고 있는 중이라는 것을 의미함. 이 경우 SECOND_IN_WAIT 컬럼이나 WAIT_TIME_MICRO 컬럼의 값을 통해 현재 얼마나 대기하고 있는지 알 수 있음. |
| WAITED UNKNOWN TIME | 알수 없는 시간만큼 대기한 후 현재는 CPU를 점유하고 어떤 작업을 하고 있는 중이라는 것을 의미함. 최근 버전의 오라클에서 이 값은 관찰되지 않음 |
| WAITED SHORT TIME | 1/100초 이하의 짧은 시간을 대기한 후 현재는 CPU를 점유하고 어떤 작업을 하고 있는 중이라는 것을 의미함. 이 경우 WAIT_TIME_MICRO 컬럼 값을 통해 대기했던 시간을 알 수 있으며, 컬럼 값은 -1로 표시 |
| WAITED KNOWN TIME | 1/100초 이상의 시간을 대기한 후 현재는 CPU를 점유하고 어떤 작업을 하고 있는 중이라는 것을 의미함 WAIT_TIME 컬럼과 WAIT_TIME_MICRO 컬럼의 값을 통해 대기했던 시간을 알 수 있음 |
원칙은 STATE 컬럼의 값이 WAITING 일 경우, 즉 실제로 현재 대기하고 있는 중일 경우에만 V$SESSION_WAIT 뷰를 사용하고, 대기 시간은 SECONDS_IN_WAIT 컬럼이나 WAIT_TIME_MICRO 컬럼을 통해 얻는다.
DESC V$SESSION_EVENT
;
Name Null? Type
-------------------- -------- ----------------
SID NUMBER
EVENT VARCHAR2(64)
TOTAL_WAITS NUMBER
TOTAL_TIMEOUTS NUMBER
TIME_WAITED NUMBER
AVERAGE_WAIT NUMBER
MAX_WAIT NUMBER
TIME_WAITED_MICRO NUMBER
EVENT_ID NUMBER
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
| EVENT | 대기 이벤트 이름 ex) db file sequential read |
| TOTAL_WAITS | 전체 대기 회수 |
| TOTAL_TIMEOUTS | 전체 타임 아웃 회수 |
| TIME_WAITED | 전체 대기 시간. 1/100초 단위 |
| AVERAGE_WAIT | 평균 대기 시간. 1/100초 단위 |
| MAX_WAIT | 최대 대기 시간. 1/100초 단위 |
| TIME_WAITED_MICRO | 전체 대기 시간. 1/1,000,00초 단위 |
| WAIT_CLASS | 대기 이벤트의 종류 ex) User I/O |
| 소스코드 | {code:SQL} DROP TABLE T1 PURGE; |
CREATE TABLE T1(C1 NUMBER);
– 2. 데이터 생성
INSERT INTO T1 VALUES(1);
COMMIT;
– 3. TX Lock Holder
EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_1');
UPDATE T1 SET C1 = 1;
|
|수행내역|{code:SQL}
KENZO:xsoftdb:SYSTEM >
1 CREATE TABLE T1(C1 NUMBER);
테이블이 생성되었습니다.
KENZO:xsoftdb:SYSTEM >
1 INSERT INTO T1 VALUES(1);
1 개의 행이 만들어졌습니다.
KENZO:xsoftdb:SYSTEM >
1 COMMIT;
커밋이 완료되었습니다.
KENZO:xsoftdb:SYSTEM >
1 EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_1');
PL/SQL 처리가 정상적으로 완료되었습니다.
KENZO:xsoftdb:SYSTEM >
1 UPDATE T1 SET C1 = 1;
1 행이 갱신되었습니다.
|
| 소스코드 | {code:SQL} – 1. TX Lock Wait EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_2'); |
UPDATE T1 SET C1 = 1;
|
|수행내역|{code:SQL}
KENZO:xsoftdb:SYSTEM >
1 EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_2');
PL/SQL 처리가 정상적으로 완료되었습니다.
KENZO:xsoftdb:SYSTEM >
1 UPDATE T1 SET C1 = 1;
|
| 소스코드 | {code:SQL} – 1. Session #2 sid 획득 col sid new_value sid2 |
SELECT SID
FROM V$SESSION
WHERE CLIENT_INFO = 'session_2';
– 2. TX Lock 확인
SET serveroutput ON
BEGIN
FOR idx IN 1..100 LOOP
DBMS_LOCK.SLEEP(0.1);
PRINT_TABLE('SELECT ' || idx || ' AS NTH,
EVENT,
SEQ#,
P1,
P2,
P3,
TRUNC(WAIT_TIME / 100, 2) AS OLD_LAST_WAIT_TIME,
SECONDS_IN_WAIT OLD_CUR_WAIT_TIME,
STATE,
TRUNC(WAIT_TIME_MICRO / 1000000, 2) AS NEW_CUR_WAIT_TIME,
TRUNC(TIME_REMAINING_MICRO / 1000000, 2) AS NEW_REMAND_TIME,
TRUNC(TIME_SINCE_LAST_WAIT_MICRO / 1000000, 2) AS NEW_LAST_WAIT_TIME
FROM V$SESSION_WAIT
WHERE SID = &SID2');
END LOOP;
END;
/
|
|수행내역|{code:SQL}
KENZO:xsoftdb:SYSTEM >
1 col sid new_value sid2
KENZO:xsoftdb:SYSTEM >
1 SELECT SID
2 FROM V$SESSION
3 WHERE CLIENT_INFO = 'session_2';
SID
----------
15
1 개의 행이 선택되었습니다.
KENZO:xsoftdb:SYSTEM >
1 SET serveroutput ON
KENZO:xsoftdb:SYSTEM >
1 BEGIN
2 FOR idx IN 1..100 LOOP
3
4 DBMS_LOCK.SLEEP(0.1);
5
6 PRINT_TABLE('SELECT ' || idx || ' AS NTH,
7 EVENT,
8 SEQ#,
9 P1,
10 P2,
11 P3,
12 TRUNC(WAIT_TIME / 100, 2) AS OLD_LAST_WAIT_TIME,
13 SECONDS_IN_WAIT OLD_CUR_WAIT_TIME,
14 STATE,
15 TRUNC(WAIT_TIME_MICRO / 1000000, 2) AS NEW_CUR_WAIT_TIME,
16 TRUNC(TIME_REMAINING_MICRO / 1000000, 2) AS NEW_REMAND_TIME,
17 TRUNC(TIME_SINCE_LAST_WAIT_MICRO / 1000000, 2) AS NEW_LAST_WAIT_TIME
18 FROM V$SESSION_WAIT
19 WHERE SID = &SID2');
20
21 END LOOP;
22 END;
23 /
NTH : 1
EVENT : enq: TX - row lock contention
SEQ# : 72
P1 : 1415053318
P2 : 524316
P3 : 869
OLD_LAST_WAIT_TIME : 0
OLD_CUR_WAIT_TIME : 300
STATE : WAITING
NEW_CUR_WAIT_TIME : 299.68
NEW_REMAND_TIME : 0
NEW_LAST_WAIT_TIME : 0
---------------------------------------------------------------------------
NTH : 2
EVENT : enq: TX - row lock contention
SEQ# : 72
P1 : 1415053318
P2 : 524316
P3 : 869
OLD_LAST_WAIT_TIME : 0
OLD_CUR_WAIT_TIME : 300
STATE : WAITING
NEW_CUR_WAIT_TIME : 299.79
NEW_REMAND_TIME : 0
NEW_LAST_WAIT_TIME : 0
---------------------------------------------------------------------------
NTH : 3
EVENT : enq: TX - row lock contention
SEQ# : 72
P1 : 1415053318
P2 : 524316
P3 : 869
OLD_LAST_WAIT_TIME : 0
OLD_CUR_WAIT_TIME : 300
STATE : WAITING
NEW_CUR_WAIT_TIME : 299.9
NEW_REMAND_TIME : 0
NEW_LAST_WAIT_TIME : 0
---------------------------------------------------------------------------
...(중략)...
---------------------------------------------------------------------------
NTH : 99
EVENT : enq: TX - row lock contention
SEQ# : 72
P1 : 1415053318
P2 : 524316
P3 : 869
OLD_LAST_WAIT_TIME : 0
OLD_CUR_WAIT_TIME : 310
STATE : WAITING
NEW_CUR_WAIT_TIME : 310.39
NEW_REMAND_TIME : 0
NEW_LAST_WAIT_TIME : 0
---------------------------------------------------------------------------
NTH : 100
EVENT : enq: TX - row lock contention
SEQ# : 72
P1 : 1415053318
P2 : 524316
P3 : 869
OLD_LAST_WAIT_TIME : 0
OLD_CUR_WAIT_TIME : 311
STATE : WAITING
NEW_CUR_WAIT_TIME : 310.51
NEW_REMAND_TIME : 0
NEW_LAST_WAIT_TIME : 0
---------------------------------------------------------------------------
PL/SQL 처리가 정상적으로 완료되었습니다.
|
| 소스코드 | {code:SQL} SELECT EVENT, TOTAL_WAITS, TRUNC(TIME_WAITED / 100, 2) AS OLD_TIME_WAITED, TRUNC(TIME_WAITED_MICRO / 1000000, 2) AS NEW_TIME_WAITED FROM V$SESSION_EVENT WHERE SID = &SID2 ORDER BY 2 DESC, 3 DESC ; {code} |
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 SELECT EVENT, 2 TOTAL_WAITS, 3 TRUNC(TIME_WAITED / 100, 2) AS OLD_TIME_WAITED, 4 TRUNC(TIME_WAITED_MICRO / 1000000, 2) AS NEW_TIME_WAITED 5 FROM V$SESSION_EVENT 6 WHERE SID = &SID2 7 ORDER BY 2 DESC, 8 3 DESC 9 ; |
EVENT TOTAL_WAITS OLD_TIME_WAITED NEW_TIME_WAITED
4 개의 행이 선택되었습니다.
|
* V$SESSION_WAIT 뷰의 100번째에 해당하는 값이 V$SESSION_EVENT 뷰의 집계값과 거의 일치하는 것이 확인 가능함.
h3. 2-4) V$SESSION_WAIT 뷰 & V$SESSION_EVENT 뷰 비교_2
h5. 2-4-1) Session #1 TEMP.SQL 파일 호출
|소스코드|{code:SQL}
-- TEMP_T.SQL 파일 생성
BEGIN
FOR idx IN 1..50 LOOP
UPDATE T1
SET C1 = 1;
FOR REC_VAL IN (SELECT *
FROM USER_OBJECTS) LOOP
NULL;
END LOOP;
COMMIT;
DBMS_LOCK.SLEEP(0.1);
END LOOP;
END;
-- SESSION_ID 확인
SELECT S.SID
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'
;
-- TEMP_T.SQL 파일 호출
@TEMP_T;
|
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 SELECT S.SID 2 FROM V$PROCESS P, 3 V$SESSION S, 4 V$PARAMETER PARA 5 WHERE P.ADDR = S.PADDR 6 AND S.AUDSID = USERENV('SESSIONID') 7 AND PARA.NAME = 'db_name' 8 ; |
SID
1 개의 행이 선택되었습니다.
KENZO:xsoftdb:SYSTEM >
1 @TEMP_T;
19 /
PL/SQL 처리가 정상적으로 완료되었습니다.
|
h5. 2-4-2) Session #2 TEMP.SQL 파일 호출
* 세션_2에서 TEMP 파일 호출하여 row_level lock을 하도록 유도
|소스코드|{code:SQL}
-- CLIENT_INFO 설정
EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_2');
-- TEMP_T.SQL 파일 호출
@TEMP_T;
|
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO('session_2'); |
PL/SQL 처리가 정상적으로 완료되었습니다.
KENZO:xsoftdb:SYSTEM >
1 @TEMP_T;
19 /
PL/SQL 처리가 정상적으로 완료되었습니다.
|
h5. 2-4-3) Session #3
* 세션_1과 세션_2에서 작업을 수행하는 동안, 세션_3에서 세션_2의 상태 체크
|소스코드|{code:SQL}
SET serveroutput ON
-- 1. Session #2 sid 획득
col sid new_value sid2
SELECT SID
FROM V$SESSION
WHERE CLIENT_INFO = 'session_2';
-- 2. Session #2 모니터링
BEGIN
FOR idx IN 1..100 LOOP
DBMS_LOCK.SLEEP(0.1);
PRINT_TABLE('SELECT ' || idx || ' AS NTH,
EVENT,
SEQ#,
P1,
P2,
P3,
TRUNC(WAIT_TIME / 100, 2) AS OLD_LAST_WAIT_TIME,
SECONDS_IN_WAIT OLD_CUR_WAIT_TIME,
STATE,
TRUNC(WAIT_TIME_MICRO / 1000000, 2) AS NEW_CUR_WAIT_TIME,
TRUNC(TIME_REMAINING_MICRO / 1000000, 2) AS NEW_REMAND_TIME,
TRUNC(TIME_SINCE_LAST_WAIT_MICRO / 1000000, 2) AS NEW_LAST_WAIT_TIME
FROM V$SESSION_WAIT
WHERE SID = &SID2');
END LOOP;
END;
|
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 SET serveroutput ON |
KENZO:xsoftdb:SYSTEM >
1 col sid new_value sid2
KENZO:xsoftdb:SYSTEM >
1 SELECT SID
2 FROM V$SESSION
3 WHERE CLIENT_INFO = 'session_2';
SID
1 개의 행이 선택되었습니다.
KENZO:xsoftdb:SYSTEM >
1 BEGIN
2 FOR idx IN 1..100 LOOP
3
4 DBMS_LOCK.SLEEP(0.1);
5
6 PRINT_TABLE('SELECT ' || idx || ' AS NTH,
7 EVENT,
8 SEQ#,
9 P1,
10 P2,
11 P3,
12 TRUNC(WAIT_TIME / 100, 2) AS OLD_LAST_WAIT_TIME,
13 SECONDS_IN_WAIT OLD_CUR_WAIT_TIME,
14 STATE,
15 TRUNC(WAIT_TIME_MICRO / 1000000, 2) AS NEW_CUR_WAIT_TIME,
16 TRUNC(TIME_REMAINING_MICRO / 1000000, 2) AS NEW_REMAND_TIME,
17 TRUNC(TIME_SINCE_LAST_WAIT_MICRO / 1000000, 2) AS NEW_LAST_WAIT_TIME
18 FROM V$SESSION_WAIT
19 WHERE SID = &SID2');
20
21 END LOOP;
22 END;
23 /
– 1) enq: TX - row lock contention
-- 아쉽지만 V$SESSION_WAIT에서는 enq: TX - row lock contention 이벤트는 확인되지 않음
-- 하지만, V$SESSION_EVENT에서는 확인됨
-- 책의 내용을 옮기자면, SECOND_IN_WAIT 컬럼(OLD_CUR_WAIT_TIME) 값은 항상 0인데,
-- 대기 시간이 매우 짧기 때문에 초 단위의 값에는 반영이 안되고 있음
-- 하지만, TIME_WAIT_MICRO 컬럼(NEW_CUR_WAIT_TIME) 값은 약 0.1초 단위로 계속해서 증가하고 있으며,
– TIME_WAIT_MICRO 컬럼이 정확도가 훨씬 높은 것을 알 수 있음
– 2) direct path read
– direct path read 이벤트 또한 확인이 되지 않음 _;
-- 책의 내용을 옮기자면, oracle 11g부터는 버퍼 캐시에 비해 크기가 크다고 판단되는 테이블을 읽을 때,
-- 버퍼 캐시를 경유하지 않고 프로세스가 데이터파일에 직접 읽는 방식을 사용할 경우가 있으며,
-- 이것을 흔히 'Serial Direct Path Read'라고 한다.
-- 이 때, 대기 이벤트는 'direct path read'이며, 기존 direct path read로 동일 하지만 SEQ#, Pl, P2 의 값이 변경됨
– 3) PL/SQL lock timer
– DBMS.LOCK_SLEEP 프로시저를 이용해서 잠을 자는 동안 'PL/SQL lock timer' 이벤트 대기함
-- 이 이벤트 또한 V$SESSION_WAIT에서는 확인되지 않으며, V$SESSION_EVENT에서 확인됨
|
h5. 2-4-4) Session #3 V$SESSION_EVENT 확인
|소스코드|{code:SQL}
SELECT EVENT,
TOTAL_WAITS,
TRUNC(TIME_WAITED / 100, 2) AS OLD_TIME_WAITED,
TRUNC(TIME_WAITED_MICRO / 1000000, 2) AS NEW_TIME_WAITED
FROM V$SESSION_EVENT
WHERE SID = &SID2
ORDER BY 2 DESC,
3 DESC
;
|
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 SELECT EVENT, 2 TOTAL_WAITS, 3 TRUNC(TIME_WAITED / 100, 2) AS OLD_TIME_WAITED, 4 TRUNC(TIME_WAITED_MICRO / 1000000, 2) AS NEW_TIME_WAITED 5 FROM V$SESSION_EVENT 6 WHERE SID = &SID2 7 ORDER BY 2 DESC, 8 3 DESC 9 ; |
EVENT TOTAL_WAITS OLD_TIME_WAITED NEW_TIME_WAITED
7 개의 행이 선택되었습니다.
|
h1. 3. V$EVENT_HISTOGRAM view
h3. 1) V$SESSION_EVENT 한계
* 특정 대기 이벤트의 대기 회수가 100번이고, 대기시간은 1초라고 할 때, 평균 대기시간은 1/100=0.01초가 된다.
* 하지만 만약, 99번은 0.001초인데 1번이 0.9초일 경우, 평균은 0.01초이지만 특정 이벤트에 편중이 된 값임에도 불구하고 확인하기가 힘듬
* 이를 파악하기 위해, V$SESSION_EVENT 뷰에서 MAX_WAIT 컬럼을 제공하지만 완벽하게 파악하기는 힘듬
h3. 2) V$EVENT_HISTOGRAM 필요성
* V$EVENT_HISTOGRAM 뷰는, 대기이벤트 별 대기시간의 히스토그램 데이터를 제공함
|소스코드|{code:SQL}
SELECT WAIT_COUNT,
WAIT_TIME_MILLI
FROM V$EVENT_HISTOGRAM
WHERE EVENT = 'db file sequential read'
;
|
| 수행내역 | {code:SQL} KENZO:xsoftdb:SYSTEM > 1 SELECT WAIT_COUNT, 2 WAIT_TIME_MILLI 3 FROM V$EVENT_HISTOGRAM 4 WHERE EVENT = 'db file sequential read' 5 ; |
WAIT_COUNT WAIT_TIME_MILLI
11 개의 행이 선택되었습니다.
|
* 위의 결과를 보면 대기 시간이 1/1000초 이하인 경우, 50% 정도를 차지하지만 0.5초~1초(512 ~ 1024)에 해당되는 경우도 36건 정도가 발생된 것을 알 수 있음
* 만약, 대기 시간이 긴 구간에서의 대기 회수가 많다면 싱글 블록 I/O의 성능이 전반적으로 느리다고 판단할 수 있으며, 자칫하면 극단적인 성능 저하 현상을 불러올 수 있음
* 이 히스토그램 정보는 세션 레벨에서는 데이터를 제공하지 않고, 시스템 레벨에서만 사용할 수 있기 때문에, 특정 구간의 정보를 얻기 위해서는 V$EVENT_HISTOGRAM 뷰에 대한 스냅샷을 생성한 다음 차이(Delta) 값을 구헤야 하며, AWR 레포트를 이용할 경우 간편하게 얻을 수 있음
h1. 4. AWR
* AWR(Automatic Workoad Repository) 에서 대기 이벤트와 관련된 뷰들을 정리해보면 다음과 같음
|| AWR 뷰 ||
| ▶ DBA HIST ACTlVE SESS HISTORY
▶ DBA HIST BG EVENT SUMMARY
▶ DBA HIST EVENT HISTOGRAM
▶ DBA HIST EVENT NAME
▶ DBA HIST SERVICE WAIT CLASS
▶ DBA HIST SYSTE~l EVENT
▶ DBA HIST WAITCLASSMET HISTORY |
* AWR 데이터 를 시용할 때는 우선 AWR 리포트를 먼저 사용하고 필요한 경우에는 위의 뷰들을 직접 사용하면 된다.
h1. 5. 대기 이벤트를 포함한 SQL 트레이스
h3. 5-1) 대기 이벤트 정보 해석
* 대기 이벤트를 포함한 SQL 트레이스를 수행하면 서버 프로세스의 트레이스 파일에 다음과 같은 형태의 정보가 기록됨
{code: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 번 커서에 대한 정보라는 것을 의미함 |
| c | CPU 사용 시간을 의미하며, 단위는 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 | 현재 시간을 의미함 |
| 구분 | 설명 | ||
|---|---|---|---|
| nam | 대기 이벤트 이름을 의미함 | ||
| ela | 대기 시간을 의미함 | ||
| p1, p2, p3 | p1 , p2, p3 에 해당하는 정보가 기록되며, direct path read 대기 이벤트라면 p1=file number, p2=first dba, p3=block cnt 가 됨 | obj# | 현재 읽고 있는 오브젝트의 10 를 의미하며, 'direct path read' 대기 이벤트라면 읽기 대상이 되는 테이블의 데이터 오브젝트 아이디(DBA_OBJECTS.DATA_OBJECT_ID)를 의미함 |
| ▶ 10046 진단 이벤트 ▶ sql_trace 진단 이벤트 ▶ DBMS_MONITOR 패키지 ▶ DBMS_SYSTEM 패키지 |
| 소스코드 | {code: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' ;
|
|수행내역|{code:SQL}
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' ;
세션이 변경되었습니다.
|
| 소스코드 | {code:SQL} alter session set events 'sql_trace level 8' ; |
SELECT /* SQ1 TRACE_1 */
COUNT(*)
FROM USER_OBJECTS
;
alter session set events 'sql_trace off';
|
|수행내역|{code:SQL}
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 ;
세션이 변경되었습니다.
|
| 소스코드 | {code:SQL} alter session set events 'sql_trace wait=true'; |
SELECT /* SQL TRACE_2 */
COUNT(*)
FROM USER_OBJECTS
;
alter session set events 'sql_trace off';
|
|수행내역|{code:SQL}
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';
세션이 변경되었습니다.
|
| 소스코드 | {code:SQL} 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';
|
|수행내역|{code:SQL}
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';
세션이 변경되었습니다.
|
| 소스코드 | {code:SQL} – 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 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';
|
|수행내역|{code:SQL}
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';
세션이 변경되었습니다.
|
| 소스코드 | {code:SQL} – 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로 수행 가능
|소스코드|{code:SQL}
oradebug event 10046 trace name context forever, level 8
...
oradebug event 10046 trace name context OFF
|
| 소스코드 | {code:SQL} oradebug event sq1 trace wait=true ; |
...
oradebug event sql_trace off;
|
h5. 5-2-3) DBMS_MONITOR 패키지
* 오라클이 공식적으로 추천하는 SQL 트레이스 수행방법은 DBMS_MONITOR 패키지를 이용하는 것
|소스코드|{code:SQL}
-- 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);
|
| 수행내역 | {code:SQL} 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#
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(*)
1 개의 행이 선택되었습니다.
KENZO:xsoftdb:SYSTEM >
1 exec dbms_monitor.session_trace_disable (&sid, &se);
PL/SQL 처리가 정상적으로 완료되었습니다.
|
h5. 5-2-4) DBMS_SYSTEM 패키지
* 오라클 10g 이전에는 현재 세션이 아닌 다른 세션에 대해 SQL 트레이스를 수행하려면 DBMS_SYSTEM 패키지를 사용하거나 oradebug를 사용해야 함.
* 문제는 DBMS_SYSTEM 패키지와 oradebug는 오라클이 공식적으로 지원하는 방법이 아니기 때문에, 문제가 될 경우 책임지지 않음
* 그러므로, 가급적 DBMS_MONITOR 패키지 이용하는 것이 좋음
|소스코드|{code:SQL}
-- 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) ;
|
| 수행내역 | {code:SQL} 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#
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(*)
1 row selected.
KENZO:xsoftdb:SYSTEM >
1 exec sys.dbms_system.set_sql_trace_in_session(&sid, &se, false) ;
PL/SQL procedure successfully completed.
|
h2. 문서에 대하여
* 최초작성자 : [~xsoft]
* 최초작성일 : 2012년 04월 07일
* 이 문서는 [오라클클럽|http://www.gurubee.net] [오라클 성능 트러블슈팅의 기초 스터디|2012년 상반기 - 오라클 성능 트러블슈팅의 기초 스터디] 모임에서 작성하였습니다.
* {color:blue}{*}이 문서의 내용은 엑셈(EXEM) 에서 출간한 '오라클 성능 트러블슈팅의 기초'를 참고하였습니다.*{color}