しばちょう先生の試して納得!DBAへの道

しばちょう先生による技術解説セミナー。
動画、資料を公開中です。

>> 最新のセミナーをチェック

しばちょう先生の試して納得!DBAへの道
第52回 AWRレポートを読むステップ4: 特定時間帯に発生する性能劣化の原因特定


みなさん、こんにちは。"しばちょう"こと柴田長(しばた つかさ)です。

本題に入る前に、まずは二つほど宣伝させてくださいね。一つ目は、5/18(木)に開催されるOracle Code Tokyo 2017です。こちらのイベントで私も14:30-15:15の枠でセッション「Live Challenge!! SQLパフォーマンスの高速化の限界を目指せ!」を担当させて頂くことになりました。内容としてはDDD2011(Oracle DBA & Developer Days 2011)でお話させて頂いた「どこまでチューニングできるのか?」の後半(DWH系クエリをOracle Databaseの機能を贅沢に使った高速化デモ)をOracle Database 12c Release 2の新機能を交えたLive Demoで再びお話させて頂く予定でございます。今年のゴールデンウィークはこの準備で終わってしまいそうですけど、頑張りますので、是非とも応援・ご参加のほどよろしくお願いいたします!

二つ目は、5/26(金)の夜に開催予定のOracle Database Technology Night #9です。こちらでは、3月のOracle Database Connect 2017で大好評であった「エキスパートはどう考えるか?体感!パフォーマンスチューニング」の再演を予定しておりますので、再演と言っても、3月でお伝えし切れなかった部分も含めてJapan Oracle User GroupのOracle ACEメンバー(関口 裕士さん、渡部 亮太さん、諸橋 渉さん)と共にお届けしたいと考えておりますので、是非ともこちらにもご参加頂けると嬉しいです。

さて今回は前回に続き、上記でご紹介させて頂いたTech Night#9で再演予定でもある「エキスパートはどう考えるか? 体感!パフォーマンスチューニング」で取り上げさせて頂いた、二つ目の「特定時間帯に発生するパフォーマンス問題」について解説させて頂きたいと思います。問題発生時のAWRレポートの何処を見て何を推測し、どのように分析して適切な対処を行うのかを、当日のセッションの流れに沿って皆様も体験して頂けると嬉しいです!



1. B社のパフォーマンス問題:
B社では、基幹業務としてDシステムを運用している。
近年、様々な事業拡張を行っていてシステムに処理の追加も行っているが、これまで問題なく動作していた。
ところが最近になって、ある特定の時間だけ性能が低下して業務に影響しているため、早急に改善して欲しいとのことである。
その問題が発生するタイミングのトランザクション性能を調べてもらったところ、以下のようになっていることが分かった。
そこで、このシステムの性能が低下した原因の特定と改善方法を、皆さんに様々な情報を使用して考えて頂きたい。

shibata-52-1

上記のグラフは、Swingbenchでオンライン・トランザクション系の負荷をかけた際の横軸が時系列(左が過去で右が最新)での「Transaction Per Second = スループット」グラフと「平均レスポンスタイム」グラフです。あるタイミングにスループットが低下し、かつ、平均レスポンスタイムが劣化するタイミングが発生していることが確認できます。

前回は日々少しずつ性能が劣化して最終的に耐えられないパフォーマンスとなっていましたが、今回は一日のあるタイミングだけ性能が劣化すること。つまり、そのタイミングを過ぎれば性能は元通りの状態となる点が異なりますね。という事は、あるタイミングだけ「ユーザー数が増加して実行されるSQL文が多くなる」or「オンライン・トランザクションで実行されるSQL文が変わる」or「オンライン・トランザクションとは別のSQL文が追加で実行される」と言った3つの可能性が推測できるわけですね。

今回は、特に負荷生成ツールを使用しているという背景から、そのツールで生成しているオンライン・トランザクション系のSQL文は常に同じものが実行されていると推測できてしまいますが、本番環境の場合は一日のあるタイミングだけ実行されるクエリやDML文の存在する可能性もありますから、「オンライン・トランザクション系のSQL文が犯人ではない」と安易に思い込むのは危険ですからご注意くださいね。


2. 性能問題が発生している範囲を含むAWRレポートで、まずは前回同様H/W構成、Snapshot期間、DB Time辺りを一気に確認してきましょう。

shibata-52-2

コチラは前回の復習となりますので、簡単に読み解いて頂けるでしょう。

今回の環境は、データベースのバージョンが「12.2.0.1.0」で非RAC構成です。Linux OSでCPUコア数が4コアで物理メモリは14.44GBですね。Elapsedが3.24(mins)であることから、およそ3分間のワークロードが記録されているAWRレポートであることが分かります。ここで必ず頭の中に記憶しておくべき大切な数字としてはなんでしたかね?そうですね。もし仮に約3分間で全CPUコア4個を100%で使い続けたら、3.24分間 × 4CPUコア = 12.96分間ですね。という事は、「Elapsed」の下に記述されている「DB Time」の値が約62分間であることを考慮すると、「CPU使用率が100%に張り付いてしまっていてなかなかCPUを使える番が回ってこずに待機した時間」 or 「CPU処理以外で待機してしまった時間」が多い傾向がありそうですね。と言うところまでが前回の復習ですね。

今回は、もう少し特徴的な文字である「PDB」が記載されています。おお!これは、Oracle Database 12c Release1から実装されたマルチテンアント・アーキテクチャのコンテナ・データベース上で稼働するPluggable Database(PDB1)のAWRレポートだったのです。そしてさらに「Host Name」を見てください。一部マスキングさせて頂いておりますが、「xxxx.oraclecloud.xxxx」との記載がある通り、このAWRレポートを取得した環境は、Oracle Database Cloud Service(DBCS)なのですよ~

という事で、構成確認が済みましたので、早速、待機イベントの発生状況について確認していきましょう。


3. 「Top 10 Timed Foreground Events」セクションで確認してみましょう。

shibata-52-3

今回の環境は、Oracle Database 12c Release 2ですから、このセクションは総待機時間が上位10の待機イベントが出力されておりますね。一番は「direct path read」待機イベント、二番は「db file sequential read」待機イベント、三番目に「DB CPU」を挟んで四番目に「log file sync」と並んでいます。

ちなみに、「DB CPU」はCPUを使用していた時間を意味しており、約595.3秒=約5分を記録しています。演習2で確認しているAWRレポートの期間である約3分間で全CPUコア4個を100%で使い続けたら、3.24分間 × 4CPUコア = 12.96分間の数字よりも小さいことが分かります。つまりは、4つのCPUコアは平均で考えてみると全開で動いていなかったと推測することが可能です。こういった感覚は身に着けておきましょう。

さて、「direct path read」待機イベントとは、どのような処理を実行した際に発生するのでしょうか?

まず、前回の連載でも登場した「db file sequential read」待機イベントは大丈夫ですよね?これは単一のブロックをストレージ・デバイスから読み込むシングル・ブロック・リードの際に発生しましたね。読み込む先はバッファ・キャッシュ上でしたね。これは次のスライドの上段で図式されています。

「direct path read」待機イベントはスライドの下段にて図式されているとおり、全表スキャンのように一回のI/O要求で複数のデータブロックをストレージ・デバイスから読み込むマルチ・ブロック読み込みの際に発生します。とだけ説明すると、「db file scattered read」待機イベントと何が違うのか?と疑問を持つ方もいらっしゃると思いますが、「db file scattered read」待機イベントはバッファ・キャッシュへの読み込みであり、こちらの「direct path read」待機イベントはバッファ・キャッシュを経由せずにサーバー・プロセスのPGA領域へ読み込むことが特徴です。つまりは他のサーバー・プロセスからメモリ(バッファ・キャッシュ)上で流用できないのですね。同じ処理を実行する度にストレージ・デバイスから読み込む必要がありますね。

shibata-52-4

もう一つの「log file sync」待機イベントは如何でしょうか?シンプルに言えば、サーバー・プロセスがCommitを要求してからLGWRプロセスがストレージ・デバイスへの書き込みを完了して、その完了通知が戻ってくるまでの時間を待機した際のイベントです。通常、DML文はREDOレコードを生成して、バッファ・キャッシュ上のデータブロックを更新しますが、その更新されたブロックがストレージ・デバイスに書き出されることを待つ必要は無いです。非同期でDBWRプロセスがストレージ・デバイスへ書き出してくれますから、高速に更新が可能なわけです。しかし、Commit処理に関しては永続化と言う目的がありますので、REDOレコードが必ずストレージ・デバイスに書き出されるのを待つ必要があるのです。

shibata-52-5


4. 今回は性能問題が発生している際のAWRレポートだけではなく平常時のAWRレポートも確認して、その差異を確認してみましょう。

shibata-52-6

先ずは、環境情報が同じか否かを念のために確認しておきましょうね。これは絶対に行ってください。後々、「全く異なる環境のAWRレポート同士を比較していた」という意味の無い作業とならないためです。また、可能であれば正常時と問題時の各AWRレポートの「Elapsed」、つまりAWRレポートに記録されている期間がほぼ同じものを用意してください。期間が異なる場合でも平均待機時間を比較する上では問題有りませんが、総待機時間は比較することができなくなりますのでご注意ください。という事で、今回はElapsedが約3分間でほぼ同一のレポートを用意させて頂いています。

shibata-52-7

さて、待機イベントの発生状況は如何でしょうか?一番目が「log file sync」待機イベントで、二番目が「db file sequential read」待機イベント、3番目に「DB CPU」が入ってきていますね。なるほど!そうです。性能問題が発生しているAWRレポートでは「direct path read」待機イベントが一番目でしたが、それが平常時には見当たりませんね。と言うことは、「direct path read」待機イベントを発生させている処理が怪しいということになってきますね。

ちなみに、DB Connectの本番セッション中に諸橋さんにコメント頂いたのですが、「Avg Wait」の列の単位を確認してみてください。よく見てみると「ms(ミリ秒)」だけではなく「µS(マイクロ秒)」と表記されている行が存在していることが分かります。一瞬の見た目は非常に似ているので見逃しがちですからご注意くださいね。「db file sequential read」待機イベントの平均待機時間は440ミリ秒だったら相当異常値ですよね。これは前回の連載を読み直してください。今回は440マイクロ秒ですから、0.44ミリ秒ですよ。え?1ミリ秒未満の値ってことは、そう、ここまで高速な場合は、「サーバーのファイルシステム・キャッシュ」にキャッシュ・ヒットしたか、「ストレージ・コントローラのキャッシュ」にキャッシュ・ヒットしたかのどちらかのケースと思ってください。このうちどちらなのか?を解説しようと思うと長くなってしまうので、今回は割愛させて頂きます。ごめんなさい。


5. ある特定時間帯だけオンライン処理が劣化するのは、ダイレクト・パス・リードが怪しいですね。

全表スキャン(ダイレクト・パス・リード)による物理I/Oが多い理由ではじめに疑うポイントは?

上記の問いをセッション中にJPOUGメンバー(Oracle ACEの3名)に尋ねてみたところ、次の3つを候補として挙げて頂きました。ちなみにセッション当日のやり取りは、綿密な事前打ち合わせを繰り返し行い、想定のシナリオ通りであったことは前回の連載でもお伝えしているとおりです(笑)

理由候補1 – 関口 裕士さん) パラレル実行している処理が追加実行されている?

理由候補2 – 渡部 亮太さん) 全表スキャンのクエリでパーティション・プルーニングが効いていない?

理由候補3 – 諸橋 渉さん) ストレージ性能に問題がありそうだ!!


6. 理由候補1)パラレル実行している処理が追加実行されている?について分析してみましょう。

まずは「direct path read」待機イベントを発生させている全表スキャンを行っているSQL文を特定する必要があります。AWRレポートの「SQL ordered by Reads」セクションを比較・確認することで見つけることが可能です。次は性能問題発生時のAWRレポート分ですが、如何でしょうか?

shibata-52-8

こちらには、ストレージ・デバイスからのデータの読み込み(物理読み込み(Physical Reads))が多い順にSQL文が並べられており、一番上のSQL*Plusから実行されている「SELECT SUM(amount_sold)…」が非常に多くのPhysical Readsを記録していますね。実行回数を示す「Executions」が0となっていることから実行中で完了していないことも分かります。明らかに怪しいですねー

ちなみに、平常時のAWRレポートでも同じセクションを確認してみると、このSQL文が実行されていないことが分かりました。(すいません。簡単すぎるのでレポートの掲載は割愛させて頂きました)

と言うことで、このSQL文が実行されたタイミングで、性能問題が発生している可能性が高まってきましたが、このSQL文が全表スキャンを行っているのか?そして、パラレル実行されているのか?については、AWRレポートからは断言できません。ここで必要となってくるのがSQL監視レポートとなります!SQL監視レポートの取得方法は「第26回 パーティション化による削除処理のパフォーマンス向上」の演習5にて解説させて頂いておりますので、是非復習してみてくださいね。

shibata-52-9

という事で、怪しいと睨んだSQL文のSQL監視レポートが上記の通りです。赤い四角で囲った部分にSQL IDが記載されており、先のAWRレポートで特定したSQL IDと一致していることが確認できると思います。

このSQL文が全表スキャンしているか否かについては次の演習7の解説に含まれていますので、ここではパラレル実行されているのかだけを見ておきましょう。と言っても非常に簡単ですよね?赤い丸で囲った部分(Execution Planの右側)に「8」と言う数字が表示されていますので、このSQL文は一回の実行を並列度8で実行されたことを意味しています。


7. 理由候補2)全表スキャンのクエリでパーティション・プルーニングが効いていない?について分析してみましょう。

こちらも演習6と同様にSQL監視レポートでの確認となります。「Plan Statistics」タブに実行計画と処理量が記録されていますが、まず探っていくポイントとしては一番右の列の「Activity%」の値が大きな行を見つけることです。

shibata-52-10

はい、上図の通り、このSQL文の実行に要した全体時間の84%を「SALES」表に対して「TABLE ACCESS FLL」というオペレーションで費やしたことが簡単に分かってしまいます。あれ?「TABLE ACCESS FULL」って・・・全表スキャンですよね。つまり、怪しいと睨んだSQL文は、まさに全表スキャンを実行していたことがここからわかってきましたね。 そして、この全表スキャンでパーティション・プルーニングが効いていないのでは?と言う渡部さんからのご指摘については、「Plan」タブに切り替えて確認を進めていきます。

shibata-52-11

何と、Oracle Database 12cでは「Pruning」列が登場しており、パーティション・プルーニングが行われているか否かを、これまた簡単に確認することができるのです。今回はSALES表が全表スキャンされていたのですから、その行を見ていくと如何でしょうか?何も表示されていない・・・という事は、パーティション・プルーニングがされていないことが明らかになりました。

ちなみに、今回のSALES表は非パーティション表でしたので、パーティション・プルーニングはそもそも実行されませんよね。って、ここまで書いておいて、パーティション・プルーニングが何者かの説明が書けていなかったことに気付きましたが、安心してください。「第25回 パーティション化による問合せのパフォーマンス向上」にてキッチリと解説してありましたので、そちらで復習してみてくださいね(笑)


8. 理由候補3)ストレージ性能に問題がありそう?について分析してみましょう。

前回のシナリオでも、諸橋さんからはストレージ性能に問題がありそうとコメントを頂きましたが、AWRレポートしか存在しなかった為に調査切れなかった部分ですね。今回はきちんとご用意しましたよー!

Device: rrqm/s   wrqm/s     r/s     w/s    rMB/s   wMB/s avgrq-sz  avgqu-sz  await  svctm  %util
xvde      0.00     0.60   647.60  439.60    5.06    3.44    16.01     0.83    0.76   0.25  26.88

xvde      0.00     0.80 14684.40  279.80  448.74    2.19    61.71   180.90   12.03   0.06  86.54

xvde      0.00     1.20 18702.60  112.80  579.33    0.88    63.15   449.64   23.91   0.05 100.02

xvde      0.00     0.80  2155.40  423.00   53.86    3.31    45.41    21.18    8.46   0.11  27.80

上記は、性能問題が発生しているタイミングの前後を含めた、Linux OS上でコマンド「iostat –mX 5」を実行して出力された結果を抜粋・整形したものです。各行が相対時間として0秒、5秒、10秒、15秒のものとご認識ください。一行目(相対時間0秒)は性能問題発生前、二行目と三行目が性能問題発生時、四行目(相対時間15秒目)が性能問題発生後です。

という事で、一行目と二三行目を比較するのですが、一番簡単なのはI/O回数(r/s、w/s)の比較でしょう。一目瞭然の結果が出力されており、秒間でのRead回数が20~30倍も増加していることが確認できます。これにより、平均待機時間(await)も増加しているという事で、性能問題が発生しているタイミングでI/O Busyな状況に陥っている可能性が高そうですよね。


9. チューニング方法を検討してください。

ここまで見てきた結果、今回の局所的なタイミングでの性能問題はオンライン・トランザクション処理とは別で、全表スキャンを行うパラレル・クエリが横からぶつけられたことによりI/Oリクエストが増大して、ストレージ性能が不足してしまったことで、発生していると推測することができそうです。

様々なチューニング方法がありますが、皆さんであれば、どのようなチューニングを検討するでしょうか?

「パラレル・クエリのパラレル度を下げる」ことで、一時的に必要となるI/O性能を軽減させる策もありますが、パラレル・クエリ側のレスポンスタイムを維持したい場合には不可能ですよね。途中で登場したパーティション・プルーニングを効果的に活用する為に「パーティション表化」することで、必要なデータのみをストレージ・デバイスから読み込ませるというのも一つのアイディアでしょう。同じくOracle Databaseの圧縮機能を活用することでフルスキャンによって読み込むデータ量を削減することも可能です。もちろん、ストレージ性能を増強するというものありです。面白いですね。

実は、これらのチューニング方法は、全て小学校の時に学習した「時間 = 道のり ÷ 速さ」に集約されます。と考えると非常にシンプルなのです。

shibata-52-12

SQLのレスポンス・タイム(時間)を小さくするには、「処理量(道のり)を減らす」or「速度と並列度(はやさ)を向上させる」しかないのです。処理量を減らす方法、高速化、並列化の手法を上記スライドに整理してありますので、参考にしてみてくださいね。

でもって、諸橋さんからアドバイス頂いたのは『Oracle Database 12c Release 2であれば、Database In-Memoryを活用すべきでしょう!』でした。そうなのですよ。是非、使ってみてください。本当か否か疑わしい方は、DB Connect 2017イベント当日の動画をご参照してみてください。Database In-Memoryを活用して、今回の性能問題を解決しているデモをご確認いただけますよ。しかも、Oracle Database Cloud ServiceのExtreme Performanceモデルで実施していますので、今すぐ皆様もお試し頂けるかと思います!!


さてさて、いかがでしたでしょうか?今回のポイントは2点。一点目は、前回と同じように性能問題時のAWRレポートだけではなく、平常時のAWRレポートは確実に保持しておきましょうね。AWRレポートを効率的に読み解くには比較するのが一番です。二点目は、AWRレポートだけでは分析し切れないという点です。今回はSQL監視レポートやOS統計情報と言った情報も必要不可欠でしたよね。是非、こういった情報取得のスキルも向上させておいてくださいね。

最後に、冒頭でのご紹介の繰り返しとなりますが、5/26(金)の夜に開催予定のOracle Database Technology Night #9です。こちらでは、3月のOracle Database Connect 2017で大好評であった「エキスパートはどう考えるか?体感!パフォーマンスチューニング」の再演を予定しております。3月でお伝えし切れなかった部分も含めてJapan Oracle User GroupのOracle ACEメンバー(関口 裕士さん、渡部 亮太さん、諸橋 渉さん)と共にお届けしたいと考えておりますので、是非ともご参加頂けると嬉しいです。

という事で、今回も最後までお付き合い頂きまして、ありがとうございました。次回もご愛読のほど、よろしくお願いします!