前提
- snap のレベル6以上で statspack のスナップショットが取得されていること。*1
手順
まず statspack レポートを出力する。
$ sqlplus perfstat/perfstat SQL> @?/rdbms/admin/spreport Specify the Begin and End Snapshot Ids ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Enter value for begin_snap: 1770<RETURN> Enter value for end_snap: 1771<RETURN> ... Specify the Report Name ~~~~~~~~~~~~~~~~~~~~~~~ The default report file name is sp_1770_1771. To use this name, press <return> to continue, otherwise enter an alternative. Enter value for report_name:<RETURN>
出力した Statspack レポートを確認してみる。
$ less sp_1770_1771.lst ... SQL ordered by Reads DB/Inst: ORCL/orcl Snaps: 1770-1771 -> End Disk Reads Threshold: 1000 Total Disk Reads: 14,124,280 -> Captured SQL accounts for 99.9% of Total Disk Reads -> SQL reported below exceeded 1.0% of Total Disk Reads CPU Elapsd Old Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value --------------- ------------ -------------- ------ -------- --------- ---------- 12,911,768 7 1,844,538.3 91.4 415.65 5336.51 3033987018 Module: JDBC Thin Client SELECT ...
例えば、[SQL ordered by Reads] を見てみる。これは「物理読み込みブロック数」。つまり、SQL 実行時にディスクから読まれたブロックの数。「1,844,538.3」ブロック読まれている。このデータベースのブロックサイズは 8KB なので、
1,844,538.3 * 8KB = 14756306.4KB = 14GB
14GB もディスクからブロックを読み込んでいることになる。
では、この SQL が当時どのような実行計画で実行されたか見てみる。
$ sqlplus perfstat/perfstat SQL> @?/rdbms/admin/sprepsql ... Specify the Begin and End Snapshot Ids ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Enter value for begin_snap: 1770<RETURN> ← 上のレポート出力時と同じ Snapshot Id を指定する Enter value for end_snap: 1771<RETURN> ← 上のレポート出力時と同じ Snapshot Id を指定する ... Specify the old (i.e. pre-10g) Hash Value ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Enter value for hash_value: 3033987018 <RETURN> ← 上のレポートの Old Hash Value の値を指定する ... Specify the Report Name ~~~~~~~~~~~~~~~~~~~~~~~ The default report file name is sp_1770_1771_3033987018. To use this name, press <return> to continue, otherwise enter an alternative. Enter value for report_name: <RETURN> ... SQL> exit
出力したレポートを見てみると、
$ less sp_1770_1771_3033987018.lst STATSPACK SQL report for Old Hash Value: 3033987018 Module: JDBC Thin Client DB Name DB Id Instance Inst Num Release RAC Host ------------ ----------- ------------ -------- ----------- --- ---------------- ORCL 2080349925 orcl 1 10.2.0.4.0 NO db01 Start Id Start Time End Id End Time Duration(mins) --------- ------------------- --------- ------------------- -------------- 1770 24-Mar-10 16:00:00 1771 24-Mar-10 17:00:01 60.02 SQL Statistics ~~~~~~~~~~~~~~ -> CPU and Elapsed Time are in seconds (s) for Statement Total and in milliseconds (ms) for Per Execute % Snap Statement Total Per Execute Total --------------- --------------- ------ Buffer Gets: 13,538,457 1,934,065.3 5.37 Disk Reads: 12,911,768 1,844,538.3 91.42 Rows processed: 53 7.6 CPU Time(s/ms): 416 59,378.5 Elapsed Time(s/ms): 5,337 762,358.6 Sorts: 14 2.0 Parse Calls: 7 1.0 Invalidations: 0 Version count: 1 Sharable Mem(K): 250 Executions: 7 SQL Text ~~~~~~~~ SELECT ... Known Optimizer Plan(s) for this Old Hash Value ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Shows all known Optimizer Plans for this database instance, and the Snap Id's they were first found in the shared pool. A Plan Hash Value will appear multiple times if the cost has changed -> ordered by Snap Id First First Last Plan Snap Id Snap Time Active Time Hash Value Cost --------- --------------- --------------- ------------ ---------- 1765 24-Mar-10 11:00 25-Mar-10 09:56 3503768424 1059346 Plans in shared pool between Begin and End Snap Ids ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Shows the Execution Plans found in the shared pool between the begin and end snapshots specified. The values for Rows, Bytes and Cost shown below are those which existed at the time the first-ever snapshot captured this plan - these values often change over time, and so may not be indicative of current values -> Rows indicates Cardinality, PHV is Plan Hash Value -> ordered by Plan Hash Value -------------------------------------------------------------------------------- | Operation | PHV/Object Name | Rows | Bytes| Cost | -------------------------------------------------------------------------------- |SELECT STATEMENT |----- 3503768424 ----| | |1059346 | |SORT ORDER BY | | 1M| 1G|1059346 | | HASH JOIN RIGHT OUTER | | 1M| 1G| 673186 | | TABLE ACCESS FULL |******************** | 6 | 558 | 15 | | HASH JOIN RIGHT OUTER | | 1M| 1G| 673163 | | TABLE ACCESS FULL |******** | 163 | 7K| 15 | | HASH JOIN | | 1M| 1G| 673140 | | TABLE ACCESS FULL |************* | 42K| 870K| 56 | | HASH JOIN RIGHT OUTER | | 1M| 1G| 673076 | | TABLE ACCESS FULL |*********** | 6 | 234 | 15 | | HASH JOIN RIGHT OUTER | | 1M| 1G| 673053 | | TABLE ACCESS FULL |************** | 673K| 14M| 533 | | HASH JOIN | | 1M| 1G| 600463 | | TABLE ACCESS FULL |******************** | 8K| 618K| 29 | | NESTED LOOPS OUTER | | 1M| 1G| 600426 | | HASH JOIN RIGHT OUTER | | 1M| 1G| 600426 | | TABLE ACCESS FULL |******************** | 8K| 618K| 29 | | HASH JOIN | | 1M| 1G| 600389 | | NESTED LOOPS | | 1M| 248M| 2543 | | TABLE ACCESS BY INDEX|************ | 1 | 179 | 2 | | INDEX UNIQUE SCAN |*************** | 1 | | 1 | | TABLE ACCESS FULL |*********** | 1M| 73M| 2541 | | VIEW |******************* | 1M| 638M| 552401 | | WINDOW SORT | | 1M| 298M| 552401 | | HASH JOIN | | 1M| 298M| 484126 | | TABLE ACCESS FULL |**************** | 13 | 78 | 15 | | HASH JOIN | | 1M| 289M| 484103 | | TABLE ACCESS FULL |******************** | 2K| 26K| 15 | | HASH JOIN | | 1M| 273M| 484080 | | TABLE ACCESS FULL|************ | 6K| 66K| 56 | | HASH JOIN | | 1M| 284M| 484016 | | TABLE ACCESS FUL|*********** | 8K| 78K| 29 | | HASH JOIN | | 1M| 267M| 483978 | | TABLE ACCESS FU|******************** | 8K| 63K| 29 | | HASH JOIN | | 1M| 253M| 483941 | | TABLE ACCESS F|******************** | 1M| 12M| 2626 | | HASH JOIN | | 1M| 233M| 467504 | | TABLE ACCESS |******** | 163 | 1K| 15 | | HASH JOIN | | 1M| 216M| 467481 | | TABLE ACCESS|*********** | 6 | 36 | 15 | | HASH JOIN | | 1M| 206M| 467457 | | VIEW |index$_join$_026 | 988 | 9K| 9 | | HASH JOIN | | | | | | INDEX FAS|*************** | 988 | 9K| 4 | | INDEX FAS|******************** | 988 | 9K| 5 | | PARTITION R| | 2M| 229M| 467438 | | TABLE ACCE|************** | 2M| 229M| 467438 | Plans in shared pool between Begin and End Snap Ids ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Shows the Execution Plans found in the shared pool between the begin and end snapshots specified. The values for Rows, Bytes and Cost shown below are those which existed at the time the first-ever snapshot captured this plan - these values often change over time, and so may not be indicative of current values -> Rows indicates Cardinality, PHV is Plan Hash Value -> ordered by Plan Hash Value | TABLE ACCESS BY INDEX RO|******************** | 1 | 93 | 0 | | INDEX UNIQUE SCAN |******************** | 1 | | 0 | -------------------------------------------------------------------------------- End of Report
と、その時どのような実行計画で実行されたか確認することができる。
Operation 列が途中で切れてるのをなんとかできんかと思って調べてみたら、こんな感じでいけた。
SQL> select plan_hash_value from stats$sql_plan_usage where snap_id between 1770 and 1771 and old_hash_value = 3033987018; PLAN_HASH_VALUE --------------- 3503768424 3503768424 SQL> select * from table(dbms_xplan.display('PERFSTAT.STATS$SQL_PLAN',null,null,'PLAN_HASH_VALUE=3503768424')); PLAN_TABLE_OUTPUT ---------------------------------------------------------------------------------------------------------------------------------------------------- ---------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time | Pstart| Pstop | ---------------------------------------------------------------------------------------------------------------------------------------------------- |* 0 | SELECT STATEMENT | | | | | 1059K(100)| | | | |* 1 | SORT ORDER BY | | 1612K| 1757M| 4198M| 1059K (1)| 03:31:53 | | | |* 2 | HASH JOIN RIGHT OUTER | | 1612K| 1757M| | 673K (1)| 02:14:39 | | | |* 3 | TABLE ACCESS FULL | **************** | 6 | 558 | | 15 (0)| 00:00:01 | | | |* 4 | HASH JOIN RIGHT OUTER | | 1612K| 1614M| | 673K (1)| 02:14:38 | | | |* 5 | TABLE ACCESS FULL | ******** | 163 | 7987 | | 15 (0)| 00:00:01 | | | |* 6 | HASH JOIN | | 1612K| 1538M| | 673K (1)| 02:14:38 | | | |* 7 | TABLE ACCESS FULL | ************* | 42463 | 870K| | 56 (0)| 00:00:01 | | | |* 8 | HASH JOIN RIGHT OUTER | | 1612K| 1506M| | 673K (1)| 02:14:37 | | | |* 9 | TABLE ACCESS FULL | *********** | 6 | 234 | | 15 (0)| 00:00:01 | | | |* 10 | HASH JOIN RIGHT OUTER | | 1612K| 1446M| 21M| 673K (1)| 02:14:37 | | | |* 11 | TABLE ACCESS FULL | ************** | 673K| 14M| | 533 (2)| 00:00:07 | | | |* 12 | HASH JOIN | | 1612K| 1412M| | 600K (1)| 02:00:06 | | | |* 13 | TABLE ACCESS FULL | **************************** | 8124 | 618K| | 29 (0)| 00:00:01 | | | |* 14 | NESTED LOOPS OUTER | | 1612K| 1292M| | 600K (1)| 02:00:06 | | | |* 15 | HASH JOIN RIGHT OUTER | | 1612K| 1149M| | 600K (1)| 02:00:06 | | | |* 16 | TABLE ACCESS FULL | **************************** | 8124 | 618K| | 29 (0)| 00:00:01 | | | |* 17 | HASH JOIN | | 1612K| 1030M| 259M| 600K (1)| 02:00:05 | | | |* 18 | NESTED LOOPS | | 1020K| 248M| | 2543 (1)| 00:00:31 | | | |* 19 | TABLE ACCESS BY INDEX ROWID | ************ | 1 | 179 | | 2 (0)| 00:00:01 | | | |* 20 | INDEX UNIQUE SCAN | *************** | 1 | | | 1 (0)| 00:00:01 | | | |* 21 | TABLE ACCESS FULL | *********** | 1020K| 73M| | 2541 (1)| 00:00:31 | | | |* 22 | VIEW | ******************* | 1612K| 638M| | 552K (1)| 01:50:29 | | | |* 23 | WINDOW SORT | | 1612K| 298M| 629M| 552K (1)| 01:50:29 | | | |* 24 | HASH JOIN | | 1612K| 298M| | 484K (1)| 01:36:50 | | | |* 25 | TABLE ACCESS FULL | **************** | 13 | 78 | | 15 (0)| 00:00:01 | | | |* 26 | HASH JOIN | | 1612K| 289M| | 484K (1)| 01:36:50 | | | |* 27 | TABLE ACCESS FULL | ******************** | 2689 | 26890 | | 15 (0)| 00:00:01 | | | |* 28 | HASH JOIN | | 1612K| 273M| | 484K (1)| 01:36:49 | | | |* 29 | TABLE ACCESS FULL | ************ | 6846 | 68460 | | 56 (0)| 00:00:01 | | | |* 30 | HASH JOIN | | 1772K| 284M| | 484K (1)| 01:36:49 | | | |* 31 | TABLE ACCESS FULL | *********** | 8045 | 80450 | | 29 (0)| 00:00:01 | | | |* 32 | HASH JOIN | | 1772K| 267M| | 483K (1)| 01:36:48 | | | |* 33 | TABLE ACCESS FULL | **************************** | 8124 | 64992 | | 29 (0)| 00:00:01 | | | |* 34 | HASH JOIN | | 1772K| 253M| 24M| 483K (1)| 01:36:48 | | | |* 35 | TABLE ACCESS FULL | ************************* | 1069K| 12M| | 2626 (1)| 00:00:32 | | | |* 36 | HASH JOIN | | 1772K| 233M| | 467K (1)| 01:33:31 | | | |* 37 | TABLE ACCESS FULL | ******** | 163 | 1630 | | 15 (0)| 00:00:01 | | | |* 38 | HASH JOIN | | 1772K| 216M| | 467K (1)| 01:33:30 | | | |* 39 | TABLE ACCESS FULL | *********** | 6 | 36 | | 15 (0)| 00:00:01 | | | |* 40 | HASH JOIN | | 1772K| 206M| | 467K (1)| 01:33:30 | | | |* 41 | VIEW | index$_join$_026 | 988 | 9880 | | 9 (0)| 00:00:01 | | | |* 42 | HASH JOIN | | | | | | | | | |* 43 | INDEX FAST FULL SCAN| *************** | 988 | 9880 | | 4 (0)| 00:00:01 | | | |* 44 | INDEX FAST FULL SCAN| *************************** | 988 | 9880 | | 5 (0)| 00:00:01 | | | |* 45 | PARTITION RANGE ALL | | 2150K| 229M| | 467K (1)| 01:33:30 | 1 | 65 | |* 46 | TABLE ACCESS FULL | ************** | 2150K| 229M| | 467K (1)| 01:33:30 | 1 | 65 | |* 47 | TABLE ACCESS BY INDEX ROWID | ************************ | 1 | 93 | | 0 (0)| | | | |* 48 | INDEX UNIQUE SCAN | *************************** | 1 | | | 0 (0)| | | | ---------------------------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 0 - access(0) filter(0) 1 - access(0) filter(0) 2 - access(0) filter(0) ... 48 - access(0) filter(0) Note ----- - 'PERFSTAT.STATS$SQL_PLAN' is old version 160 rows selected.
参考
*1:自分の場合、パフォーマンス問題が発生したときに後から解析しやすいように statspack のスナップショット、v$session、v$sysstat、OSの統計情報(top、vmstatなど)などを自動的に収集するようにしています。
