この記事は約40分23秒で読むことができます。

sqlトレースとtkprof

初期化パラメータの設定

SQL_TRACE

SQLトレースの有効化の確認

コード表示

col name for a24;
col value for a12;
select name,value from V$PARAMETER where NAME like '%sql_trace%';
コード表示

AINE@pdb1> col name for a24;
AINE@pdb1> col value for a12;
AINE@pdb1> select name,value from V$PARAMETER where NAME like '%sql_trace%';

NAME                     VALUE
------------------------ ------------
sql_trace                FALSE

1 row selected.

Elapsed: 00:00:00.01

TRACEFILE_IDENTIFIER

tracefile_identifierを設定しておく。あとでみつけやすい。

コード表示

col name for a24;
col value for a12;
select name,value from V$PARAMETER where NAME like '%tracefile_identifier%';
コード表示

AINE@pdb1> col name for a24;
AINE@pdb1> col value for a12;
AINE@pdb1> select name,value from V$PARAMETER where NAME like '%tracefile_identifier%';

NAME                     VALUE
------------------------ ------------
tracefile_identifier

1 row selected.

Elapsed: 00:00:00.01

tracefile_identifierの設定。

コード表示

alter session set tracefile_identifier='test_trace';
コード表示

INE@pdb1> alter session set tracefile_identifier='test_trace';

Session altered.

Elapsed: 00:00:00.02
AINE@pdb1> select name,value from V$PARAMETER where NAME like '%tracefile_identifier%';

NAME                     VALUE
------------------------ ------------
tracefile_identifier     test_trace

1 row selected.

Elapsed: 00:00:00.01

TIMED_STATISTICS

経過時間の設定ができる。デフォはできる。

コード表示

col name for a24;
col value for a12;
select name,value from V$PARAMETER where NAME like '%timed_statistics%';
コード表示

[oracle@6898242bcdd5 mnt]$ sqlplus aine/ORACLE_PWD@pdb1

SQL*Plus: Release 18.0.0.0.0 - Production on Sat Jan 26 22:27:22 2019
Version 18.3.0.0.0

Copyright (c) 1982, 2018, Oracle.  All rights reserved.

Last Successful login time: Sat Jan 26 2019 19:28:38 +09:00

Connected to:
Oracle Database 18c Enterprise Edition Release 18.0.0.0.0 - Production
Version 18.3.0.0.0

AINE@pdb1> col name for a24;
AINE@pdb1> col value for a12;
AINE@pdb1> select name,value from V$PARAMETER where NAME like '%timed_statistics%';

NAME                     VALUE
------------------------ ------------
timed_statistics         TRUE

1 row selected.

Elapsed: 00:00:00.01
AINE@pdb1>

セッション単位でできるようにする。基本はセッション単位で。

コード表示

ALTER SESSION SET timed_statistics=TRUE;

USER_DUMP_DESTではなくてv$diag_infoで確認する!

トレースファイル作成場所の確認。マルチテナントアーキテクチャになった12cぐらいからこのv$diag_infoで確認する。Diag Traceに吐かれる。

コード表示

col name for a24;
col value for a100;
select name,value from V$PARAMETER where NAME like '%user_dump_dest%';
select name,value from V$diag_Info;
コード表示

AINE@pdb1> col name for a24;
AINE@pdb1> col value for a100;
AINE@pdb1> select name,value from V$PARAMETER where NAME like '%user_dump_dest%';

NAME                     VALUE
------------------------ ----------------------------------------------------------------------------------------------------
user_dump_dest           /opt/oracle/product/18c/dbhome_1/rdbms/log

1 row selected.

Elapsed: 00:00:00.00

AINE@pdb1> col name for a24;
AINE@pdb1> col value for a100;
AINE@pdb1> select name,value from V$diag_Info;

NAME                     VALUE
------------------------ ----------------------------------------------------------------------------------------------------
Diag Enabled             TRUE
ADR Base                 /opt/oracle
ADR Home                 /opt/oracle/diag/rdbms/orcl/ORCL
Diag Trace               /opt/oracle/diag/rdbms/orcl/ORCL/trace
Diag Alert               /opt/oracle/diag/rdbms/orcl/ORCL/alert
Diag Incident            /opt/oracle/diag/rdbms/orcl/ORCL/incident
Diag Cdump               /opt/oracle/diag/rdbms/orcl/ORCL/cdump
Health Monitor           /opt/oracle/diag/rdbms/orcl/ORCL/hm
Default Trace File       /opt/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_30410.trc
Active Problem Count     0
Active Incident Count    0

11 rows selected.

Elapsed: 00:00:00.01

MAX_DUMP_FILE_SIZE

トレースファイルサイズの確認。

コード表示

col name for a24;
col value for a100;
select name,value from V$PARAMETER where NAME like '%max_dump_file_size%';
コード表示

AINE@pdb1> select name,value from V$PARAMETER where NAME like '%max_dump_file_size%';

NAME                     VALUE
------------------------ ----------------------------------------------------------------------------------------------------
max_dump_file_size       unlimited

1 row selected.

Elapsed: 00:00:00.01

SQLトレースの実行

セッション単位で実行できるようにする。

コード表示

ALTER SESSION SET sql_trace=TRUE;

セッション単位で終了する。

コード表示

ALTER SESSION SET sql_trace=FALSE;

PLSQLを使ってセッション単位で実行できるようにする。

コード表示

DBMS_SESSION.SET_SQL_TRACE(TRUE);

PLSQLを使ってセッション単位で終了する。

コード表示

DBMS_SESSION.SET_SQL_TRACE(FALSE);

なんかてきとうなSQL実行する

トレースしたいSQLをSQL_TRACE=TRUEの状態で実行する。

コード表示

SELECT
	s0.warehouse_code
	,s0.arrive_date
	,s0.cust_id
	,s5.cust_kbn
	,s0.store_no
	,s6.store_kbn
	,s0.prov_inst_qty
	,s1.item
	,s1.item_kbn
	,s2.loc
	,s2.ZONE
	,s2.BLOCK
	,s2.area
	,s2.LINE
	,s3.zone_kbn
	,s4.route_no
	,s4.barth_no
	,s7.cart_no
	,s8.basket_no
FROM
	aine.sales_trn s0
	,aine.item_mst@testlink s1
	,aine.loc_mst@testlink s2
	,aine.zone_mst@testlink s3
	,kuraine.route_mst@testlink s4
	,kuraine.cust_mst@testlink s5
	,kuraine.store_mst@testlink s6
	,kuraine.cart_mst@testlink s7
	,kuraine.basket_mst@testlink s8
WHERE
	s0.warehouse_code = s1.warehouse_code
AND s1.warehouse_code = s2.warehouse_code
AND s1.main_loc = s2.loc
AND s2.warehouse_code = s2.warehouse_code
AND s2.ZONE = s3.ZONE
AND s3.warehouse_code = s4.warehouse_code
AND s0.cust_id = s5.cust_id
AND s0.store_no = s6.store_no
AND s5.cart_no = s7.cart_no
AND s5.basket_no = s8.basket_no
;

SQL実行前にglogin.sql確認しておく。

SET AUTOTRACE TRACEONLYがコメントアウトされているか確認する。ちなみにSQLは実行されている。

コード表示

[oracle@6898242bcdd5 ~]$ find / -name *login*.sql -type f 2>/dev/null
/opt/oracle/product/18c/dbhome_1/sqlplus/admin/glogin.sql
[oracle@6898242bcdd5 ~]$ vim /opt/oracle/product/18c/dbhome_1/sqlplus/admin/glogin.sql
コード表示

COLUMN OTHER_PLUS_EXP FORMAT A200
COLUMN PLAN_PLUS_EXP  FORMAT A200
SET NUMWIDTH 13
SET LINESIZE 1000
SET LONG 40000
SET LONGCHUNKSIZE 40000
SET PAGESIZE 50000--1ページあたりの表示行
SET SERVEROUTPUT ON--dbms_outputの表示結果を制御
SET TAB OFF--タブをタブのままで表示するか、スペースのままで表示するか
SET TRIMSPOOL ON--行末までの空白を除去するかどうか
SET FEED ON--取得件数の表示の有無
--SET AUTOTRACE TRACEONLY
SET TIMING ON--経過時間を表示するかどうか
SET TERM OFF--@での実行時のみ、表示結果の制御
--SET HIST ON
DEFINE_EDITOR=VIM
SET SQLP "_USER'@'_CONNECT_IDENTIFIER> "

SQL実行前に下準備。

以下のsql実行しておく。トレース開始前に。ALTER SESSION SET sql_traceに関してはselect name,value from V$PARAMETER where NAME like '%sql_trace%';で変更されていることを確認する。

コード表示

col name for a24;--共通
col value for a12;--共通
select name,value from V$PARAMETER where NAME like '%sql_trace%';--共通
ALTER SESSION SET sql_trace=TRUE;--共通
alter system checkpoint;--更新系
alter system switch logfile;--更新系
alter system flush shared_pool;--検索系・更新系
alter system flush buffer_cache;--検索系・更新系
ALTER SESSION SET sql_trace=FALSE;--共通

trcファイル吐かれているか確認

別セッションでtraceファイル吐かれているか確認しておく。

コード表示

[oracle@6898242bcdd5 ~]$ cd /opt/oracle/diag/rdbms/orcl/ORCL/trace
[oracle@6898242bcdd5 trace]$ pwd
/opt/oracle/diag/rdbms/orcl/ORCL/trace
[oracle@6898242bcdd5 trace]$ ll | grep test_trace
-rw-r-----. 1 oracle oinstall  395099 Jan 27 09:20 ORCL_ora_29903_test_trace.trc
-rw-r-----. 1 oracle oinstall   31189 Jan 27 09:20 ORCL_ora_29903_test_trace.trm
[oracle@6898242bcdd5 trace]$ tkprof ORCL_ora_29903_test_trace.trc ORCL_ora_29903_test_trace.trc.tkprof

TKPROF: Release 18.0.0.0.0 - Development on Sun Jan 27 09:43:52 2019

Copyright (c) 1982, 2018, Oracle and/or its affiliates.  All rights reserved.


[oracle@6898242bcdd5 trace]$ ll | grep test_trace
-rw-r-----. 1 oracle oinstall  395099 Jan 27 09:20 ORCL_ora_29903_test_trace.trc
-rw-r--r--. 1 oracle oinstall   60233 Jan 27 09:43 ORCL_ora_29903_test_trace.trc.tkprof
-rw-r-----. 1 oracle oinstall   31189 Jan 27 09:20 ORCL_ora_29903_test_trace.trm

trcファイルをtkprofで整形

出力されたtrcファイルをtkprofで整形する。対象のsqlが記載されている行数分表示するようにする。

コード表示

cat -n ファイル名 | head -終了行 | tail -`expr 終了行 - 開始行 + 1`
コード表示

[oracle@6898242bcdd5 trace]$ cat -n ORCL_ora_29903_test_trace.trc.tkprof | head -1168 | tail -`expr 1168 - 1091 + 1`
  1091  ********************************************************************************
  1092
  1093  SELECT
  1094          s0.warehouse_code
  1095          ,s0.arrive_date
  1096          ,s0.cust_id
  1097          ,s5.cust_kbn
  1098          ,s0.store_no
  1099          ,s6.store_kbn
  1100          ,s0.prov_inst_qty
  1101          ,s1.item
  1102          ,s1.item_kbn
  1103          ,s2.loc
  1104          ,s2.ZONE
  1105          ,s2.BLOCK
  1106          ,s2.area
  1107          ,s2.LINE
  1108          ,s3.zone_kbn
  1109          ,s4.route_no
  1110          ,s4.barth_no
  1111          ,s7.cart_no
  1112          ,s8.basket_no
  1113  FROM
  1114          aine.sales_trn s0
  1115          ,aine.item_mst@testlink s1
  1116          ,aine.loc_mst@testlink s2
  1117          ,aine.zone_mst@testlink s3
  1118          ,kuraine.route_mst@testlink s4
  1119          ,kuraine.cust_mst@testlink s5
  1120          ,kuraine.store_mst@testlink s6
  1121          ,kuraine.cart_mst@testlink s7
  1122          ,kuraine.basket_mst@testlink s8
  1123  WHERE
  1124          s0.warehouse_code = s1.warehouse_code
  1125  AND s1.warehouse_code = s2.warehouse_code
  1126  AND s1.main_loc = s2.loc
  1127  AND s2.warehouse_code = s2.warehouse_code
  1128  AND s2.ZONE = s3.ZONE
  1129  AND s3.warehouse_code = s4.warehouse_code
  1130  AND s0.cust_id = s5.cust_id
  1131  AND s0.store_no = s6.store_no
  1132  AND s5.cart_no = s7.cart_no
  1133  AND s5.basket_no = s8.basket_no
  1134
  1135  call     count       cpu    elapsed       disk      query    current        rows
  1136  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1137  Parse        1      0.01       0.10          1          0          2           0
  1138  Execute      1      0.00       0.00          0          0          0           0
  1139  Fetch     2739      0.01       0.04         23        391          0       41067
  1140  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1141  total     2741      0.03       0.15         24        391          2       41067
  1142
  1143  Misses in library cache during parse: 1
  1144  Optimizer mode: ALL_ROWS
  1145  Parsing user id: 103
  1146  Number of plan statistics captured: 1
  1147
  1148  Rows (1st) Rows (avg) Rows (max)  Row Source Operation
  1149  ---------- ---------- ----------  ---------------------------------------------------
  1150       41067      41067      41067  HASH JOIN  (cr=391 pr=23 pw=0 time=40779 us starts=1 cost=22 size=7186725 card=41067)
  1151           3          3          3   REMOTE  ROUTE_MST (cr=0 pr=0 pw=0 time=698 us starts=1 cost=2 size=51 card=3)
  1152       41067      41067      41067   HASH JOIN  (cr=391 pr=23 pw=0 time=32398 us starts=1 cost=20 size=6488586 card=41067)
  1153          39         39         39    REMOTE  ZONE_MST (cr=0 pr=0 pw=0 time=653 us starts=1 cost=2 size=468 card=39)
  1154       41067      41067      41067    HASH JOIN  (cr=391 pr=23 pw=0 time=22314 us starts=1 cost=17 size=5995782 card=41067)
  1155          39         39         39     REMOTE  LOC_MST (cr=0 pr=0 pw=0 time=639 us starts=1 cost=2 size=1092 card=39)
  1156       41067      41067      41067     HASH JOIN  (cr=391 pr=23 pw=0 time=11116 us starts=1 cost=15 size=4845906 card=41067)
  1157          39         39         39      REMOTE  ITEM_MST (cr=0 pr=0 pw=0 time=616 us starts=1 cost=2 size=936 card=39)
  1158        3159       3159       3159      HASH JOIN  (cr=391 pr=23 pw=0 time=5595 us starts=1 cost=13 size=296946 card=3159)
  1159           9          9          9       REMOTE  STORE_MST (cr=0 pr=0 pw=0 time=610 us starts=1 cost=2 size=234 card=9)
  1160        3159       3159       3159       HASH JOIN  (cr=391 pr=23 pw=0 time=3976 us starts=1 cost=11 size=214812 card=3159)
  1161           3          3          3        NESTED LOOPS  (cr=0 pr=0 pw=0 time=2384 us starts=1 cost=2 size=105 card=3)
  1162           3          3          3         NESTED LOOPS  (cr=0 pr=0 pw=0 time=1546 us starts=1 cost=2 size=84 card=3)
  1163           3          3          3          REMOTE  CUST_MST (cr=0 pr=0 pw=0 time=608 us starts=1 cost=2 size=63 card=3)
  1164           3          3          3          REMOTE  CART_MST (cr=0 pr=0 pw=0 time=878 us starts=3 cost=0 size=7 card=1)
  1165           3          3          3         REMOTE  BASKET_MST (cr=0 pr=0 pw=0 time=834 us starts=3 cost=0 size=7 card=1)
  1166        3159       3159       3159        TABLE ACCESS FULL SALES_TRN (cr=391 pr=23 pw=0 time=1348 us starts=1 cost=9 size=104247 card=3159)
  1167
  1168  ********************************************************************************

まとめ

ハードパースされた回数とか知りたかった!↓

コード表示

  1135  call     count       cpu    elapsed       disk      query    current        rows
  1136  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1137  Parse        1      0.01       0.10          1          0          2           0
  1138  Execute      1      0.00       0.00          0          0          0           0
  1139  Fetch     2739      0.01       0.04         23        391          0       41067
  1140  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1141  total     2741      0.03       0.15         24        391          2       41067

Leave a Reply

Your email address will not be published. Required fields are marked *