sql oracle statspack tkprof hard parse回数の確認

初期化パラメータの確認

job_queue_processesの確認

ジョブ実行用に作成できるプロセスの最大数を指定。ジョブキュー内のジョブを実行するために、少なくとも1以上を指定する必要。

コード表示

col name for a24;
col value for a12;
select name,value from V$PARAMETER where NAME like '%job_queue_processes%';

dockerコンテナ内で出力したspool結果をdocker起動時に指定したdockerホストから見えるディレクトリに移動させ、winscpで出力したスプールファイルを刈り取り。というか/mntに移動してからsqlplus起動してスプールすればいい。。

コード表示

set markup html on
spool test.html
select * from STATS$PARAMETER where NAME like '%timed_statistics%';
spool off
set markup html off
コード表示

[oracle@centos7 ~]$ docker exec -it orcl_18cr3_1 bash
[oracle@6898242bcdd5 ~]$ sqlplus perfstat/perfstat@pdb1

SQL*Plus: Release 18.0.0.0.0 - Production on Sat Jan 26 17:18:52 2019
Version 18.3.0.0.0

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

Last Successful login time: Sat Jan 26 2019 17:16:12 +09:00

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

PERFSTAT@pdb1> host pwd
/home/oracle

PERFSTAT@pdb1> host ls -lt
total 212
-rw-r--r--. 1 oracle oinstall    913 Jan 26 17:16 test.html
-rw-r--r--. 1 oracle oinstall 162575 Jan 26 14:39 test_statspack.lst
-rw-r--r--. 1 oracle oinstall    237 Jan 26 09:41 spcpkg.lis
-rw-r--r--. 1 oracle oinstall  12864 Jan 26 09:41 spctab.lis
-rw-r--r--. 1 oracle oinstall   4570 Jan 26 09:41 spcusr.lis
drwxr-xr-x. 2 oracle oinstall   4096 Jan 20 10:58 rlwrap-extensions
-rw-r--r--. 1 root   root      15080 Jan 20 10:52 epel-release-7-11.noarch.rpm
lrwxrwxrwx. 1 root   root         26 Jan 19 23:19 setPassword.sh -> /opt/oracle/setPassword.sh

PERFSTAT@pdb1> set markup html on
PERFSTAT@pdb1> spool test.html
PERFSTAT@pdb1> select * from STATS$PARAMETER where NAME like '%job_queue_processes%';
PERFSTAT@pdb1> spool off

PERFSTAT@pdb1> set markup html off

PERFSTAT@pdb1> host ls -lt
total 212
-rw-r--r--. 1 oracle oinstall    913 Jan 26 17:20 test.html
-rw-r--r--. 1 oracle oinstall 162575 Jan 26 14:39 test_statspack.lst
-rw-r--r--. 1 oracle oinstall    237 Jan 26 09:41 spcpkg.lis
-rw-r--r--. 1 oracle oinstall  12864 Jan 26 09:41 spctab.lis
-rw-r--r--. 1 oracle oinstall   4570 Jan 26 09:41 spcusr.lis
drwxr-xr-x. 2 oracle oinstall   4096 Jan 20 10:58 rlwrap-extensions
-rw-r--r--. 1 root   root      15080 Jan 20 10:52 epel-release-7-11.noarch.rpm
lrwxrwxrwx. 1 root   root         26 Jan 19 23:19 setPassword.sh -> /opt/oracle/setPassword.sh
PERFSTAT@pdb1> Disconnected from Oracle Database 18c Enterprise Edition Release 18.0.0.0.0 - Production
Version 18.3.0.0.0
[oracle@6898242bcdd5 ~]$ ll
total 212
-rw-r--r--. 1 root   root      15080 Jan 20 10:52 epel-release-7-11.noarch.rpm
drwxr-xr-x. 2 oracle oinstall   4096 Jan 20 10:58 rlwrap-extensions
lrwxrwxrwx. 1 root   root         26 Jan 19 23:19 setPassword.sh -> /opt/oracle/setPassword.sh
-rw-r--r--. 1 oracle oinstall    237 Jan 26 09:41 spcpkg.lis
-rw-r--r--. 1 oracle oinstall  12864 Jan 26 09:41 spctab.lis
-rw-r--r--. 1 oracle oinstall   4570 Jan 26 09:41 spcusr.lis
-rw-r--r--. 1 oracle oinstall    913 Jan 26 17:20 test.html
-rw-r--r--. 1 oracle oinstall 162575 Jan 26 14:39 test_statspack.lst
[oracle@6898242bcdd5 ~]$ mv test.html /mnt
[oracle@6898242bcdd5 ~]$ ll
total 208
-rw-r--r--. 1 root   root      15080 Jan 20 10:52 epel-release-7-11.noarch.rpm
drwxr-xr-x. 2 oracle oinstall   4096 Jan 20 10:58 rlwrap-extensions
lrwxrwxrwx. 1 root   root         26 Jan 19 23:19 setPassword.sh -> /opt/oracle/setPassword.sh
-rw-r--r--. 1 oracle oinstall    237 Jan 26 09:41 spcpkg.lis
-rw-r--r--. 1 oracle oinstall  12864 Jan 26 09:41 spctab.lis
-rw-r--r--. 1 oracle oinstall   4570 Jan 26 09:41 spcusr.lis
-rw-r--r--. 1 oracle oinstall 162575 Jan 26 14:39 test_statspack.lst
[oracle@6898242bcdd5 ~]$ cd /mnt
[oracle@6898242bcdd5 mnt]$ ll
total 4
drwxrwxrwx. 5   1000     1001  46 Jan  2 15:05 11gr2
drwxrwxrwx. 5   1000     1001  46 Jan  2 15:05 12cr2
drwxrwxrwx. 5   1000     1001  46 Jan 12 22:21 18cr3
-rw-r--r--. 1 oracle oinstall 913 Jan 26 17:20 test.html
SNAP_ID DBID INSTANCE_NUMBER NAME VALUE ISDEFAULT ISMODIFIED
2 1525818796 1 job_queue_processes 4000 TRUE FALSE
1 1525818796 1 job_queue_processes 4000 TRUE FALSE

timed_statisticsの確認

時間に関する統計情報を収集するか否かを決定するパラメータ。デフォは収集する。

コード表示

select * from STATS$PARAMETER where NAME like '%timed_statistics%';
SNAP_ID DBID INSTANCE_NUMBER NAME VALUE ISDEFAULT ISMODIFIED
2 1525818796 1 timed_statistics TRUE TRUE FALSE
1 1525818796 1 timed_statistics TRUE TRUE FALSE

statistics_levelの確認

収集される統計情報量を調節できる。

コード表示

select * from STATS$PARAMETER where NAME like '%statistics_level%';
SNAP_ID DBID INSTANCE_NUMBER NAME VALUE ISDEFAULT ISMODIFIED
2 1525818796 1 statistics_level TYPICAL TRUE FALSE
1 1525818796 1 statistics_level TYPICAL TRUE FALSE

スナップショットの閾値の確認

スナップショットを取得すると、ライブラリ・キャッシュにあるSQL情報はSTATS$SUMMARYテーブルに格納されるが、すべて格納すると、膨大になるため、閾値を越えたSQLだけを格納するように組まれているぽい。そこで閾値を確認してみる。なお$ORACLE_HOME/rdbms/admin/spdoc.txtが原文。

閾値 概要 原文(引用)
i_executions_th SQLの実行回数。デフォルト値は100 SQL Threshold: number of times the statement was executed
i_disk_reads_th SQLによるディスク・アクセス数。デフォルト値は1000 SQL Threshold: number of disk reads
the statement made
i_parse_calls_th SQLが実行する解析コール数。デフォルト値は1000 SQL Threshold: number of parse
calls the statement made
i_buffer_gets_th SQLがアクセスされたバッファのフロック取得数。デフォルト値は10000 SQL Threshold: number of buffer
gets the statement made
i_sharable_mem_th SQLの共有可能メモリ量(単位:byte)。デフォルトは1048576バイト SQL Threshold: amount of sharable
memory
i_version_count_th SQLの種類の数。デフォルト値は20 SQL Threshold: number of versions
of a SQL statement
i_seg_log_reads_th セグメントに対する論理読み込み数。デフォルト値は10000 Segment statistic Threshold: number
of logical reads on a segment.
i_seg_phy_reads_th セグメントに対する物理読み込み数。デフォルト値は1000 Segment statistic Threshold: number
of physical reads on a segment.
i_seg_buff_busy_th セグメントに対するバッファビジー待機数。デフォルト値は100 Segment statistic Threshold: number
of buffer busy waits for a segment.
i_seg_rowlock_w_th セグメントに対する行ロック待機数。デフォルト値は100 Segment statistic Threshold: number
of row lock waits for a segment.
i_seg_itl_waits_th セグメントに対するITL待機数。デフォルト値は100 Segment statistic Threshold: number
of ITL waits for a segment.
i_seg_cr_bks_sd_th セグメントに対する、指定インスタンスのCRブロック転送数。デフォル
ト値は1000(RAC環境のみ)
Segment statistic Threshold: number
of Consistent Reads blocks served by
the instance for the segment*.
i_seg_cu_bks_sd_th セグメントに対する、指定インスタンスのカレントブロック転送数。デフ
ォルト値は1000(RAC環境のみ)
Segment statistic Threshold: number
of CUrrent blocks served by the
instance for the segment*.

今設定されてあるパラメータ値の確認はSTATS$STATSPACK_PARAMETERより確認できる。

コード表示

select * from STATS$STATSPACK_PARAMETER;
Name Null? Type
DBID NOT NULL NUMBER
INSTANCE_NUMBER NOT NULL NUMBER
SESSION_ID NOT NULL NUMBER
SNAP_LEVEL NOT NULL NUMBER
NUM_SQL NOT NULL NUMBER
EXECUTIONS_TH NOT NULL NUMBER
PARSE_CALLS_TH NOT NULL NUMBER
DISK_READS_TH NOT NULL NUMBER
BUFFER_GETS_TH NOT NULL NUMBER
SHARABLE_MEM_TH NOT NULL NUMBER
VERSION_COUNT_TH NOT NULL NUMBER
PIN_STATSPACK NOT NULL VARCHAR2(10)
ALL_INIT NOT NULL VARCHAR2(5)
LAST_MODIFIED DATE
UCOMMENT VARCHAR2(160)
JOB NUMBER
SEG_PHY_READS_TH NOT NULL NUMBER
SEG_LOG_READS_TH NOT NULL NUMBER
SEG_BUFF_BUSY_TH NOT NULL NUMBER
SEG_ROWLOCK_W_TH NOT NULL NUMBER
SEG_ITL_WAITS_TH NOT NULL NUMBER
SEG_CR_BKS_RC_TH NOT NULL NUMBER
SEG_CU_BKS_RC_TH NOT NULL NUMBER
OLD_SQL_CAPTURE_MTH NOT NULL VARCHAR2(10)

hard parseに時間のかかるsqlを実行してみる。

sqlは以下の参考文献より拝借。

Hard Parseに時間が掛かるお手軽なSQLを作ってみる。(Oracle Database)

コード表示

WITH a AS (
	SELECT /*+ inline */
		1
	FROM
		dual
		, dual
		, dual
		, dual
		, dual
		, dual
		, dual
		, dual
		, dual
		, dual
), b AS (
	SELECT /*+ inline */
		1
	FROM
		a
		, a
		, a
		, a
		, a
		, a
		, a
		, a
		, a
		, a
) SELECT
	1
  FROM
	b
	, b
	, b;

v$sysstatでsql実行前の状況を確認してみる。

9.96 V$SYSSTAT

システム全体でのサマリを参照することができる。

コード表示

col name for a24
col value for 999999999999
select * from v$sysstat where NAME like 'parse%';
コード表示

AINE@pdb1> col name for a24
AINE@pdb1> col value for 999999999999
AINE@pdb1> select * from v$sysstat where NAME like 'parse%';

   STATISTIC# NAME                             CLASS         VALUE       STAT_ID        CON_ID
------------- ------------------------ ------------- ------------- ------------- -------------
         1892 parse time cpu                      64         12981     206905303             3
         1893 parse time elapsed                  64         13826    1431595225             3
         1894 parse count (total)                 64        784665      63887964             3
         1895 parse count (hard)                  64         33672     143509059             3
         1896 parse count (failures)              64          1793    1118776443             3
         1897 parse count (describe)              64           161     469016317             3

6 rows selected.

Elapsed: 00:00:00.01

hard parseの回数を確認する。

sqlトレースファイルをtkprofで整形して確認する。

処理 sql
検索系・更新系 alter system flush shared_pool;
検索系・更新系 alter system flush buffer_cache;
更新系 alter system checkpoint;
更新系 alter system switch logfile;
コード表示

col name for a24;
col value for a12;
select name,value from V$PARAMETER where NAME like '%tracefile_identifier%';
alter session set tracefile_identifier='test_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=FASLE;
コード表示

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

SQL*Plus: Release 18.0.0.0.0 - Production on Sun Jan 27 11:52:06 2019
Version 18.3.0.0.0

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

Last Successful login time: Sun Jan 27 2019 11:38:51 +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 '%tracefile_identifier%';

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

1 row selected.

Elapsed: 00:00:00.01
AINE@pdb1> alter session set tracefile_identifier='test_trace';

Session altered.

Elapsed: 00:00:00.00
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
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.02
AINE@pdb1> ALTER SESSION SET sql_trace=TRUE;

Session altered.

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

NAME                     VALUE
------------------------ ------------
sql_trace                TRUE

1 row selected.

Elapsed: 00:00:00.01
AINE@pdb1> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.21
AINE@pdb1> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.03
AINE@pdb1> host ls -lt
total 212
-rw-r--r--. 1 oracle oinstall    265 Jan 27 11:41 test.sql
-rw-r--r--. 1 oracle oinstall 162575 Jan 26 14:39 test_statspack.lst
-rw-r--r--. 1 oracle oinstall    237 Jan 26 09:41 spcpkg.lis
-rw-r--r--. 1 oracle oinstall  12864 Jan 26 09:41 spctab.lis
-rw-r--r--. 1 oracle oinstall   4570 Jan 26 09:41 spcusr.lis
drwxr-xr-x. 2 oracle oinstall   4096 Jan 20 10:58 rlwrap-extensions
-rw-r--r--. 1 root   root      15080 Jan 20 10:52 epel-release-7-11.noarch.rpm
lrwxrwxrwx. 1 root   root         26 Jan 19 23:19 setPassword.sh -> /opt/oracle/setPassword.sh

AINE@pdb1> host vim test.sql
AINE@pdb1> @test.sql

別セッションにてtraceファイルが吐かれているかを確認する。

コード表示

[oracle@6898242bcdd5 ~]$ cd /opt/oracle/diag/rdbms/orcl/ORCL/trace
[oracle@6898242bcdd5 trace]$ ll -lt | grep test_trace
-rw-r-----. 1 oracle oinstall  551104 Jan 27 12:00 ORCL_ora_3725_test_trace.trc
-rw-r-----. 1 oracle oinstall   84736 Jan 27 12:00 ORCL_ora_3725_test_trace.trm
-rw-r--r--. 1 oracle oinstall   60233 Jan 27 09:43 ORCL_ora_29903_test_trace.trc.tkprof
-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_3725_test_trace.trc ORCL_ora_3725_test_trace.trc.tkprof

TKPROF: Release 18.0.0.0.0 - Development on Sun Jan 27 12:02:46 2019

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


[oracle@6898242bcdd5 trace]$ ll -lt | grep test_trace
-rw-r--r--. 1 oracle oinstall  161006 Jan 27 12:02 ORCL_ora_3725_test_trace.trc.tkprof
-rw-r-----. 1 oracle oinstall  551104 Jan 27 12:00 ORCL_ora_3725_test_trace.trc
-rw-r-----. 1 oracle oinstall   84736 Jan 27 12:00 ORCL_ora_3725_test_trace.trm
-rw-r--r--. 1 oracle oinstall   60233 Jan 27 09:43 ORCL_ora_29903_test_trace.trc.tkprof
-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]$ cat -n ORCL_ora_3725_test_trace.trc.tkprof | head -n 2062 | tail -`expr 2062 - 1407 + 1`
  1407  ********************************************************************************
  1408
  1409  WITH a AS (
  1410          SELECT /*+ inline */
  1411                  1
  1412          FROM
  1413                  dual
  1414                  , dual
  1415                  , dual
  1416                  , dual
  1417                  , dual
  1418                  , dual
  1419                  , dual
  1420                  , dual
  1421                  , dual
  1422                  , dual
  1423  ), b AS (
  1424          SELECT /*+ inline */
  1425                  1
  1426          FROM
  1427                  a
  1428                  , a
  1429                  , a
  1430                  , a
  1431                  , a
  1432                  , a
  1433                  , a
  1434                  , a
  1435                  , a
  1436                  , a
  1437  ) SELECT
  1438          1
  1439    FROM
  1440          b
  1441          , b
  1442          , b
  1443
  1444  call     count       cpu    elapsed       disk      query    current        rows
  1445  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1446  Parse        1     18.05      18.05          0          0          0           0
  1447  Execute      1      0.00       0.00          0          0          0           0
  1448  Fetch        2      0.00       0.00          0          0          0           1
  1449  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1450  total        4     18.05      18.05          0          0          0           1
********************************************************************************

サマリ。Parse行のcpu列とelapsed列に着目。

コード表示

  1444  call     count       cpu    elapsed       disk      query    current        rows
  1445  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1446  Parse        1     18.05      18.05          0          0          0           0
  1447  Execute      1      0.00       0.00          0          0          0           0
  1448  Fetch        2      0.00       0.00          0          0          0           1
  1449  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1450  total        4     18.05      18.05          0          0          0           1

v$sysstatでsql実行後の状況を確認してみる。

9.96 V$SYSSTAT

システム全体でのサマリを参照することができる。

コード表示

col name for a24
col value for 999999999999
select * from v$sysstat where NAME like 'parse%';
コード表示

AINE@pdb1> col name for a24
AINE@pdb1> col value for 999999999999
AINE@pdb1> select * from v$sysstat where NAME like 'parse%';

   STATISTIC# NAME                             CLASS         VALUE       STAT_ID        CON_ID
------------- ------------------------ ------------- ------------- ------------- -------------
         1892 parse time cpu                      64         14793     206905303             3
         1893 parse time elapsed                  64         15639    1431595225             3
         1894 parse count (total)                 64        784920      63887964             3
         1895 parse count (hard)                  64         33797     143509059             3
         1896 parse count (failures)              64          1793    1118776443             3
         1897 parse count (describe)              64           161     469016317             3

6 rows selected.

Elapsed: 00:00:00.02
AINE@pdb1> host expr 33797 - 33672
125

tkprofで加工されたsqlトレースファイルに出力されている項目に関して

コード表示

  1444  call     count       cpu    elapsed       disk      query    current        rows
  1445  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1446  Parse        1     18.05      18.05          0          0          0           0
  1447  Execute      1      0.00       0.00          0          0          0           0
  1448  Fetch        2      0.00       0.00          0          0          0           1
  1449  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
  1450  total        4     18.05      18.05          0          0          0           1

トレース統計(表側)

項目名 概要
Parse もろもろのチェックを行って、SQLを実行計画に変換する。
Execute Oracleによって実行されるSQL。INSERT文、UPDATE文、DELETE文、SFIECT文、MERGE文とかとか。
Fetch 問い合わせを満たす行数。

トレース統計(表頭)

項目名 概要
count 表側の項目に対する回数。
cpu 表側の項目に対するcpuの処理時間の合計(秒)。TIMED_STATISTICSがONになっている場合のみ。
elapsed 表側の項目に対する経過時間の合計(秒)。TIMED_STATISTICSがONになっている場合のみ。
disk ディスク上のデータファイルから物理読み込みしたデータブロックの総数。
query 一貫モードで取得されたバッファの総数。SELECT文は一貫モード。
current 一貫モードで取得されたバッファの総数。DML文は現行モード。
rows 処理された行数。サブクエリの総数は含まない。

トレース統計(実行計画)

項目名 概要
cr 行単位での結果に対して、バッファから読み取ったブロック総数
pr 行単位での結果に対して、物理読み込みブロックの総数
pw 行単位での結果に対して、物理書き込みブロックの総数
time 処理にかかった時間(単位:マイクロ秒)

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