はじめに Oracle のチューニングポイントは待機イベントを減らすこと!! 待機イベントの解消 = パフォーマンス向上 2

Size: px

Start display at page:

Download "はじめに Oracle のチューニングポイントは待機イベントを減らすこと!! 待機イベントの解消 = パフォーマンス向上 2"

みがねちゅうか
7 years ago
Views:

1 おら! オラ!Oracle - どっぷり検証生活 - リスクに備えたログ管理の重要性 ~DB 特権ユーザのモニタリング~ Oracle Database 現場で役立つパフォーマンスチューニング 2010 年 8 月 25 日株式会社インサイトテクノロジーエンジニアリング本部テクノロジーコンサルティング部松尾亮 1

2 はじめに Oracle のチューニングポイントは待機イベントを減らすこと!! 待機イベントの解消 = パフォーマンス向上 2

3 待機イベントとは? プロセスが CPU を使用していない時間 User I/O ロック競合 etc SQL 実行 Commit 実行サーバプロセス SQL 解析ロック待ち User I/O Redo 生成 commit バックグラウンドプロセス CPU Time 待機イベント Redo ログ書き込み 3

4 待機イベントの確認方法ある期間におけるインスタンス全体の待機イベントを確認したいパフォーマンス統計レポート (STATSPACK or AWR) を確認 - STATSPACK Oracle ~ - AWR Oracle ~ EE のみ利用可今回のセミナーでは Standerd Edition でも利用可能な STATSPACK を例にして説明しますある特定の処理おける待機イベントを確認したい SQL トレース動的パフォーマンスビュー (V$ 表 ) を確認 4

5 STATSPACK 概要ある期間 (snapshot 間 ) のデータベース処理の統計情報をレポートする定期的にスナップショットを DB に保存 ( 手動 ) Standard Edition で利用可能! time snap#1 snap#2 snap#3 #1~#3 間のレポート取得 #2~#3 間のレポート取得待機イベント統計 SGA のヒット率セッション統計 etc 5

6 STATSPACK の使用方法 SQL> -- STATSPACK 環境のインストール SQL> conn / as sysdba STATSPACK 管理ユーザ (perfstat) のパスワードオブジェクト格納表領域一時表領域を指定 SQL> -- スナップショットの取得 SQL> conn perfstat/password SQL> exec statspack.snap(i_snap_level=>7); スナップショットレベルについては次ページに記載 SQL> -- レポートの取得 SQL> conn perfstat/password レポートの開始 ID 終了 ID レポートファイル名を指定 6

7 STATSPACK の取得レベル (9iR2~) level 収集データ基本統計アドバイス情報 SQL 統計 SQL 詳細セグメント情報ラッチ詳細デフォルトは level 5 だが level 7 の情報が役立つことが多い Level 10 は情報量が多くスナップショット取得にかかる負荷が高くなる為サポートから依頼された場合を除き基本的に使用しない 7

8 STATSPACK レポートで最も注目すべきポイント Top 5 待機イベントがレポートで最も注目すべきポイント! Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time enq: TX - row lock contention 14,858 3, gc buffer busy acquire 419,613 2, shared server idle wait 453,775 1, enq: TX - index contention 32,020 1, CPU time 1, Waits : イベントのために待機した合計回数 Time(s) : 合計待機時間 ( 秒 ) Avg wait(ms) : 平均待機時間 %Total Call Time : 全ての待機時間に対する占有比率上位の待機イベントの解消 = チューニング効果の期待大 8

9 STATSPACK での調査ステップ 1. Top 5 待機イベントを確認 2. 上位の待機イベントの意味を確認 ( マニュアル KROWN 等 ) 3. 待機イベントの発生要因に関連するセクションを調査 ex) db file scattered read db file sequential read 等 SQL Ordered By XXX セクションを確認 SQL チューニング? enqueue Enqueue activity Segments by Row Lock Waits セクションを確認アプリ処理の見直し? buffer busy waits Segments by Buffer Busy Waits セクションを確認空きリスト競合? 逆キー索引パーティション化? 9

10 調査例ステップ 1 待機イベントの上位に以下 2 つのイベントが出現 db file scattered read マルチブロック読込 (Full Scan Index Fast Full Scan など ) db file sequential read 単一ブロック読込 (Index Scan) SQL の I/O 関連イベントなので SQL ordered by Elapsed time SQL ordered by Gets 等を確認 SQL ordered by Elapsed time for DB: Elapsed Elap per CPU Old Time (s) Executions Exec (s) %Total Time (s) Physical Reads Hash Value Module: httpd@web001.test.local (TNS V1-V3) SELECT FROM TAB1 WHERE 10

11 調査例ステップ 2 SQL ordered by XXX で確認した SQL 分析レポートを取得 Snap Snap Instance DB Name Id Snap Started Level Comment orcl orcl 1 23 Aug : Aug : Aug : Aug :30 7 Specify the Begin and End Snapshot Ids ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ begin_snap に値を入力してください : 1 Begin Snapshot Id specified: 1 end_snap に値を入力してください : 2 End Snapshot Id specified: 2 Specify the Hash Value ~~~~~~~~~~~~~~~~~~~~~~ hash_value に値を入力してください : Hash Value specified is:

12 調査例ステップ 3 SQL レポートを確認 First First Last Plan Snap Id Snap Time Active Time Hash Value Cost 月 : 月 : 月 : 月 : 実行計画が変更されたタイミングが確認できる ~ 略 ~ Operation PHV/Object Name Rows Bytes Cost SELECT STATEMENT FOR UPDATE PARTITION HASH ALL TABLE ACCESS BY LOCAL INDEX RO TAB INDEX RANGE SCAN TAB1_IDX SELECT STATEMENT FOR UPDATE PARTITION HASH SINGLE TABLE ACCESS BY LOCAL INDEX RO TAB INDEX RANGE SCAN TAB1_IDX

13 STATSPACK での分析に向かないケースある特定の処理が遅かったある特定の瞬間だけ遅かったスナップショットの取得間隔が 30 分間で - 通常 1 秒で終了する処理が 1 分かかった - ある 1 分間の間だけ高負荷状態になった etc このような場合 STATSPACK でボトルネックを検出することは困難 13

14 特定の SQL 調査 (SQL トレースを取得 ) 特定の SQL の待機イベント情報を含めた SQL トレースを取得 SQL> alter session set events '10046 trace name context forever, level 8'; ~ 問題のSQLを実行 ~ SQL> alter session set events '10046 trace name context off'; 実行中のセッションに対して SQL トレースを取得 -- v$session 等の情報からセッションを特定 alter session set nls_date_format='yyyy/mm/dd HH24:MI:SS'; select username,program,server,status,sid,serial#,last_logon_time from v$session where username is notnull; -- 特定した sid serial# に対して SQL トレースを取得 exec sys.dbms_system.set_ev(&sid, &serial, 10046, 8, ''); exec sys.dbms_system.set_ev(&sid, &serial, 10046, 0, ''); 取得したトレースファイルを整形 ( 初期化パラメータ user_dump_dest or background_dump_dest に出力される ) $ tkprof < トレースファイル名 > < 整形後ファイル名 > sys=no 14

15 特定の SQL 調査 (SQL トレースを確認 1) OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows Parse Execute Fetch total Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited Waited SQL*Net message to client SQL*Net message from client row cache lock ges message buffer allocation library cache lock KJC: Wait for msg sends to complete library cache pin SQL*Net break/reset to client gc cr grant 2-way Disk file operations I/O db file sequential read

16 特定の SQL 調査 (SQL トレースを確認 2) ( 参考 ) TKPROF 整形前のトレース ~ 略 ~ WAIT #2: nam='db file sequential read' ela= 1211 file#=2 block#=18914 blocks=1 obj#=-1 tim= WAIT #2: nam='ges message buffer allocation' ela= 8 pool=0 request=1 allocated=0 obj#=-1 tim= WAIT #2: nam='gc cr disk read' ela= 226 p1=2 p2=18922 p3=4 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 1338 file#=2 block#=18922 blocks=1 obj#=-1 tim= WAIT #2: nam='ges message buffer allocation' ela= 9 pool=0 request=1 allocated=0 obj#=-1 tim= WAIT #2: nam='gc cr disk read' ela= 204 p1=2 p2=18930 p3=4 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 6934 file#=2 block#=18930 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 2327 file#=2 block#=18946 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 5903 file#=2 block#=18954 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 507 file#=2 block#=18962 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 2536 file#=2 block#=18970 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 5483 file#=2 block#=18978 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 3660 file#=2 block#=18986 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 496 file#=2 block#=18994 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 499 file#=2 block#=19002 blocks=1 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 504 file#=2 block#=19010 blocks=1 obj#=-1 tim= ~ 略 ~ 16

17 特定の SQL 調査 (SQL 実行計画を確認 ) 実行計画の確認は個人的には Explain Plan がお薦め! SQL を実行せずに Plan を表示する実際に実行すると Plan が変わることがあるので注意 Predicate Information に出力される ID による紐付け索引使用可否の判断該当の where 句の判断が容易 -- PLAN_TABLE を作成 -- SQL を解析 SQL> explain plan for 解析したい SQL 文 ; Explained. -- 解析結果を表示 SQL> select * from table(dbms_xplan.display()); 別紙にて詳細解説 17

18 チューニング事例紹介 ( ここからは Performance Insight を活用 ) 18

19 事例 1 ~ 概要 ~ システム概要モバイルコンテンツ配信システムの DB Oracle11gR1 2node RAC 状況テスト期間中アプリの改修に伴い索引を新規追加追加後の動作検証 ( 負荷テスト ) で遅延が発生 ( 追加前 :400 処理 / 秒追加後 :200 処理 / 秒 ) 追加した表は複数セッションから insert (1 処理 1 件 ) が大量に行われるという特性がある要望索引を追加した状態で追加前と同等のパフォーマンスに戻したい 19

20 事例 1 ~ 状況 ~ 索引追加前 CPU 使用率索引追加後 CPU 使用率待機イベント待機イベント CPU 使用率は減少 (CPU が使えていない ) ロック関連の待機イベントが多発! 20

21 事例 1 ~ 状況 (STATSPACK では )~ 索引追加後 Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time enq: TX - row lock contention 14,858 3, gc buffer busy acquire 419,613 2, shared server idle wait 453,775 1, enq: TX - index contention 32,020 1, CPU time 1, Host CPU (CPUs: 16 Cores: 8 Sockets: 2) ~~~~~~~~ Load Average Begin End User System Idle WIO WCPU

22 事例 1 ~ 状況 ~ 索引追加前ロック発生オブジェクト索引追加後ロック発生オブジェクト buffer busy 発生オブジェクト buffer busy 発生オブジェクト追加した索引に関連する表索引に対するロック buffer busy が多発している! 22

23 事例 1 ~ 状況 (STATSPACK では )~ 索引追加後 Segments by Row Lock Waits Row Subobject Obj. Lock Pct Owner Tablespace Object Name Name Type Waits Total SCOTT TS_INDEX TEST1_PKEY INDEX 10, SCOTT TS_INDEX TEST2_PKEY INDEX 8, SCOTT TS_INDEX TEST3_PKEY INDEX 7, SCOTT TS_INDEX TEST4_IDX1 INDEX 1, SCOTT TS_DATA TEST2_TAB TABLE Segments by Buffer Busy Waits Buffer Subobject Obj. Busy Pct Owner Tablespace Object Name Name Type Waits Total SCOTT TS_INDEX TEST1_PKEY INDEX 20, SCOTT TS_INDEX TEST2_PKEY INDEX 18, SCOTT TS_INDEX TEST3_PKEY INDEX 16, SCOTT TS_INDEX TEST3_IDX2 INDEX 3, SCOTT TS_INDEX TEST4_IDX1 INDEX 3,

24 事例 1 ~ 現場の様子 ~ この時の現場の様子をお届けしますアプリ担当者 ( 以下アプリ ) アプリ改修したので使いそうな索引を追加しました DBA 分かりました確認しますってめちゃくちゃいっぱいあるじゃないですか! この索引全部使うんですか?? アプリいやーちょっと分からないんですけど使うかもしれないとこには全部作ってみました 24

25 事例 1 ~ 現場の様子 ~ DBA そそうですか確か今回索引を追加する表ってどれも insert が大量に実行されるテーブルですよね? 索引があると insert は遅くなるんですよだから検索に使われない索引は削除したいですねアプリはーそうですか DBA まとりあえず負荷テストしてみますかそんなに影響出ないかもしれないし 25

26 事例 1 ~ 現場の様子 ~ パフォーマンス 50% に Down! DBA あららちょっと想像以上に遅くなりましたねまずは使われてない索引を削除しましょうか想定される一連の処理を実行してもらえますか? アプリはい分かりましたしばし待ち実行終了 26

27 事例 1 ~ 現場の様子 ~ DBA 使われてない索引がいくつかあったので削除しますねこれとこれとこれらは削除しても影響なさそうですか? 確実に使う筈というものがあれば教えて下さいアプリうーん削除しても大丈夫だと思います DBA じゃ削除しますねーそして再度負荷テスト 10% くらいパフォーマンス回復まだあと 40% 27

28 事例 1 ~ 現場の様子 ~ ( ちょっと break) 使用されていない索引の確認方法として索引のモニタリング機能がありますが v$sql_plan でメモリに存在する実行計画を参照し現在実行計画に使用されていないインデックスを確認するという方法も可能です短期間のテスト等ではお手軽に確認できます SQL> select object_name,object_type,hash_value 1 from v$sql_plan 2 where object_type like 'INDEX%' and object_name like '%EMP%' 3 group by object_name,object_type,hash_value 4 order by 1,2; OBJECT_NAME OBJECT_TYPE HASH_VALUE IDX_EMP_1 INDEX PK_EMP INDEX (UNIQUE) PK_EMP INDEX (UNIQUE) 出力されてない検索に利用されてない 28

29 事例 1 ~ 現場の様子 ~ DBA insert 競合を解消するにはフリーリストを増やす! かな試してみるか! と思ったけどこの表がある表領域は自動セグメント領域管理だったフリーリストの調整はできないじゃんえーっとこの表は連番で insert されていくからどうしても索引のブロックは競合するんだろうな insert insert insert 索引ブロック : insert insert 索引は順番に並んで格納される為このシステムの処理特性上同一ブロックへの競合が発生しやすい! 29

30 事例 1 ~ 現場の様子 ~ ( またまたちょっと break) フリーリストとは insert 可能な空きブロックの情報を管理している領域 insert 時にはフリーリストの空きブロック情報を参照する為 insert の多重度が高いとフリーリストへのアクセスが競合するその場合フリーリストを増加させることでパフォーマンスが向上する可能性がある自動セグメント領域管理 (ASSM) ではビットマップ情報で空きブロック情報が管理され明示的に調整はできない Insert Insert フリーリスト insert 可能なブロックのリスト #1 ( 空き ) #2 #3 #4 Insert Insert Insert block#1 block#5 block#7 #5 ( 空き ) #6 #7 ( 空き ) #8 30

31 事例 1 ~ 現場の様子 ~ DBA 連番で次々と insert されてくるデータを同一ブロックに集中させない為にはハッシュパーティションだな! 逆キー索引も有効か??? でも逆キー索引は範囲検索できないんだよな確かパーティションオプション持ってるしパーティショニングしてみるか! 問題となっていそうな表と索引をハッシュパーティション化性能改善! 更に以前より 20% 程度の性能向上! 31

32 事例 1 ~ 解説 ~ [ 原因 ] 連番データの insert が多重実行されるという特性であった為同一ブロックへの競合が発生しやすい状況であったそのような状況で過剰に索引を追加したことによりブロック競合が多発した [ 対処 ] 1. 丌要な索引の削除 2. ハッシュパーティショニング 32

33 事例 1 ~ 解説 ~ 索引がボトルネックになる場合もある - 更新系処理では表データと同様に索引データの更新も必要となる為オーバヘッドがかかる - 連番データの insert が多重実行されるような場合索引ブロックの競合が発生しやすい 33

34 事例 2 ~ 概要 ~ システム概要金融系システムのDB Oracle10gR1 4node RAC 状況取引は月曜午前 7 時から土曜午前 7 時まで土曜の日中にメンテナンス作業実施月曜午前 7 時のオープン直後からDBの負荷が急上昇サーバハングによる障害発生要望障害調査を依頼 34

35 事例 2 ~ 状況 ~ CPU 使用率障害復旧待機イベント enqueue の TS(Temp Segment) SS(Sort Segment) が増加している 35

36 事例 2 ~ 状況 ~ データファイル I/O TEMP 表領域への物理アクセスが多い過剰なソートを実行している SQL がある?? 36

37 事例 2 ~ 状況 ~ 高負荷 SQL SQL [Hash Value=XXXXXXXXXX] SELECT FROM TAB1 WHERE DATE-TIME ROWS DISK_READS BUFFER_GETS CPU_TIME ELAPSED_TIME (YYYY/MM/DD HH24:MI:SS) EXEC /EXEC /EXEC /EXEC /EXEC(Sec) /EXEC(Sec) /11/02 07:45: ,836 21, SQL [Hash Value=??????????] SELECT FROM TAB2 WHERE DATE-TIME ROWS DISK_READS BUFFER_GETS CPU_TIME ELAPSED_TIME (YYYY/MM/DD HH24:MI:SS) EXEC /EXEC /EXEC /EXEC /EXEC(Sec) /EXEC(Sec) /11/02 07:45: ,302 11, CPU_TIME と ELAPSED_TIME の差が大きい待機イベント時間が長いということ! 37

38 事例 2 ~ 現場の様子 ~ この時の現場の様子をお届けします土曜の日中 Aさん古いデータを大量に削除したからフラグメンテーションを解消しとかないとな SQL> alter table EMP move; SQL> alter index PK_EMP rebuild; SQL> alter index IDX_EMP_1 rebuild; SQL> alter index IDX_EMP_2 rebuild; A さんこれで良しさ帰ろっと 38

39 事例 2 ~ 現場の様子 ~ 月曜 7 時 A さんの携帯に運用監視オペレータから電話が OP A さんっ!DB サーバの CPU が 100% に張り付きっぱなしでサービスが停まってます! A さんえぇ!? すぐ確認します! A さんはリモート接続してすぐに調査を開始 39

40 事例 2 ~ 現場の様子 ~ 月曜 7 時 30 分頃 A さん土曜にメンテナンスした表にアクセスしている SQL が遅いみたいだな実行計画が変わっちゃったみたいよし統計情報を収集しよう! SQL> exec dbms_stats.gather_table_stats( - ownname => 'SCOTT', - tabname => 'EMP', - cascade => true); A さんどうかなぁ 40

41 事例 2 ~ 現場の様子 ~ 駄目だ!! 実行計画も変わってないようだ A さん統計情報を再収集したから再解析してる筈なんだけどなぁ何で実行計画が変わってくれないんだろブツブツその後しばらく試行錯誤するも状況は改善せず 41

42 事例 2 ~ 現場の様子 ~ 月曜 8 時頃 A さんどうしよう何か他に手はないかなあ実行計画の問題だから共有プールも関係あるか? とりあえずフラッシュしてみよう SQL> alter system flush shared_pool; A さんん? ちょっと負荷が下がってきたか? おぉー! 下がった下がった! よかった ~ これで一安心でもかなり大きな損害が 42

43 事例 2 ~ 解説 ~ [ 原因 ] 以下のメンテナンス作業によって表のオプティマイザ統計情報が削除された 1. 表の再編成 (move 処理 ) 2. 索引の再編成 (rebuild 処理 ) その後統計情報再収集を行わなかった為デフォルトの統計情報が利用され結果的に適切な実行計画が選択されなかった ( 補足 ) move 処理後は索引が使用丌可 (STATUS=UNUSABLE) となる為 rebuild 処理が必須 43

44 事例 2 ~ 解説 ~ [ 統計情報の収集後実行計画が変わらなかったワケ ] dbms_stats.gather_table_stats の no_invalidate オプションが auto_invalidate (10gR1 以降のデフォルト値 ) だった為この auto_invalidate の場合新しい統計情報を利用した再解析が行われるまでにタイムラグがある ( しばらくの間は既存のカーソルを再利用する ) [ 対策 ] 1.no_invalidate を false にして実行する ( 実行例 ) or 2. 共有プールをフラッシュする SQL> exec dbms_stats.gather_table_stats( - ownname => 'SCOTT', - tabname => 'EMP', - cascade => true, - no_invalidate => false); 44

45 Question? 45

46 製品のご紹介データベース監査ツールパフォーマンス管理ツールデータベースログ管理に必要なすべてを提供するツール 300 社 1,800 ライセンスを超える販売実績で J-SOX および情報漏洩対策ツールのシェア No.1 大規模顧客大規模システムへの導入に強み対応データベース Oracle Database EE/SE Microsoft SQL Server(2000_32bit.2005_32bit) Fujitsu Symfoware Server パフォーマンス管理パフォーマンスチューニングを実現するツール実績 1995 年の販売以来 1,000 社 8,000 ライセンスを超える販売実績オラクルデータベースの 6 本に 1 本の割合で導入されるパフォーマンスツールのデファクトスタンダード対応データベース Oracle Database EE/SE/SE1 オラクルデータベースの 6 本に 1 本という数字は特定パートナー様からの報告内容より引用しております Copyright 2009 Insight Technology, Inc. All Rights Reserved. 46

おら! オラ!Oracle どっぷり検証生活 Oracle を徹底検証した結果を隔週水曜日に配信していますご登録はこちらから ( 無料!) http://www.insight-tec.

~~~~~~~~~~~~~~~~~~ wait Call CPU time 1, latch: library cache 7, latch: library cache lock 4, job scheduler co

072 DB Magazine 2007 September ~~~~~~~~~~~~~~~~~~ wait Call CPU time 1,055 34.7 latch: library cache 7,278 750 103 24.7 latch: library cache lock 4,194 465 111 15.3 job scheduler coordinator slave wait

はじめに Oracle のチューニングポイントは 待機イベントを減らすこと!! 待機イベントの解消 = パフォーマンス向上 2

はじめに Oracle のチューニングポイントは待機イベントを減らすこと!! 待機イベントの解消 = パフォーマンス向上 2