순간적인(1~2분 사이) 과다 실행된 SQL 찾기

OS환경 : Oracle Linux 6.8 (64bit)

DB 환경 : Oracle Database 11.2.0.4

쿼리 : 순간적인(1~2분 사이) 과다 실행된 SQL 찾기

잠잠하던 DB서버의 CPU가 특정시간대(5분 사이)에 에 급격하게 사용율이 증가하는 현상 발생 시

해당 시간대에 문제된 원인 SQL을 찾아야함

하지만 AWR, ADDM은 수집 주기가 길어서(30분) 5분이내 순간적인 부하 SQL은 찾기가 힘듬

이런 경우 ASH를 통해서 조회가 가능함

ASH는 실시간(1초)마다 수집하는데 이를 이용해 동일한 sql_id 가 많이 보이는 쿼리를 의심할수 있음

동일한 sql_id가 많다는 것은 동일쿼리가 많이 수행 또는 오랫동한 수행한 쿼리로 판단할 수 있음

예를 들어 아래의 쿼리는 해당 시간 20190212 09:43:00~09:44:00(1분사이)에 수집된 sql_id 수를 합산하여

부하를 유발하는(의심되는) 쿼리를 유추해 볼수 있음

참고로 아래 쿼리는 정확한 진단은 아니기 때문에 참고만 하면 됨

SQL> 
select *
from (
select max(sample_time)
     , sql_id, count(*) cnt, sql_opname
     , (select sql_text
        from v$sql s
        where s.sql_id = h.sql_id
        and rownum <= 1)
from v$active_session_history h
where 1=1
and session_type = 'FOREGROUND'
and sql_exec_id is not null
--and is_awr_sample = 'Y'
and sample_time >= to_date('20190212 09:43:00', 'yyyymmdd hh24:mi:ss')
and sample_time <= to_date('20190212 09:44:00', 'yyyymmdd hh24:mi:ss')
group by sql_id, sql_opname
order by cnt desc
)
where 1=1
and rownum <= 10
;

insert_100_session.sh 를 실행한 뒤 확인하는 테스트 진행

(해당 쉘은 https://positivemh.tistory.com/412 참조)

세션1

현재 시간 확인

SQL> select systimestamp from dual;
 
SYSTIMESTAMP
---------------------------------------------------------------------------
12-FEB-19 09.43.01.846369 AM +09:00
 
1 row selected.

시간 간격을 09:43:00~09:44:00 까지로 정해서 쿼리 입력

SQL> 
select *
from (
select max(sample_time)
     , sql_id, count(*) cnt, sql_opname
     , (select sql_text
        from v$sql s
        where s.sql_id = h.sql_id
        and rownum <= 1)
from v$active_session_history h
where 1=1
and session_type = 'FOREGROUND'
and sql_exec_id is not null
--and is_awr_sample = 'Y'
and sample_time >= to_date('20190212 09:43:00', 'yyyymmdd hh24:mi:ss')
and sample_time <= to_date('20190212 09:44:00', 'yyyymmdd hh24:mi:ss')
group by sql_id, sql_opname
order by cnt desc
)
where 1=1
and rownum <= 10
;
 
no rows selected

세션2

insert_100_session.sh 실행

$ sh insert_100_session.sh 
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
.
.

세션1

시간 간격을 09:43:00~09:44:00 까지로 정해서 쿼리 재입력

SQL>
select *
from (
select max(sample_time)
     , sql_id, count(*) cnt, sql_opname
     , (select sql_text
        from v$sql s
        where s.sql_id = h.sql_id
        and rownum <= 1)
from v$active_session_history h
where 1=1
and session_type = 'FOREGROUND'
and sql_exec_id is not null
--and is_awr_sample = 'Y'
and sample_time >= to_date('20190212 09:43:00', 'yyyymmdd hh24:mi:ss')
and sample_time <= to_date('20190212 09:44:00', 'yyyymmdd hh24:mi:ss')
group by sql_id, sql_opname
order by cnt desc
)
where 1=1
and rownum <= 10
;
 
MAX(SAMPLE_TIME)                                SQL_ID         CNT SQL_OPNAME
--------------------------------------------------------------------------- ------------- ---------- ----------------------------------------------------------------
(SELECTSQL_TEXTFROMV$SQLSWHERES.SQL_ID=H.SQL_IDANDROWNUM<=1)
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
12-FEB-19 09.43.42.841 AM                            3gsrgx4q0qnm7    1835 INSERT
INSERT INTO SESS_TEST VALUES (SESS_TEST_SEQ.NEXTVAL, SYSDATE, :B1 )
 
12-FEB-19 09.43.24.841 AM                            4vs91dcv7u1p6      13 INSERT
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,terminal,action#,returncode, obj$creator,obj$name,auth$privileges,auth$grantee, new$owner,new$name,ses$actions,ses$tid,lo
goff$pread, logoff$lwrite,logoff$dead,comment$text,spare1,spare2,  priv$used,clientid,sessioncpu,proxy$sid,user$guid, instance#,process#,xid,scn,auditid,  sqlbind,sqltext,obj$edition,dbid)  values(:1,
:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4,:5,:6,:7,:8,     :9,:10,:11,:12,     :13,:14,:15,:16,:17,      :18,:19,:20,:21,:22,       :23,:24,:25,:26,:27,     :28,:29,:30,:31,:32,     :33,:34,:35,:36)
 
12-FEB-19 09.43.24.841 AM                            0k8522rmdzg4k       4 SELECT
select privilege# from sysauth$ where (grantee#=:1 or grantee#=1) and privilege#>0
 
12-FEB-19 09.43.24.841 AM                            5qgz1p0cut7mx       3 PL/SQL EXECUTE
BEGIN DBMS_OUTPUT.DISABLE; END;
 
12-FEB-19 09.43.24.841 AM                            cm5vu20fhtnq1       2 SELECT
select /*+ connect_by_filtering */ privilege#,level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0
 
12-FEB-19 09.43.24.841 AM                            5z198pygpnju7       2 PL/SQL EXECUTE
BEGIN FOR i IN 1..10000       LOOP              INSERT INTO SESS_TEST VALUES (SESS_TEST_SEQ.NEXTVAL, SYSDATE, i);       END LOOP; END;
 
12-FEB-19 09.43.24.841 AM                            dyk4dprp70d74       1 SELECT
SELECT DECODE('A','A','1','2') FROM DUAL
 
 
7 rows selected.

결과 중 첫번째 줄에 많이 실행된 insert 구문이 존재하는것을 확인 가능함 

(CNT는 계속 증가중임)

참조 : https://positivemh.tistory.com/412

https://cafe.naver.com/dbian/1371

https://cafe.naver.com/dbian/1372