log file syncのトラブルシューティング [アーキテクチャ]
現場で発生したlog file syncの性能遅延をトラシューしたときのメモである。2019年9月に一度上げたが、解析が誤っていたためいったん記事を取り下げたもののリバイスした。
ある日、業務チームか性能遅延解析依頼があった。内容はlog file syncが大量発生して性能遅延が発生しているみたいなので、見て欲しいということであった。AWRを見ると、なるほど確かにlog file syncが待機イベントの上位（トップ）に来ていた。ちなみに、この業務は現行でも動いているもので、このような待機は出ていない。現行はOracle11.1で30分程度の処理が、この問題発生しているOracle19.2 (Exadata)の環境では110分以上かかっており、そのほとんど(80%以上)がlog file syncで占められており、1待機あたりのレイテンシは50msecを越えるという、とてつもなく遅い状態であった。
問題のAPは、以下の特徴を持っていた。
・母体テーブルの中から処理対象レコードに対して１件ずつループ処理を行う
・ループ処理の中で母体テーブルの更新と、dblink越しに他DBへの更新を行う
・１ループ毎にコミットする（母体、他DBともに1件ずつのコミット）
1件ずつコミットする、というAPのつくりはOracle的にはイマイチではあるが、それはそれで現行では性能要件を満たして動いている訳なので、ここでは特に問題視はしていない。問題は、なぜ19cでは同じAPがこれだけlog file syncで待機してしまうのか、ということである。ちなみに、事象を再現させるためのサンプルAPで、dblink越しの更新を行わないよう変更すると、log file syncによる遅延事象は発生しなかった。
この記事を読んでいる方には言うまでもないと思うが、log file syncとはLGWR（ログライター）がログバッファに書き込んだredoチェンジベクターをREDOログファイルに書き込む際に発生する待機である。具体的にはサーバプロセスがコミットを発行しLGWRに書き込み要求をしてから、書き込み完了を受け取るまでの待機である。このうち、純粋にディスクへの書き込み(I/O)に要した待機はlog file parallel write待機イベントである。
log file sync待機の原因にはさまざまな要因が考えられる。一番明らかなのは、REDOログファイルへの書き込みが純粋に遅い場合である。プアなストレージや3rdベンダのストレージとの相性問題を心配するような状況では被疑箇所として考えられるが、今回の場合はExadataであり、REDOログファイルへの書き込みはフラッシュキャッシュで折り返されるため、これが原因とは考えにくい。実際、log file parallel write待機はほとんど発生していないし、レイテンシも良好であった。
次に考えられるのは、頻繁なREDOログファイルスイッチによる影響である。限りあるREDOログファイルが一巡してしまうと、アーカイブログに出力されるまではREDOログへの上書きができなく待機が発生する場合がある。しかし、今回の場合は十分に大きなREDOログファイルとしていたため、これが原因とは考えられない。実際、ログスイッチが何度も発生していないことはAWRやアーカイブログを見ても明らかである。
一般的にはAPのつくりもlog file sync待機の要因となる。log file syncはコミットを発行する度に発生する待機イベントであり、コミットしないAPはないことから、ある意味、log file syncの発生自体が問題ではない。問題はこれが多発することによりそのオーバーヘッドによりAPが本来の性能を出せないことが問題なのだ。従って、たとえば10000件単位にコミットするようにAPを改修すれば、当然待機イベントを減らせるし、待機時間も減らせる。今回のケースでも確かに有効ではあろう。しかし、問題の本質は待機回数ではなく、待機時間、つまり1コミットあたりのレイテンシが19.2では極端に遅いという事象であると考えられるため、これは本質的な解決になっていない。
とすると、他は何か。。。LGWR周りで考えられるのは以下２つの機能である。
(1)adaptive log file sync ・・・従来LGWRへの書き込み要求はpost/wait方式（書き込み要求を出してLGWRが完了を通知する方式）であったが、新しくpolling方式（書き込み要求を出して、要求を出した側が再びLGWRに完了を確認する方式）が使えるようになった。11.2.0.3よりデフォルトで有効（2つの方式をLGWRの負荷に応じて動的に切り替える）ようになっている。_use_adaptive_log_file_syncで制御可能（MOS1541136.1参照）
(2)scalable log writer ・・・従来はLGWRはシングルプロセスで動作していたが、LGWRのI/O処理をパラレルで実行できるよう、複数のワーカープロセス(LGnn)を立ち上げ、REDOログファイルへのI/Oを複数のCPUで分散して処理する方式が使えるようになった。12.1から、LGWRへの負荷に応じて動的に従来の方式とを切り替えるようになっている。_use_single_log_writerパラメータで制御可能
どちらの方式も、ポイントは動的に切り替わるという点である。LGWRのトレースログを見ると、確かに切り替わった痕跡が確認できるが、その理由、つまり切り替わりの条件がわからないのである。従って、性能試験をする中では問題なくても、運用中になんらかの条件で切り替わったことにより性能への影響が発生することがあり得るということである。もちろん、通常はポジティブな効果が得られ運用は楽になるのかもしれない。しかし逆の場合、トラシューは困難となり、また、運用中にこれを変更することは、DBの根幹に影響するプロセスだけに慎重にならざるを得ない。いずれにしても、どちらもWriteインテンシブな使い方を想定した機能改善だとは思うが、これが有効に働くケースを見極める必要がある。
なお、上記の解析をするにあたり、新久保氏によるJPOUGの講演資料は非常に参考になった。上記２つのような重要なアーキテクチャ上の変更を2013年に既に気付き、課題としてコミュニティに対して提起していた点は大変有意義なことと思うし、自分も見習いたいと感じた。以前のJPOUGの懇親会でお話させていただいたが、この場を借りてお礼申し上げたい。
結局、本事象はサポートの解析の結果、製品不具合であることが判明したが、このlog file syncのトラシューを通し、OracleのREDOの仕組みは枯れたアーキテクチャではなく、バージョンが上がるにつれ確実に改良されてきていることがよく分かった。
以上
ある日、業務チームか性能遅延解析依頼があった。内容はlog file syncが大量発生して性能遅延が発生しているみたいなので、見て欲しいということであった。AWRを見ると、なるほど確かにlog file syncが待機イベントの上位（トップ）に来ていた。ちなみに、この業務は現行でも動いているもので、このような待機は出ていない。現行はOracle11.1で30分程度の処理が、この問題発生しているOracle19.2 (Exadata)の環境では110分以上かかっており、そのほとんど(80%以上)がlog file syncで占められており、1待機あたりのレイテンシは50msecを越えるという、とてつもなく遅い状態であった。
問題のAPは、以下の特徴を持っていた。
・母体テーブルの中から処理対象レコードに対して１件ずつループ処理を行う
・ループ処理の中で母体テーブルの更新と、dblink越しに他DBへの更新を行う
・１ループ毎にコミットする（母体、他DBともに1件ずつのコミット）
1件ずつコミットする、というAPのつくりはOracle的にはイマイチではあるが、それはそれで現行では性能要件を満たして動いている訳なので、ここでは特に問題視はしていない。問題は、なぜ19cでは同じAPがこれだけlog file syncで待機してしまうのか、ということである。ちなみに、事象を再現させるためのサンプルAPで、dblink越しの更新を行わないよう変更すると、log file syncによる遅延事象は発生しなかった。
この記事を読んでいる方には言うまでもないと思うが、log file syncとはLGWR（ログライター）がログバッファに書き込んだredoチェンジベクターをREDOログファイルに書き込む際に発生する待機である。具体的にはサーバプロセスがコミットを発行しLGWRに書き込み要求をしてから、書き込み完了を受け取るまでの待機である。このうち、純粋にディスクへの書き込み(I/O)に要した待機はlog file parallel write待機イベントである。
log file sync待機の原因にはさまざまな要因が考えられる。一番明らかなのは、REDOログファイルへの書き込みが純粋に遅い場合である。プアなストレージや3rdベンダのストレージとの相性問題を心配するような状況では被疑箇所として考えられるが、今回の場合はExadataであり、REDOログファイルへの書き込みはフラッシュキャッシュで折り返されるため、これが原因とは考えにくい。実際、log file parallel write待機はほとんど発生していないし、レイテンシも良好であった。
次に考えられるのは、頻繁なREDOログファイルスイッチによる影響である。限りあるREDOログファイルが一巡してしまうと、アーカイブログに出力されるまではREDOログへの上書きができなく待機が発生する場合がある。しかし、今回の場合は十分に大きなREDOログファイルとしていたため、これが原因とは考えられない。実際、ログスイッチが何度も発生していないことはAWRやアーカイブログを見ても明らかである。
一般的にはAPのつくりもlog file sync待機の要因となる。log file syncはコミットを発行する度に発生する待機イベントであり、コミットしないAPはないことから、ある意味、log file syncの発生自体が問題ではない。問題はこれが多発することによりそのオーバーヘッドによりAPが本来の性能を出せないことが問題なのだ。従って、たとえば10000件単位にコミットするようにAPを改修すれば、当然待機イベントを減らせるし、待機時間も減らせる。今回のケースでも確かに有効ではあろう。しかし、問題の本質は待機回数ではなく、待機時間、つまり1コミットあたりのレイテンシが19.2では極端に遅いという事象であると考えられるため、これは本質的な解決になっていない。
とすると、他は何か。。。LGWR周りで考えられるのは以下２つの機能である。
(1)adaptive log file sync ・・・従来LGWRへの書き込み要求はpost/wait方式（書き込み要求を出してLGWRが完了を通知する方式）であったが、新しくpolling方式（書き込み要求を出して、要求を出した側が再びLGWRに完了を確認する方式）が使えるようになった。11.2.0.3よりデフォルトで有効（2つの方式をLGWRの負荷に応じて動的に切り替える）ようになっている。_use_adaptive_log_file_syncで制御可能（MOS1541136.1参照）
(2)scalable log writer ・・・従来はLGWRはシングルプロセスで動作していたが、LGWRのI/O処理をパラレルで実行できるよう、複数のワーカープロセス(LGnn)を立ち上げ、REDOログファイルへのI/Oを複数のCPUで分散して処理する方式が使えるようになった。12.1から、LGWRへの負荷に応じて動的に従来の方式とを切り替えるようになっている。_use_single_log_writerパラメータで制御可能
どちらの方式も、ポイントは動的に切り替わるという点である。LGWRのトレースログを見ると、確かに切り替わった痕跡が確認できるが、その理由、つまり切り替わりの条件がわからないのである。従って、性能試験をする中では問題なくても、運用中になんらかの条件で切り替わったことにより性能への影響が発生することがあり得るということである。もちろん、通常はポジティブな効果が得られ運用は楽になるのかもしれない。しかし逆の場合、トラシューは困難となり、また、運用中にこれを変更することは、DBの根幹に影響するプロセスだけに慎重にならざるを得ない。いずれにしても、どちらもWriteインテンシブな使い方を想定した機能改善だとは思うが、これが有効に働くケースを見極める必要がある。
なお、上記の解析をするにあたり、新久保氏によるJPOUGの講演資料は非常に参考になった。上記２つのような重要なアーキテクチャ上の変更を2013年に既に気付き、課題としてコミュニティに対して提起していた点は大変有意義なことと思うし、自分も見習いたいと感じた。以前のJPOUGの懇親会でお話させていただいたが、この場を借りてお礼申し上げたい。
結局、本事象はサポートの解析の結果、製品不具合であることが判明したが、このlog file syncのトラシューを通し、OracleのREDOの仕組みは枯れたアーキテクチャではなく、バージョンが上がるにつれ確実に改良されてきていることがよく分かった。
以上
2020-05-26 00:57
nice!(0)
コメント(0)
コメント 0