前回(6/17)に引き続き、Oracle の性能問題に対する調査方法についてのセミナーに参加させていただきました。
- 「実習セミナー：RAC環境でのレスポンス遅延を調査・解決」 | oracletech.jp
今回のコンテンツは、RAC環境でのレスポンス遅延の事例を扱います。RAC環境に関しては、触れる機会自体がそれほどないこともありますし、調査においてはシングル環境にはない特別なノード間の処理を意識する必要があるなど、上級者の方にとっても歯ごたえのある内容になっています。なお、あまり経験がないという初級者の方も、5つの演習が調査手順に沿った内容になっていますので、演習は厳しいかもしれませんが「演習毎の"解説"を理解すること」を目的に受講いただくだけでも、十分満足していただける内容かと思います。
- 前回までのレポート
講師は PS ソリューションズ 井上さま。３年弱の業務の中で Oracle Master Platinum を取得され、先日 11g のアップグレード試験を受けられて、その結果待ちとのこと。サポートエンジニアの資格もお持ちとのことです。
今回のお題は、2 Node RAC で構成されているシステムで「Node1 側で実行された処理のレスポンスが悪い」という報告がありました。手元にあるのはそれぞれのノードにおける正常時と障害時の AWR レポートのテキストファイル 4 つ。そこからレスポンス遅延の原因および処理の特定を行いましょうというもの。
前回までと同様、実際に調査する際の流れに沿って演習が進められました。
- Node1 の稼働傾向を確認して、障害の原因、ならびに次に調査する項目を検討する
- Node2 の稼働傾向を確認して、障害の原因、ならびに次に調査する項目を検討する
- Node2 の REDO ログの処理状況を確認して、障害の原因を検討する
- Node1 で遅延していたと考えられる処理を確認する
- まとめ
今回は事前アンケートによる AWR レポートの調査経験の有無を参考にして 3人 1組のグループが決められており、当日受付で通知されたグループ番号にしたがって席に着きました。座席にある USB メモリから、各自持参した PC にファイルを取り込んで調査を始めました。
以下、状況の確認と推測については講師による解説を中心に、後付けで調べたマニュアル情報などを併記しています。
稼働傾向の確認
稼働傾向は AWR レポートの以下の項目を確認しました。- Oracle の CPU 使用率(Instance Activity Stats)
- CPU 使用率は
CPU used by this sessionの情報を用いて以下の式で算出。Oracle の CPU 使用率(%) = per Second の値 / CPU の core 数
- CPU 使用率は
- DB に対する負荷量と処理量(Load Profile)
- 負荷量は
Executions(参照系と更新系の処理回数) とTransactions(更新系の処理回数)の値 - 処理量は
Redo size(書込量の目安) とLogical reads(読込量の目安) の値
- 負荷量は
- 待機イベントの発生状況(Top 5 Timed Events)
- CPU 使用率は、正常時と障害時でそれほど変化はなく 12% 程度
- それほど高い状況ではないため CPU リソースが枯渇した事によるものではない
- 負荷量は変化していないが処理量が増加している
- 負荷量は変わらずに処理量が増えていることから、１実行当たりの処理量が増加している
- 障害発生時は
gc cr block busyの待機が発生しており総処理時間の 25% を占めている- 処理に必要なブロックを Node2 から転送(キャッシュ・フュージョン)する際に、まだ該当ブロックが Node2 にて処理中の状態であったと考えられる
- 待機イベントに基づく応答時間の分析 - Oracle Database Oracle ClusterwareおよびOracle Real Application Clusters管理およびデプロイメント・ガイド 10g リリース2（10.2）
gc current block busyおよびgc cr block busyの待機イベントは、リモート・インスタンス処理が遅延した後で、リモート・インスタンスがブロックを受信したことを示します。ほとんどの場合は、ログ・フラッシュが原因です。これらの待機イベントが存在しても、そのブロックの並列性が高いとはかぎりません。並列性は、gc buffer busyイベントが存在する場合に高くなります。このイベントは、リモート・インスタンスのセッションで、ブロックが確保または保留されていることを示します。また、同じインスタンス上のセッションがすでに同じブロックを要求していることを示す場合もあります。いずれの場合も、インスタンス間で移動中のブロックにアクセスしているため、現行のセッションが待機状態になっていることを示します。
- CPU 使用率は障害時に 4% 程度増えているが、それでも 12% 程度
- 増加後の値も 12% 程度であることから CPU リソースが枯渇した事によるものではない
- 使用率の増加は、DB に対する処理量及び負荷量が増加したことに起因していると考えられる
- 負荷量、処理量ともに増加している。とくに書込量が約 100 倍に増加している。(更新系の負荷量はほぼ増加していない
- 更新系の負荷量が増加していないにもかかわらず処理量(とくに書込量)が増加しているため、1実行当たりの更新量が増加していると考えられる
gcs log flush sync、log file parallel writeの待機が発生しており、合計の待機時間が総処理時間の約 23% を占めている- REDO ログの書き出しにて処理が遅延していると考えられる
- アイドル・イベント - Oracle Enterprise Manager Oracle Databaseおよびデータベース関連メトリック・リファレンス・マニュアル 10gリリース2（10.2）
- RMOUG 2010: My presentations « Oracle database internals by Riyaj
- Gcs log file sync (p15)
- But, if the instances crash right after the block is transferred to other node, how does RAC maintain consistency?
- Actually, before sending a current mode block LMS process will request LGWR for a log flush.
- Until LGWR sends a signal back to LMS process, LMS process will wait on 'gcs log flush' event.
- CR block transfer might need log flush if the block was considered "busy"
- One of the busy condition
- LGWR and CPU priority (p47)
- LGWR performance is akin to Global cache performance.
- If LGWR suffers from performance issues, it will reflect on Global cache performance.
- For example, If LGWR suffers from CPU latency issues, then LMS will have longer waits for 'gcs log flush sync' event
- This leads to poor GC performance in other nodes.
- Gcs log file sync (p15)
- log file parallel write - Oracle待機イベント - Oracle Database リファレンス 10g リリース2（10.2）
REDOレコードをログ・バッファからREDOログ・ファイルに書き込んでいます。待機時間: 物理的I/O（書込み）の完了に必要な時間。REDOレコードはパラレルで書き込まれますが、パラレル書込みは、最後のI/Oがディスク上に書き込まれるまで完了しません。
REDO ログの処理状況を確認
REDO ログの処理状況は AWR レポートの以下の項目を確認しました。- REDO ログの書込速度(Wait Events)
- log switch の発生回数(Instance Activity Stats - Thread Activity)
log file parallel writeの Avg wait(ms) はほとんど同じ- 1回当たりの REDO ログへの書込速度は遅延していない。
- 障害時は log switch が約 3 分に 1 回(19回/1時間)発生している
- REDO ログの書込処理(I/O)が遅延している状況ではなく、書込量が多くなったことにより遅延が発生していると考えられる
遅延していた処理の特定
Node1 で遅延していた処理の特定は AWR レポートのSQL ordered by Cluster Wait Time を確認しました。
- あるパッケージ・プロシージャの呼び出しが上位 2つにある
- その 2つの Cluster Wait Time (s) を合計すると、
gc cr block busyの待機時間とほぼ等しくなっている
調査まとめ
今回の解説のスライドにある図が大変わかりやすかったので、おぼろげな記憶を頼りに遅延状況が発生していた時のイメージを起こしてみました。
- Node1
- Oracle の CPU 使用率に変化は見られない
- 処理量が増加している(負荷量は変化なし)
- 障害発生時は
gc cr block busyの待機が発生しており、総処理時間の約 25% を占めている - とあるパッケージの処理(SQL)が遅延している
- Node2
- Oracle の CPU 使用率が 4% 程度上昇している
- 処理量、負荷量共に増加している(更新系の負荷量はほぼ増加していないが、処理量は約 100倍に増加している)
- 障害発生時は、
gcs log flush sync、log file parallel writeの待機が発生しており、合計の待機時間が総処理時間の 23% を占めている - 1 回当たりの REDO ログ書き込み速度に遅延は見られない
- 障害時は、log switch が約 3分に 1回発生している
対策としては次のようなことが考えられます。
- REDO 生成量の削減
- キャッシュ・フュージョン量の削減
この分析結果をもってセミナは終了したのですが、受講者から対策についての具体案について質問がありました。REDO 生成量についてはロギングしない、SQL をチューニングするというような案があるようです。また、気づくと別の案について twitter で盛り上がっていました。
RAC を使用している今の現場では AWR レポートではなく statspack を参照するときがありますが、今回のセミナで RAC 環境におけるレポートの読み進め方がわかり大変参考になりました。以前学習した 『ORACLE MASTER Expert [RAC]編』をもう一度、見直そうと思いました。
今回の演習は持ち込み PC の使用が可能でしたので MacBook Air を持参しました。そのため「画面が小さい」「JIS 配列のキー打ちづらい」「キーピッチが小さい」「gedit 使いづらい」などと本筋とは関係の無いところに対する言い訳は使えませんでした。vim のタブに 4つのファイルを展開して、それとは別のタブに正常時・障害時、ノード1・ノード2を縦分割して表示してました。ただ、検索は単なる / や ? しか普段も使ってないので、grep 系のプラグインを入れてもっと検索を効率化したいなと、勉強会のテーマとは別のところで課題を見つけてしまいました（＾＾；
なお、今回のセミナと同じ演習を Oracle DBA & Developer Days 2011 の 180分枠で行われるそうです。それとは別に、「ORA-4031」をテーマにした座学もあるそうです。興味のある方は是非！また、性能問題調査の第３弾は１０月に予定されているようですのでこちらも要チェックです。１０月と言えば INSIGHT OUT 2011 – DB Tech Showcase もありますし、DB 関連のイベントが満載ですね。
0 件のコメント:
コメントを投稿