2011/09/04

Oracle実習セミナー行ってきました（Part3）

,

前回(6/17)に引き続き、Oracle の性能問題に対する調査方法についてのセミナーに参加させていただきました。

講師は PS ソリューションズ 井上さま。３年弱の業務の中で Oracle Master Platinum を取得され、先日 11g のアップグレード試験を受けられて、その結果待ちとのこと。サポートエンジニアの資格もお持ちとのことです。

今回のお題は、2 Node RAC で構成されているシステムで「Node1 側で実行された処理のレスポンスが悪い」という報告がありました。手元にあるのはそれぞれのノードにおける正常時と障害時の AWR レポートのテキストファイル 4 つ。そこからレスポンス遅延の原因および処理の特定を行いましょうというもの。

前回までと同様、実際に調査する際の流れに沿って演習が進められました。

  1. Node1 の稼働傾向を確認して、障害の原因、ならびに次に調査する項目を検討する
  2. Node2 の稼働傾向を確認して、障害の原因、ならびに次に調査する項目を検討する
  3. Node2 の REDO ログの処理状況を確認して、障害の原因を検討する
  4. Node1 で遅延していたと考えられる処理を確認する
  5. まとめ

今回は事前アンケートによる AWR レポートの調査経験の有無を参考にして 3人 1組のグループが決められており、当日受付で通知されたグループ番号にしたがって席に着きました。座席にある USB メモリから、各自持参した PC にファイルを取り込んで調査を始めました。

以下、状況の確認と推測については講師による解説を中心に、後付けで調べたマニュアル情報などを併記しています。

稼働傾向の確認

稼働傾向は AWR レポートの以下の項目を確認しました。
  • Oracle の CPU 使用率(Instance Activity Stats)
    • CPU 使用率は CPU used by this session の情報を用いて以下の式で算出。 
      Oracle の CPU 使用率(%) = per Second の値 / CPU の core 数
  • DB に対する負荷量と処理量(Load Profile)
    • 負荷量は Executions(参照系と更新系の処理回数) と Transactions(更新系の処理回数)の値
    • 処理量は Redo size(書込量の目安) と Logical reads(読込量の目安) の値
  • 待機イベントの発生状況(Top 5 Timed Events)
まずは Node1 で上記項目を確認して、状況を推測。
  • CPU 使用率は、正常時と障害時でそれほど変化はなく 12% 程度
    • それほど高い状況ではないため CPU リソースが枯渇した事によるものではない
  • 負荷量は変化していないが処理量が増加している
    • 負荷量は変わらずに処理量が増えていることから、１実行当たりの処理量が増加している
  • 障害発生時は gc cr block busy の待機が発生しており総処理時間の 25% を占めている
    • 処理に必要なブロックを Node2 から転送(キャッシュ・フュージョン)する際に、まだ該当ブロックが Node2 にて処理中の状態であったと考えられる
出ました RAC 固有の　gc〜 で始まるグローバル・キャッシュ・サービスの待機イベント。マニュアルを見ると次のようにあります。
  • 待機イベントに基づく応答時間の分析 - Oracle Database Oracle ClusterwareおよびOracle Real Application Clusters管理およびデプロイメント・ガイド 10g リリース2（10.2）
    gc current block busyおよびgc cr block busyの待機イベントは、リモート・インスタンス処理が遅延した後で、リモート・インスタンスがブロックを受信したことを示します。ほとんどの場合は、ログ・フラッシュが原因です。これらの待機イベントが存在しても、そのブロックの並列性が高いとはかぎりません。並列性は、gc buffer busyイベントが存在する場合に高くなります。このイベントは、リモート・インスタンスのセッションで、ブロックが確保または保留されていることを示します。また、同じインスタンス上のセッションがすでに同じブロックを要求していることを示す場合もあります。いずれの場合も、インスタンス間で移動中のブロックにアクセスしているため、現行のセッションが待機状態になっていることを示します。
どうやら Node2 で何らかの問題が発生しているようですね。ということで Node2 の項目を確認して状況を推測。
  • CPU 使用率は障害時に 4% 程度増えているが、それでも 12% 程度
    • 増加後の値も 12% 程度であることから CPU リソースが枯渇した事によるものではない
    • 使用率の増加は、DB に対する処理量及び負荷量が増加したことに起因していると考えられる
  • 負荷量、処理量ともに増加している。とくに書込量が約 100 倍に増加している。(更新系の負荷量はほぼ増加していない
    • 更新系の負荷量が増加していないにもかかわらず処理量(とくに書込量)が増加しているため、1実行当たりの更新量が増加していると考えられる
  • gcs log flush sync、log file parallel write の待機が発生しており、合計の待機時間が総処理時間の約 23% を占めている
    • REDO ログの書き出しにて処理が遅延していると考えられる
またもや出ました RAC 固有の gcs〜 で始まる待機イベント。リファレンスマニュアルや RAC 管理者ガイドではこの待機イベントについて触れられていませんでしたが、Enterprise Manager のデータベース・メトリックの説明でアイドル・イベントであることが分かりました。また、『Advanced RAC troubleshooting』と題したセミナ資料に詳しい説明がありました。

REDO ログの処理状況を確認

REDO ログの処理状況は AWR レポートの以下の項目を確認しました。
  • REDO ログの書込速度(Wait Events)
  • log switch の発生回数(Instance Activity Stats - Thread Activity)
Node2 で上記項目を確認して状況を分析。
  • 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 の待機時間とほぼ等しくなっている

調査まとめ

今回の解説のスライドにある図が大変わかりやすかったので、おぼろげな記憶を頼りに遅延状況が発生していた時のイメージを起こしてみました。

RAC環境でレスポンス遅延が発生していたときの状況

  • 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回発生している
以上のことから、Node1 でレスポンス遅延が発生していた原因は、Node2 における REDO ログの書込処理が遅延していたためと考えられます。また、書込処理の遅延については、1回当たりの書き込み時間に遅延している状況は見られず、REDO の書き出し回数(log switch)が増加している状況であることから書き出し量が多いことに起因していると考えられます。

対策としては次のようなことが考えられます。

  • 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 関連のイベントが満載ですね。

at 7:13
このエントリーをはてなブックマークに追加

0 件のコメント:

コメントを投稿

登録: コメントの投稿 (Atom)