V$SESSION 뷰의 LAST_CALL_ET 및 SQL_EXEC_START 칼럼에 대한 명확한 이해

1. LAST_CALL_ET 및 SQL_EXEC_START 칼럼 개요


V$SESSION 뷰의 LAST_CALL_ET (Last Call Elapsed Time) 칼럼은 이름에서도 알 수 있듯이 마지막 콜을 수행한 후, 현재시점까지의 경과 시간을 제공합니다. 따라서 세션 상태가 ‘ACTIVE’ 라면 LAST_CALL_ET 칼럼에서 제공하는 수치는 최근에 수행한 SQL의 수행 시간이며, 세션 상태가 ‘INACTIVE’라면 IDLE 상태가 지속된 시간을 의미합니다. 따라서 현재 세션이 수행하는 SQL의 응답시간을 확인할 때나 INACTIVE 상태가 지속된 시간을 확인할 때 LAST_CALL_ET 칼럼은 매우 유용합니다.

하지만 LAST_CALL_ET 칼럼은 한가지 문제점이 있습니다. 해당 칼럼 값은 ‘MAIN CURSOR’ 기준으로 작동되므로 프로시저 내에서 수행되는 개별 SQL의 수행 시간을 파악하는 것이 불가능합니다. 즉, 프로시저 (MAIN CURSOR) 내의 개별 SQL (CHILID CURSOR)의 수행시간을 확인할 수 없다는 단점이 있었습니다.

오라클은 이러한 한계점을 보완하기 위해 11g 부터 SQL_EXEC_START 칼럼을 제공합니다. SQL_EXEC_START 칼럼은 ‘MAIN CURSOR’ 기준이 아닌, 매 SQL 수행 시작 시간을 제공하므로 프로시저 내에서 수행되는 개별 SQL의 수행 시간을 확인할 수 있습니다. 그림-1을 보면서 파악해보도록 하겠습니다.

2. 간단한 예제 수행 결과 비교


그림-1. LAST_CALL_ET 칼럼 및 SQL_EXEC_START 칼럼 비교

%ec%84%b1%eb%8a%a55-1

표-1. 비교표

구분 LAST_CALL_ET (SYSDATE-SQL_EXEC_START)*86400
프로시저인 경우 Procedure 수행 시작부터 현재까지의 경과 시간을 제공 Procedure 내의 개별 쿼리에 대한 경과 시간을 제공
단순 SQL인 경우 SQL 수행 시작부터 현재까지의 경과 시간을 제공 좌동
INACTIVE 상태인 경우 IDLE 상태가 지속된 시간을 제공 NULL

3. 테스트 방법


3-1. 프로시저 생성

create or replace procedure proc_call_time_test
is
v_cnt1 number;
v_cnt2 number;
begin
    for i in 1..1000 loop
           for j in 1..1000 loop
              select count(*) into v_cnt1 from t1;
                  select count(*) into v_cnt2 from t2;
           end loop;
        end loop;
end;
/

3-2. 모니터링 쿼리 작성

set serveroutput on
set verify off
define __SID=&1;

begin
print_table('SELECT a.sid ,
       b.value exec_cnt ,
       a.last_call_et ,
       ( sysdate- a.sql_exec_start ) *86400 sql_exec_time ,
       SUBSTR( d.sql_text , 1 , 100 ) sql_text,
       d.program_id ,
       d.program_line#
FROM   v$session a ,
       v$sesstat b ,
       v$statname c ,
       v$sql d
WHERE  a.sid=&__SID
AND    a.sid=b.sid
AND    b.statistic#=c.statistic#
AND    c.name=''execute count''
AND    a.sql_id=d.sql_id
AND    a.sql_child_number=d.child_number');
end;
/

3-3. 모니터링 결과 확인

SCOTT@OOW1:1> @mon_1_sess_ela 214

SID                           : 214
EXEC_CNT                      : 429
LAST_CALL_ET                  : 37
SQL_EXEC_TIME                 : 4 ------------> 해당 SQL의 수행 시간은 4초임을 알 수 있음
SQL_TEXT                      : SELECT COUNT(*) FROM T1
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 8
-----------------

PL/SQL procedure successfully completed.

SCOTT@OOW1:1> @mon_1_sess_ela 214
SID                           : 214
EXEC_CNT                      : 430
LAST_CALL_ET                  : 38
SQL_EXEC_TIME                 : 1  -------------> 새로운 SQL 수행 시점에 값이 재 설정됨
SQL_TEXT                      : SELECT COUNT(*) FROM T2
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 9
-----------------

PL/SQL procedure successfully completed.

SCOTT@OOW1:1> @mon_1_sess_ela 214
SID                           : 214
EXEC_CNT                      : 431
LAST_CALL_ET                  : 39
SQL_EXEC_TIME                 : 1  ------------> 새로운 SQL 수행 시점에 값이 재 설정됨
SQL_TEXT                      : SELECT COUNT(*) FROM T1
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 8
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s