오라클 11g R2 tfa(ahf) SQL 성능 진단 자동 수집 가이드(SRDC)

OS환경 : Oracle Linux 6.8 (64bit)

DB 환경 : Oracle Database 11.2.0.4

방법 : 오라클 11g R2 tfa(ahf) SQL 성능 진단 자동 수집 가이드(SRDC)

먼저 AHF 설치

https://positivemh.tistory.com/607

wait 이벤트 발생용 쿼리 생성 쉘

http://sites.google.com/site/ukja/sql-scripts-1/j-m/make_long

set heading off
set timing off
set feedback off
set serveroutput on size 100000
 
var v_sql clob;
 
begin
  :v_sql := 'select count(*) from ';
 
  for r in (select t1.table_name
        from user_tables t1, user_tables t2 where rownum <= 500 and
            t1.table_name not like '%$%') loop
    :v_sql := :v_sql || r.table_name || ', ';
   
  end loop;
 
  :v_sql := :v_sql || ' dual where 1 = 0;';
 
end;
/
 
spool long_parse.sql
 
exec dbms_output.put_line(:v_sql);
 
spool off
set heading on
set timing on
set feedback on
set serveroutput off
 

해당 쉘 실행시 long_parse.sql 이 생성됨

$ cat long_parse.sql 
select count(*) from DUAL, 
.
.
dual where 1 = 0;        

1번 세션에서 long_parse.sql 실행

SQL> @long_parse.sql

1번 세션 long_parse.sql 실행 직후

동시에 2번, 3번, 4번 ,5번 세션에서 long_parse.sql 실행

1	SQL> @long_parse.sql

wait 이벤트 확인

SQL> 
col wait_class for a12
col event for a50
select * from (
 select
 WAIT_CLASS ,
 EVENT,
 count(sample_time) as EST_SECS_IN_WAIT
 from v$active_session_history
 where sample_time between sysdate - interval '1' hour and sysdate
 group by WAIT_CLASS,EVENT
 order by count(sample_time) desc
 )
where rownum <6;
 
WAIT_CLASS   EVENT                        EST_SECS_IN_WAIT
------------ -------------------------------------------------- ----------------
(null)         (null)                                1367
Concurrency  cursor: pin S wait on X                         826
Scheduler    resmgr:cpu quantum                           14
Other         Streams AQ: qmn coordinator waiting for slave to start            5
User I/O     db file sequential read                           4

해당 wait 이벤트를 발생시킨 SQL 확인(sql_id)

SQL> 
select event, sql_id, BLOCKING_SESSION, BLOCKING_SESSION_SERIAL#
from v$active_session_history
where event = 'cursor: pin S wait on X'
and rownum <= 10;
 
EVENT                           SQL_ID     BLOCKING_SESSION BLOCKING_SESSION_SERIAL#
-------------------------------------------------- ------------- ---------------- ------------------------
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
cursor: pin S wait on X                fa89par2ys3p4           45             47219
 
10 rows selected.

sql id를 확인했다면 제일 처음 설치했던 AHF 실행

DBNAME 입력 후 sql id 입력 후 엔터

$ ./tfactl diagcollect -srdc dbsqlperf
Enter the Database Name [Required for this SRDC] : ORCL11
Enter the SQL ID  [Required for this SRDC]: fa89par2ys3p4
Scripts to be run by this srdc: ipspack srdc_sqlhc.sql srdc_sqltc.sql srdc_sql_monitor.sql srdc_zip_tcbfiles 
Components included in this srdc: OS CRS DATABASE NOCHMOS
/bin/bash: copy: command not found
Use of uninitialized value $dbutil::dbunique_name in length at /home/oracle/oracle.ahf/tfa/bin/common/dbutil.pm line 849.
/bin/bash: copy: command not found
Use of uninitialized value $dbutil::dbunique_name in length at /home/oracle/oracle.ahf/tfa/bin/common/dbutil.pm line 849.
 
Collection Id : 20200812214208oracle11
 
Detailed Logging at : /home/oracle/oracle.ahf/data/repository/srdc_dbsqlperf_collection_Wed_Aug_12_21_42_12_KST_2020_node_all/diagcollect_20200812214208_oracle11.log
2020/08/12 21:42:34 KST : NOTE : Any file or directory name containing the string .com will be renamed to replace .com with dotcom
2020/08/12 21:42:34 KST : Collection Name : tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip
2020/08/12 21:42:35 KST : Getting list of files satisfying time range [08/12/2020 09:42:34 KST, 08/12/2020 21:42:35 KST]
2020/08/12 21:42:35 KST : Collecting additional diagnostic information...
2020/08/12 21:42:48 KST : Collecting ADR incident files...
2020/08/12 21:42:59 KST : Completed collection of additional diagnostic information...
2020/08/12 21:43:03 KST : Completed Local Collection
.-------------------------------------.
|          Collection Summary         |
+----------+-----------+-------+------+
| Host     | Status    | Size  | Time |
+----------+-----------+-------+------+
| oracle11 | Completed | 1.4MB |  29s |
'----------+-----------+-------+------'
 
Logs are being collected to: /home/oracle/oracle.ahf/data/repository/srdc_dbsqlperf_collection_Wed_Aug_12_21_42_12_KST_2020_node_all
/home/oracle/oracle.ahf/data/repository/srdc_dbsqlperf_collection_Wed_Aug_12_21_42_12_KST_2020_node_all/oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip

SQL 성능진단 로그가 수집됨

제일 마지막줄에 있는 /home/oracle/oracle.ahf/data/repository/srdc_dbsqlperf_collection_Wed_Aug_12_21_42_12_KST_2020_node_all/oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip

파일을 SR에 업로드하여 SQL 성능문제시 분석을 받아볼 수 있음

해당 파일 내용 확인

제일 마지막줄에 있는 경로로 이동 후 zip 파일 압축해제

$ cd /home/oracle/oracle.ahf/data/repository/srdc_dbsqlperf_collection_Wed_Aug_12_21_42_12_KST_2020_node_all
$ ls
diagcollect_20200812214208_oracle11.log          oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip
diagcollect_console_20200812214208_oracle11.log  oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip.txt
$ unzip oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip

압축 해제시 서버 hostname으로 된 디렉토리가 나옴

해당 디렉토리 확인

$ ls -al
total 1492
drwx------ 3 oracle dba    4096 Aug 12 21:44 .
drwxr-x--x 4 oracle dba    4096 Aug 12 21:43 ..
-rw-r--r-- 1 oracle dba    1830 Aug 12 21:43 diagcollect_20200812214208_oracle11.log
-rw-r--r-- 1 oracle dba     745 Aug 12 21:43 diagcollect_console_20200812214208_oracle11.log
drwxr-xr-x 3 oracle dba    4096 Aug 12 21:44 oracle11
-rw-r--r-- 1 oracle dba 1450610 Aug 12 21:43 oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip
-rw-r--r-- 1 oracle dba     928 Aug 12 21:43 oracle11.tfa_srdc_dbsqlperf_Wed_Aug_12_21_42_12_KST_2020.zip.txt
-rw-r--r-- 1 oracle dba   43912 Aug 12 21:42 oracle11.zip_inventory.xml
-rw-r--r-- 1 oracle dba      26 Aug 12 21:42 TFA.txt
$ cd oracle11
$ ls
db_feature_usage_statistics_orcl11  oracle11_LSMOD                  oracle11_VARTMPORACLE
diag                                oracle11_LSOF                   script_db_feature_usage.sql.sh
IPSPKG_20200812214249_COM_1.zip     oracle11_MOUNT                  script_ipspack.sh
monitor_sql_fa89par2ys3p4.html      oracle11_NETSTAT                script_ipspack.sh.out
oracle11_cha_collection.err         oracle11_NSSWITCH_CONF          script_srdc_zip_tcbfiles.sh
oracle11_cha_collection.log         oracle11_OPATCH_DBHOMES         skipped_files.txt
oracle11_cloudmetadata.log          oracle11_oracle-release         sqlhc_20200812_213804_fa89par2ys3p4_6_10053_trace_from_cursor.trc
oracle11_collection.err             oracle11_oratab                 sqlhc_20200812_213804_fa89par2ys3p4.zip
oracle11_collection.log             oracle11_os_collection.log      srdc_sqlhc.sql
oracle11_crs_collection.err         oracle11_os_report              srdc_sqlhc.sql.html
oracle11_crs_collection.log         oracle11_PROCDIRINFO            srdc_sql_monitor.sql
oracle11_DF                         oracle11_PS                     srdc_sql_monitor.sql.out
oracle11_dmesg                      oracle11_redhat-release         srdc_sqltc.sql
oracle11_DMESG                      oracle11_RPMQA                  srdc_sqltc.sql.out
oracle11_ENTROPY_AVAIL              oracle11_RUNLEVEL               srdc_tcb.zip
oracle11_fmwSaaSCollect.err         oracle11_srdc_zip_tcbfiles.out  tfa_1597235838_srdc_dbsqlperfsrdc_user_log
oracle11_fmwSaaSCollect.log         oracle11_summary                tfa_1597235838_srdc_dbsqlperfuserenv
oracle11_INITTAB                    oracle11_TOP_50_MEMORY          tfa_1597235838_srdc_dbsqlperf.xml
oracle11_LAST_REBOOT                oracle11_UPTIME                 zisOi3Et

다양한 정보들을 수집함

그중 용량이 가장 큰 sqlhc_20200812_213804_fa89par2ys3p4_6_10053_trace_from_cursor.trc 파일 확인

$ vi sqlhc_20200812_213804_fa89par2ys3p4_6_10053_trace_from_cursor.trc 
Trace file /oracle/app/oracle/diag/rdbms/orcl11/ORCL11/trace/ORCL11_ora_27208_DBMS_SQLDIAG_10053_20200812_213804.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/app/oracle/product/11.2.0/db_1
System name:    Linux
Node name:      ORACLE11
Release:        4.1.12-37.4.1.el6uek.x86_64
Version:        #2 SMP Tue May 17 07:23:38 PDT 2016
Machine:        x86_64
VM name:        VMWare Version: 6
Instance name: ORCL11
Redo thread mounted by this instance: 1
Oracle process number: 29
Unix process pid: 27208, image: oracle@ORACLE11 (TNS V1-V3)
 
 
*** 2020-08-12 21:38:16.558
*** SESSION ID:(37.2993) 2020-08-12 21:38:16.558
*** CLIENT ID:() 2020-08-12 21:38:16.558
*** SERVICE NAME:(SYS$USERS) 2020-08-12 21:38:16.558
*** MODULE NAME:(SQL*Plus) 2020-08-12 21:38:16.558
*** ACTION NAME:() 2020-08-12 21:38:16.558
 
 
*** TRACE CONTINUED FROM FILE /oracle/app/oracle/diag/rdbms/orcl11/ORCL11/trace/ORCL11_ora_27208_sqlhc_20200812_213804.trc ***
 
EXEC #140056012364888:c=46,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,plh=0,tim=1597235896557879
CLOSE #140056012364888:c=0,e=2,dep=1,type=0,tim=1597235896558081
=====================
PARSING IN CURSOR #140056012364888 len=50 dep=1 uid=0 oct=42 lid=0 tim=1597235896558139 hv=625793985 ad='0' sqlid='3cv3pgwkntqy1'
alter session set events 'trace [SQL_Optimizer.*]'
END OF STMT
PARSE #140056012364888:c=33,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,plh=0,tim=1597235896558137
EXEC #140056012364888:c=890,e=2171,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,plh=0,tim=1597235896560335
CLOSE #140056012364888:c=0,e=3,dep=1,type=0,tim=1597235896560372
STAT #140055969962272 id=1 cnt=1 pid=0 pos=1 obj=0 op='FILTER  (cr=2 pr=2 pw=0 time=754 us)'
STAT #140055969962272 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=2 pr=2 pw=0 time=751 us cost=3 size=696 card=1)'
STAT #140055969962272 id=3 cnt=1 pid=2 pos=1 obj=5160 op='TABLE ACCESS BY INDEX ROWID WRI$_REPT_FILES (cr=2 pr=2 pw=0 time=741 us cost=2 size=683 card=1)'
STAT #140055969962272 id=4 cnt=1 pid=3 pos=1 obj=5164 op='INDEX SKIP SCAN WRI$_REPT_FILES_IDX_01 (cr=1 pr=1 pw=0 time=438 us cost=1 size=0 card=1)'
STAT #140055969962272 id=5 cnt=0 pid=2 pos=2 obj=5154 op='TABLE ACCESS BY INDEX ROWID WRI$_REPT_COMPONENTS (cr=0 pr=0 pw=0 time=4 us cost=1 size=13 card=1)'
STAT #140055969962272 id=6 cnt=0 pid=5 pos=1 obj=5155 op='INDEX UNIQUE SCAN WRI$_REPT_COMPONENTS_PK (cr=0 pr=0 pw=0 time=3 us cost=0 size=0 card=1)'
CLOSE #140055969962272:c=83,e=82,dep=1,type=0,tim=1597235896560991
LOBGETLEN: c=0,e=3,p=0,cr=0,cu=0,tim=1597235896561015
LOBREAD: c=0,e=28,p=0,cr=0,cu=0,tim=1597235896561064
LOBREAD: c=25,e=25,p=0,cr=0,cu=0,tim=1597235896561111
LOBGETLEN: c=1,e=2,p=0,cr=0,cu=0,tim=1597235896561151
LOBREAD: c=157,e=32,p=0,cr=0,cu=0,tim=1597235896561194
LOBREAD: c=0,e=21,p=0,cr=0,cu=0,tim=1597235896561238
LOBGETLEN: c=0,e=2,p=0,cr=0,cu=0,tim=1597235896561686
LOBREAD: c=54,e=25,p=0,cr=0,cu=0,tim=1597235896561756
Registered qb: SEL$1 0x550880a0 (PARSER)
---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$1 nbfros=502 flg=0
    fro(0): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"
    fro(1): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"
    fro(2): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"
    fro(3): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"
    fro(4): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"
    fro(5): flg=4 objn=116 hint_alias="DUAL"@"SEL$1"

sql trace 파일임

참조 : 

Doc. 2435332.1

https://positivemh.tistory.com/607

https://ukja.tistory.com/322

http://sites.google.com/site/ukja/sql-scripts-1/j-m/make_long

https://positivemh.tistory.com/544

https://positivemh.tistory.com/607

https://positivemh.tistory.com/645

https://positivemh.tistory.com/647

https://positivemh.tistory.com/631