DBのパフォーマンス調査で再現テストしてstatspack取るときに、いまさらだけど、再現操作中(処理中)にstatspackスナップショット取らないといけないんだっけ?? 再現操作の前後でいいんだっけ(再現中にリアルタイムでスナップショット取る必要があるわけではなく、再現操作の開始前と、終了後のタイミングで1回ずつ取ればいいんだっけ)?があやしくなったので確認しました。特に実行時間が短い再現操作のDB調査で使えると思います
結果、後者でOKです(ただし累積系の値に限られます。ロードアベレージやCPU使用率などリアルタイムの値が出力される項目以外です)
確認した方法
- スナップショット取る
- 再現操作する -> 終わる
- スナップショット取る
- 直近2点間でレポート取得 (※ここには再現操作中の負荷がきっちり記録されてるか?)
- スナップショット取る
- 直近2点間でレポート取得 (※ここは無風状態が記録されてるか?)
確認結果
上記想定の通りでした。
具体的な操作は以下です
- execute statspack.snap(i_snap_level=>7); ※スナップ3
- 再現操作
- select count(*) from huge_table;
- 1分くらい?
- execute statspack.snap(i_snap_level=>7); ※スナップ4
- @?/rdbms/admin/spreport
- 直近2点を指定 (begin:1, end:2)
- execute statspack.snap(i_snap_level=>7); ※スナップ5
- @?/rdbms/admin/spreport
- 直近2点を指定 (begin:2, end:3)
※検証時スナップIDが3から始まってます
sp_3_4.lst
Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- ------------------
Begin Snap: 3 12-1月 -23 16:04:51 178 1.5
End Snap: 4 12-1月 -23 16:06:46 178 1.5
Elapsed: 1.92 (mins) Av Act Sess: 0.7
DB time: 1.33 (mins) DB CPU: 0.40 (mins)
--
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
Data Guard: Gap Manager 2 121 60416 37.4
pman timer 38 114 3008 35.3
db file sequential read 1,091,302 63 0 19.6
CPU time 23 7.1
log file parallel write 173 1 4 .2
-------------------------------------------------------------
Host CPU (CPUs: 4 Cores: 4 Sockets: 1)
~~~~~~~~ Load Average
Begin End User System Idle WIO WCPU
------- ------- ------- ------- ------- ------- --------
0.18 1.08 6.64 3.65 88.85 8.31
--
SQL ordered by Elapsed time for DB: mydb Instance: mydb Snaps: 3 -4
-> Total DB Time (s): 80
-> Captured SQL accounts for 98.3% of Total DB Time
-> SQL reported below exceeded 1.0% of Total DB Time
Elapsed Elap per CPU Old
Time (s) Executions Exec (s) %Total Time (s) Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
75.42 1 75.42 94.5 20.50 1,089,236 2099888218
Module: SQL*Plus
select count(*) from huge_table
sp_4_5.lst
Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- ------------------
Begin Snap: 4 12-1月 -23 16:06:46 178 1.5
End Snap: 5 12-1月 -23 16:10:55 181 1.5
Elapsed: 4.15 (mins) Av Act Sess: 0.2
DB time: 0.88 (mins) DB CPU: 0.24 (mins)
--
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
pman timer 83 250 3008 42.5
Data Guard: Gap Manager 4 242 60416 41.1
log file sync 38,946 41 1 7.0
log file parallel write 38,982 37 1 6.4
CPU time 12 2.0
-------------------------------------------------------------
Host CPU (CPUs: 4 Cores: 4 Sockets: 1)
~~~~~~~~ Load Average
Begin End User System Idle WIO WCPU
------- ------- ------- ------- ------- ------- --------
1.08 0.78 6.05 2.25 91.00 2.70
--
SQL ordered by Elapsed time for DB: mydb Instance: mydb Snaps: 4 -5
-> Total DB Time (s): 53
-> Captured SQL accounts for 7.8% of Total DB Time
-> SQL reported below exceeded 1.0% of Total DB Time
Elapsed Elap per CPU Old
Time (s) Executions Exec (s) %Total Time (s) Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
0.68 1 0.68 1.3 0.66 101 2912400228
Module: SQL*Plus
BEGIN statspack.snap; END;
解説
pman timerとData Guard: Gap Manager は、Oralce内部のイベントで無視する必要があるやつです(12cから出力されるようになった。パッチ当てれば出力されなくなる。この環境では当たってない)
それ以外だと、再現操作前後のスナップを指定したsp_3_4.lstでは再現操作のSQLやDB全体の負荷が記録され、再現操作の後～さらに後のスナップを指定したsp_4_5.lstは無風状態になっていることが確認できました。
ただし、CPU使用率やロードアベレージなど、リアルタイム的なものは処理中のものでないと参考にならないようです。
上記の方法で取れることが分かりましたが、特に処理時間の短い再現操作の確認の場合、同じタイミングで別の処理が流れてるとその処理の方が記録されてしまう可能性があって分かりづらくなってしまうので、なるべく無風状態(かCPU使用率が落ち着いてることなどを確認して)やるのがいいと思います
こういう5分くらいでさくっと書ける記事を書くのが楽です(長大なやつは大体書き途中に自分で納得いかなくなってお蔵入りになる)