ORA-4036でPGA_AGGREGATE_LIMITを上げた話 [アーキテクチャ]
いつになっても夜に電話で起こされるのは辛いものである。先日も夜にORA-4036が出た！と電話がかかってきた。状況はこうである。夜ORA-4036が出た。他に業務影響は出ていない。どんな状況なのかわからない。翌営対応とはいえPGAのことが頭から離れない。明日どう対応しようか、切り分けするためにはどのような方法がよいのか、そもそも原因は何なのだろうか、、、コロナによる外出規制は解除になったものの、なかなか商用環境に触れない状況は続いており、その限られた時間で結果を出さなければならない、と思うと不安は募るばかりである。
この状況で翌日どう考え対処したか、をメモしておく。
ORA-4036はPGA_AGGREGATE_LIMITを超えたことを示すエラーである。PGAは通常セッションが終了すれば解放されるため、おそらくその時間帯になんらかの負荷の高い処理、特にソートやハッシュ結合を伴う処理が行われたのに違いない。したがって、明日調査確認すべきは、まずDBの正常性を確認することである。監視（EnterpriseManager)で問題が検出されていないこと、PGAの空きが十分確保されていることである。次に問題のあった時間帯の原因となるSQLの特定である。業務APまたは運用作業のSQLを特定できれば、あとは試験環境で再現させ、どう修正するか、という議論ができるようになる。ここまでが私が頭におおまかに描いていた障害対応のシナリオだった。朝の出かける前に、PGAの情報取得について書籍[1]でAWRレポートのPGAセクションの確認ポイントを予習しておく。現場での引き出しは少しでも多いほうがよい。
しかし現実は思い通りにならないものである。朝は予定通り、まず正常性確認から始めた。EMの画面でオールグリーンであることを確認する。問題ないのは想定通りである。次にv$pgastatを確認した。これはPGAの状態を確認する動的パフォーマンスビューであり、現在アロケート済みのPGAサイズ"total PGA allocated"が確認できる。通常はこのサイズがpga_aggregate_limitのパラメータ値よりずっと小さいはずである。しかし、実際はほぼ同じ値（pga_aggregate_limitの9割以上のサイズ）であった。こうなると、一過性の問題と考えることはできない。いつ、このタイミングでも、ソート処理を行うバッチが流れれば、ORA-4036で異常終了するかもしれない、という状況である。この時点で、早くも私が思い描いていたシナリオは崩れ去ったのである。
ここで、具体的にv$pgastatの結果がどんなものか確認しておこう。以下は手元のノートPC上のVMの環境での実行結果、バージョンは19.3である。下記の例であれば、total PGA allocatedが現在のPGA利用サイズ267MB（★1）に対し、ハードリミットであるpga_aggregate_limitが2GB（★2）なので、ORA-4036発生まで十分余裕があることがわかる。
さて、PGAが高止まりしているということは何らかのサーバープロセスが掴み続けているということである。では一体何のプロセスなのか。それを確認するにはv$processを見ればよい。意外なことにMMONのスレーブプロセス（m000などの5つ）がそれぞれ大きなPGAをアロケートしていることがわかった。そのサイズは1つのプロセスで4GB程度、5つの合計で20GB程度であった。ちなみにOracleのMMONはAWRのスナップショットを取得したりする管理系のバックグラウンドプロセスである。
ここで、v$processの例を見てみよう。私の手元の環境でPGAのアロケートサイズで降順にソートしている。この例ではM000～M004の4つのMMONスレーブプロセスがあり、その合計はたかだかが22MB程度である。
次にalert.logを確認する。事象発生時間に、「PGA_AGGREGATE_LIMITを超えたが、最もPGAを使っているプロセスはORA-4036の割り込みを受け取れるプロセスではないので、今後の発生はDBRMトレースファイルに記録する」旨のメッセージが出力されていた。DBRMのトレースと言われてもピンとこないが、同じディレクトリに確かにSID_dbrm_XXX.trcというトレースファイルがある。中を確認してみると、ORA-4036の発生したpidが記録されている。そして、psでこのpidを持つプロセスを探すと、m000というMMONのスレーブプロセスであった。
この挙動はリファレンスマニュアル[2]のPGA_AGGREGATE_LIMITパラメータのActions Taken When PGA_AGGREGATE_LIMIT is Exceededに記載されている（下記★の部分）。「most untunable memory」というのが、具体的にPGAをどう使っている状態なのかがイメージできないが、少なくともPGAを一番使っているプロセスは、LIMITに達すると制約を受け、最悪の場合はセッションが終了させられるように読み取れる。今回はバックグラウンドプロセスだったのでその制約を受けなかったが、通常の業務APであれば、セッション停止により異常終了するという事態になりかねない。
---
Actions Taken When PGA_AGGREGATE_LIMIT is Exceeded →PGA_AGGREGATE_LIMITを超えたときの挙動
Parallel queries will be treated as a unit. First, the sessions that are using the most untunable memory will have their calls aborted. Then, if the total PGA memory usage is still over the limit, the sessions that are using the most untunable memory will be terminated.
→パラレルクエリーは一つの単位として扱われる。一番チューニングできないメモリを使っているセッションは呼び出しを中止させられる。それでもPGAの使用量がリミットを超えていれば、そのセッションは停止させられる。
SYS processes and background processes other than job queue processes will not be subjected to any of the actions described in this section. Instead, if they are using the most untunable memory, they will periodically write a brief summary of their PGA usage to a trace file.
→★SYSプロセスとバックグラウンドプロセス（ジョブキュープロセス以外）は上記のアクションの対象外である。もしそれらが一番チューニングできないメモリを使っていたら、定期的にPGAの利用状況についてトレースファイルに出力する。
---
ここまでで大まかな状況と直接原因がわかったので、次は根本原因の特定である。MOSで19cの類似事象を確認し、以下の既知不具合を見つけた。(1)はMMONのスレーブプロセスがPGAを多く使ってしまう、という事象についてのドキュメントであり、その根本原因が(2)の不具合である。XMLFORESTを使う問い合わせでPGAを使ってしまうというもので、これは特にMMON固有という訳ではないようだ。ワークアラウンドとしてはeventを設定してインスタンスのバウンスとあるので、パッチは回避できそうであるものの、すぐには実施できない、ということもわかった。
(1)Standard Mmon Slave Process Using High PGA (Doc ID 2641033.1)
(2)Bug 30611650 : HIGH PGA USAGE FOR A QUERY USING XMLFOREST
※XMLFORESTとは以下のようにカラム名で問い合わせの結果をXML化する関数。詳細は[5]参照
ここまでの切り分けで午前中は終了。根本原因については上記の見立てが正しいかどうかサポートに問い合わせるとして、何よりもまず今の危険な状況を暫定対処する必要がある。ORA-4036の直接原因はPGA_AGGREGATE_LIMITに達したことによるものであるため、すぐに思いつくのはこの値を上げることである。方法としては以下の２通りがあると考えた。
案１：PGA_AGGREGATE_LIMITを上げる
例）alter system set pga_aggregate_limit=XXG
案２：PGA_AGGREGATE_LIMITを外す
例）alter system set pga_aggregate_limit=0;
案１の場合はMMONのスレーブプロセスの肥大化により本来使えるべきPGA領域が使えなくなっているので、その分を考慮して上げればよい。しかし、肥大化が続いているとすると、やがてまた同じこととなるので、あくまで時間稼ぎでしかない。一方、案２はPGAのハードリミット制御を止めてしまう、という対処であり、不測の処理の負荷増等でDBのメモリを使いきらないようなガードがなくなる。しかし、リファレンスマニュアル[2]を見ると以下のように記載があり、物理メモリサイズからSGAのサイズを引いた90%になるらしい。この場合Hugepageは考慮されるのか、とか挙動として若干不安な点もあるため、今回は結果として案１を選択し、値は案２と同じ結果になるように明示的に値を設定することとした。
---
Default value
... If MEMORY_TARGET is not set, and PGA_AGGREGATE_TARGET is explicitly set to 0, then the value of PGA_AGGREGATE_LIMIT is set to 90% of the physical memory size minus the total SGA size.
→もしMEMORY_TARGETが設定されておらず、PGA_AGGREGATE_TARGETが明示的に0に設定されていれば、PGA_AGGREGATE_LIMITは物理メモリサイズからSGAのサイズを引いた90%に設定される
---
続いて他のDBでも同様のことが発生していないかを確認する。同様に、v$pgastatとv$processを見るだけですぐ判断できるだろう。結果、同様のPGAの肥大化が発生していることと、幸運なことにそれほどPGA_AGGREGATE_LIMITのサイズまで切迫していない状況が確認できた。さらにリークの傾向を確認しなければならない。これが突発的に大きくなるものであれば、今大丈夫でも明日はダメかもしれないからである。pgastatの履歴はDBA_HIST_PGASTATで確認できる（前日夜に調べておいてよかった）。name列がtotal PGA allocatedのものだけを抜いて、結果をExcelに張り付け、snap_idを横軸、value列を縦軸にプロットすると、ゆるやかな右肩上がりのグラフになった。突発性の増加傾向はない。暫定対処する対象としては今回問題が発生したDBだけでも大丈夫だろうと判断した。
なお、手元の環境でのDBA_HIST_PGASTATの出力結果は以下の通りである。手元の環境では手動でsnap取得したが、通常であればAWRは定期的（30分や1時間おき）に取得されているだろうから、これで過去から現在までのPGAのアロケート済みサイズの推移が確認できる。なお、RACならINSTANCE_NUMBER毎に集計することは言うまでもない。
平行してサポートから、事象が発生した時間帯のash（dba_hist_active_sess_history）から、MMONが発行していたSQL_IDが特定ができたとの連絡があった。v$sqlからこのsql_idのsql_fulltextを抜き、内容を確認すると、果たしてリークする条件となるXMLFORESTを使っていることが判明した。この不具合に合致することはほぼ間違いないだろう、あとはサポートの裏どりだけだ。
ここまでの対応で１日が終了。とりあえず枕を高くして眠ることができる状態までにはできた。しかしまだ暫定対処が終わっただけであり、根本対処をどうするか、という話はこれからである。ORA-4036は避けられる状態にはなったがMMONスレーブプロセスは大きいままである。インスタンスバウンスは避けたいが、プロセスは小さくしたい。少し調べてみた限り、DBを一度制限モードにすることでMMONプロセスを再起動できる方法があるらしいとわかった。しかし、制限モードにすると既存セッションはkillされてしまう[3]ため、実質的にバウンスと大差ない。コミュニティではMMONをkillすれば自動起動する、という意見もある[4]が、サポートされない上に、起動に失敗する不具合（Doc ID 2023652.1)があったりと、勧められる方法ではないだろう。
なお、手元の環境で制限モードにしてみたところ、MMONだけでなく、そのスレーブプロセスも再起動されることは確認できた(pidが変更されていることから明らか)。★の部分で数秒待たされたので、セッションが多い場合はそれなりに時間がかかるだろう。お試しならともかく、商用でやることはあまり想像できない。当面、様子見しかないのだろうか。
今回の経験を通し、PGA_AGGREGATE_LIMITの設計はそもそもどうあるべきかを考えさせられる。いままで、デフォルトでPGA_AGGREGATE_TARGETの2倍になるので、上限としては十分余裕がある設計になっていると思っていた。今回の場合もバックグラウンドプロセスによるPGA肥大化が起きなければ問題はなかっただろう。しかし、そもそもオンプレの場合、OSの上限まで余裕があるにも関わらず、クエリが異常終了する、ということを望むことは少ないだろう。その意味では0に設定する、またはSGA（Hugepage）サイズを除いたユーザ領域のサイズに対し、若干の安全率を残した値を明示的に設定するという考え方でもよいように思う。あえて2倍という中途半端なリミットを設けることに意味はないのではないか。この機能はむしろDB統合やクラウドなど、複数DBでリソースをシェアする状況において、それぞれのリソース制限をかけたい場合に積極的に活用すべきだろうと思う。
◆参考
[1]Oracle Database Problem Solving and Troubleshooting Handbook (English Edition),pp.240-244
[2]Database Reference 19c, PGA_AGGREGATE_LIMIT
[3]Database Administrator’s Guide, Restricting Access to an Open Database
[4]Is it possible to explicitly restart MMON without bouncing a database?
[5]SQL Language Reference, XMLFOREST
以上
この状況で翌日どう考え対処したか、をメモしておく。
ORA-4036はPGA_AGGREGATE_LIMITを超えたことを示すエラーである。PGAは通常セッションが終了すれば解放されるため、おそらくその時間帯になんらかの負荷の高い処理、特にソートやハッシュ結合を伴う処理が行われたのに違いない。したがって、明日調査確認すべきは、まずDBの正常性を確認することである。監視（EnterpriseManager)で問題が検出されていないこと、PGAの空きが十分確保されていることである。次に問題のあった時間帯の原因となるSQLの特定である。業務APまたは運用作業のSQLを特定できれば、あとは試験環境で再現させ、どう修正するか、という議論ができるようになる。ここまでが私が頭におおまかに描いていた障害対応のシナリオだった。朝の出かける前に、PGAの情報取得について書籍[1]でAWRレポートのPGAセクションの確認ポイントを予習しておく。現場での引き出しは少しでも多いほうがよい。
しかし現実は思い通りにならないものである。朝は予定通り、まず正常性確認から始めた。EMの画面でオールグリーンであることを確認する。問題ないのは想定通りである。次にv$pgastatを確認した。これはPGAの状態を確認する動的パフォーマンスビューであり、現在アロケート済みのPGAサイズ"total PGA allocated"が確認できる。通常はこのサイズがpga_aggregate_limitのパラメータ値よりずっと小さいはずである。しかし、実際はほぼ同じ値（pga_aggregate_limitの9割以上のサイズ）であった。こうなると、一過性の問題と考えることはできない。いつ、このタイミングでも、ソート処理を行うバッチが流れれば、ORA-4036で異常終了するかもしれない、という状況である。この時点で、早くも私が思い描いていたシナリオは崩れ去ったのである。
ここで、具体的にv$pgastatの結果がどんなものか確認しておこう。以下は手元のノートPC上のVMの環境での実行結果、バージョンは19.3である。下記の例であれば、total PGA allocatedが現在のPGA利用サイズ267MB（★1）に対し、ハードリミットであるpga_aggregate_limitが2GB（★2）なので、ORA-4036発生まで十分余裕があることがわかる。
SQL> select * from v$pgastat; NAME VALUE UNIT CON_ID ---------------------------------------- ---------- ------------ ---------- aggregate PGA target parameter 209715200 bytes 0 aggregate PGA auto target 13107200 bytes 0 global memory bound 41943040 bytes 0 total PGA inuse 240287744 bytes 0 total PGA allocated 280586240 bytes 0★1 maximum PGA allocated 456682496 bytes 0 total freeable PGA memory 16908288 bytes 0 MGA allocated (under PGA) 0 bytes 0 maximum MGA allocated 0 bytes 0 process count 107 0 max processes count 121 0 PGA memory freed back to OS 169869312 bytes 0 total PGA used for auto workareas 0 bytes 0 maximum PGA used for auto workareas 5061632 bytes 0 total PGA used for manual workareas 0 bytes 0 maximum PGA used for manual workareas 0 bytes 0 over allocation count 152 0 bytes processed 220843008 bytes 0 extra bytes read/written 0 bytes 0 cache hit percentage 100 percent 0 recompute count (total) 155 0 21 rows selected. SQL> show parameter pga_aggregate_limit NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ pga_aggregate_limit big integer 2G ★2 SQL>
さて、PGAが高止まりしているということは何らかのサーバープロセスが掴み続けているということである。では一体何のプロセスなのか。それを確認するにはv$processを見ればよい。意外なことにMMONのスレーブプロセス（m000などの5つ）がそれぞれ大きなPGAをアロケートしていることがわかった。そのサイズは1つのプロセスで4GB程度、5つの合計で20GB程度であった。ちなみにOracleのMMONはAWRのスナップショットを取得したりする管理系のバックグラウンドプロセスである。
ここで、v$processの例を見てみよう。私の手元の環境でPGAのアロケートサイズで降順にソートしている。この例ではM000～M004の4つのMMONスレーブプロセスがあり、その合計はたかだかが22MB程度である。
SQL> select program, pga_alloc_mem,pga_freeable_mem from v$process order by 2 desc PROGRAM PGA_ALLOC_MEM PGA_FREEABLE_MEM ------------------------------------------------ ------------- ---------------- oracle@localhost.localdomain (TT00) 20610133 0 oracle@localhost.localdomain (DBW0) 13769925 3735552 oracle@localhost.localdomain (M001) 11893845 6094848★ oracle@localhost.localdomain (MMON) 9537069 4259840 oracle@localhost.localdomain (M000) 6764981 2293760★ oracle@localhost.localdomain (CJQ0) 5932589 1572864 ・・・ oracle@localhost.localdomain (W002) 2128981 0 oracle@localhost.localdomain (M003) 2128981 0★ oracle@localhost.localdomain (DIAG) 2123101 0 ・・・ oracle@localhost.localdomain (W000) 1932373 0 oracle@localhost.localdomain (M002) 1932373 0★ oracle@localhost.localdomain (SCMN) 1932373 0 ・・・ 88 rows selected.
次にalert.logを確認する。事象発生時間に、「PGA_AGGREGATE_LIMITを超えたが、最もPGAを使っているプロセスはORA-4036の割り込みを受け取れるプロセスではないので、今後の発生はDBRMトレースファイルに記録する」旨のメッセージが出力されていた。DBRMのトレースと言われてもピンとこないが、同じディレクトリに確かにSID_dbrm_XXX.trcというトレースファイルがある。中を確認してみると、ORA-4036の発生したpidが記録されている。そして、psでこのpidを持つプロセスを探すと、m000というMMONのスレーブプロセスであった。
alert_SID.log PGA_AGGREGATE_LIMIT has been exceeded but some processes using the most PGA memory are not eligible to receive ORA-4036 interrupts. Further occurrences of this condition will be written to the trace file of the DBRM process. SID_dbrm_XXX.trc PGA LIMIT: pid XXX is a top contributor to going over PGA_AGGREGATE_LIMIT PGA LIMIT: pid XXX is ineligible for an ORA-4036 interrupt System processes and most backgroud processes cannot receive ORA-4036 interrupts. When they are contributing to the instance exceeding PGA_AGGREGATE_LIMIT, they will periodically dump their PGA usage.
この挙動はリファレンスマニュアル[2]のPGA_AGGREGATE_LIMITパラメータのActions Taken When PGA_AGGREGATE_LIMIT is Exceededに記載されている（下記★の部分）。「most untunable memory」というのが、具体的にPGAをどう使っている状態なのかがイメージできないが、少なくともPGAを一番使っているプロセスは、LIMITに達すると制約を受け、最悪の場合はセッションが終了させられるように読み取れる。今回はバックグラウンドプロセスだったのでその制約を受けなかったが、通常の業務APであれば、セッション停止により異常終了するという事態になりかねない。
---
Actions Taken When PGA_AGGREGATE_LIMIT is Exceeded →PGA_AGGREGATE_LIMITを超えたときの挙動
Parallel queries will be treated as a unit. First, the sessions that are using the most untunable memory will have their calls aborted. Then, if the total PGA memory usage is still over the limit, the sessions that are using the most untunable memory will be terminated.
→パラレルクエリーは一つの単位として扱われる。一番チューニングできないメモリを使っているセッションは呼び出しを中止させられる。それでもPGAの使用量がリミットを超えていれば、そのセッションは停止させられる。
SYS processes and background processes other than job queue processes will not be subjected to any of the actions described in this section. Instead, if they are using the most untunable memory, they will periodically write a brief summary of their PGA usage to a trace file.
→★SYSプロセスとバックグラウンドプロセス（ジョブキュープロセス以外）は上記のアクションの対象外である。もしそれらが一番チューニングできないメモリを使っていたら、定期的にPGAの利用状況についてトレースファイルに出力する。
---
ここまでで大まかな状況と直接原因がわかったので、次は根本原因の特定である。MOSで19cの類似事象を確認し、以下の既知不具合を見つけた。(1)はMMONのスレーブプロセスがPGAを多く使ってしまう、という事象についてのドキュメントであり、その根本原因が(2)の不具合である。XMLFORESTを使う問い合わせでPGAを使ってしまうというもので、これは特にMMON固有という訳ではないようだ。ワークアラウンドとしてはeventを設定してインスタンスのバウンスとあるので、パッチは回避できそうであるものの、すぐには実施できない、ということもわかった。
(1)Standard Mmon Slave Process Using High PGA (Doc ID 2641033.1)
(2)Bug 30611650 : HIGH PGA USAGE FOR A QUERY USING XMLFOREST
※XMLFORESTとは以下のようにカラム名で問い合わせの結果をXML化する関数。詳細は[5]参照
SQL> select xmlforest(dummy) from dual; XMLFOREST(DUMMY) ----------------X
ここまでの切り分けで午前中は終了。根本原因については上記の見立てが正しいかどうかサポートに問い合わせるとして、何よりもまず今の危険な状況を暫定対処する必要がある。ORA-4036の直接原因はPGA_AGGREGATE_LIMITに達したことによるものであるため、すぐに思いつくのはこの値を上げることである。方法としては以下の２通りがあると考えた。
案１：PGA_AGGREGATE_LIMITを上げる
例）alter system set pga_aggregate_limit=XXG
案２：PGA_AGGREGATE_LIMITを外す
例）alter system set pga_aggregate_limit=0;
案１の場合はMMONのスレーブプロセスの肥大化により本来使えるべきPGA領域が使えなくなっているので、その分を考慮して上げればよい。しかし、肥大化が続いているとすると、やがてまた同じこととなるので、あくまで時間稼ぎでしかない。一方、案２はPGAのハードリミット制御を止めてしまう、という対処であり、不測の処理の負荷増等でDBのメモリを使いきらないようなガードがなくなる。しかし、リファレンスマニュアル[2]を見ると以下のように記載があり、物理メモリサイズからSGAのサイズを引いた90%になるらしい。この場合Hugepageは考慮されるのか、とか挙動として若干不安な点もあるため、今回は結果として案１を選択し、値は案２と同じ結果になるように明示的に値を設定することとした。
---
Default value
... If MEMORY_TARGET is not set, and PGA_AGGREGATE_TARGET is explicitly set to 0, then the value of PGA_AGGREGATE_LIMIT is set to 90% of the physical memory size minus the total SGA size.
→もしMEMORY_TARGETが設定されておらず、PGA_AGGREGATE_TARGETが明示的に0に設定されていれば、PGA_AGGREGATE_LIMITは物理メモリサイズからSGAのサイズを引いた90%に設定される
---
続いて他のDBでも同様のことが発生していないかを確認する。同様に、v$pgastatとv$processを見るだけですぐ判断できるだろう。結果、同様のPGAの肥大化が発生していることと、幸運なことにそれほどPGA_AGGREGATE_LIMITのサイズまで切迫していない状況が確認できた。さらにリークの傾向を確認しなければならない。これが突発的に大きくなるものであれば、今大丈夫でも明日はダメかもしれないからである。pgastatの履歴はDBA_HIST_PGASTATで確認できる（前日夜に調べておいてよかった）。name列がtotal PGA allocatedのものだけを抜いて、結果をExcelに張り付け、snap_idを横軸、value列を縦軸にプロットすると、ゆるやかな右肩上がりのグラフになった。突発性の増加傾向はない。暫定対処する対象としては今回問題が発生したDBだけでも大丈夫だろうと判断した。
なお、手元の環境でのDBA_HIST_PGASTATの出力結果は以下の通りである。手元の環境では手動でsnap取得したが、通常であればAWRは定期的（30分や1時間おき）に取得されているだろうから、これで過去から現在までのPGAのアロケート済みサイズの推移が確認できる。なお、RACならINSTANCE_NUMBER毎に集計することは言うまでもない。
SQL> select * from dba_hist_pgastat where name ='total PGA allocated' order by snap_id;
★SNAP_ID DBID ★INSTANCE_NUMBER NAME ★VALUE CON_DBID CON_ID
---------- ---------- --------------- ------------------------------ ---------- ---------- ----------
112 2780785463 1 total PGA allocated 380929024 2780785463 0
113 2780785463 1 total PGA allocated 223073280 2780785463 0
114 2780785463 1 total PGA allocated 223990784 2780785463 0
115 2780785463 1 total PGA allocated 262359040 2780785463 0
116 2780785463 1 total PGA allocated 263014400 2780785463 0
117 2780785463 1 total PGA allocated 263014400 2780785463 0
118 2780785463 1 total PGA allocated 263014400 2780785463 0
119 2780785463 1 total PGA allocated 286373888 2780785463 0
120 2780785463 1 total PGA allocated 284532736 2780785463 0
121 2780785463 1 total PGA allocated 248374272 2780785463 0
122 2780785463 1 total PGA allocated 202958848 2780785463 0
123 2780785463 1 total PGA allocated 229661696 2780785463 0
124 2780785463 1 total PGA allocated 208464896 2780785463 0
125 2780785463 1 total PGA allocated 265885696 2780785463 0
126 2780785463 1 total PGA allocated 253380608 2780785463 0
127 2780785463 1 total PGA allocated 216879104 2780785463 0
128 2780785463 1 total PGA allocated 236321792 2780785463 0
平行してサポートから、事象が発生した時間帯のash（dba_hist_active_sess_history）から、MMONが発行していたSQL_IDが特定ができたとの連絡があった。v$sqlからこのsql_idのsql_fulltextを抜き、内容を確認すると、果たしてリークする条件となるXMLFORESTを使っていることが判明した。この不具合に合致することはほぼ間違いないだろう、あとはサポートの裏どりだけだ。
ここまでの対応で１日が終了。とりあえず枕を高くして眠ることができる状態までにはできた。しかしまだ暫定対処が終わっただけであり、根本対処をどうするか、という話はこれからである。ORA-4036は避けられる状態にはなったがMMONスレーブプロセスは大きいままである。インスタンスバウンスは避けたいが、プロセスは小さくしたい。少し調べてみた限り、DBを一度制限モードにすることでMMONプロセスを再起動できる方法があるらしいとわかった。しかし、制限モードにすると既存セッションはkillされてしまう[3]ため、実質的にバウンスと大差ない。コミュニティではMMONをkillすれば自動起動する、という意見もある[4]が、サポートされない上に、起動に失敗する不具合（Doc ID 2023652.1)があったりと、勧められる方法ではないだろう。
なお、手元の環境で制限モードにしてみたところ、MMONだけでなく、そのスレーブプロセスも再起動されることは確認できた(pidが変更されていることから明らか)。★の部分で数秒待たされたので、セッションが多い場合はそれなりに時間がかかるだろう。お試しならともかく、商用でやることはあまり想像できない。当面、様子見しかないのだろうか。
[oracle@localhost ~]$ ps -ef | grep mmon oracle 7097 1 0 07:17 ? 00:00:05 ora_mmon_orclcdb oracle 28559 18645 0 11:53 pts/2 00:00:00 grep --color=auto mmon [oracle@localhost ~]$ ps -ef | grep m00 oracle 27386 1 0 11:34 ? 00:00:01 ora_m000_orclcdb oracle 27395 1 0 11:34 ? 00:00:01 ora_m002_orclcdb oracle 27808 1 0 11:40 ? 00:00:00 ora_m001_orclcdb oracle 28035 1 0 11:44 ? 00:00:00 ora_m004_orclcdb oracle 28568 18645 0 11:53 pts/2 00:00:00 grep --color=auto m00 [oracle@localhost ~]$ sqlplus / as sysdba SQL*Plus: Release 19.0.0.0.0 - Production on Thu May 28 11:54:02 2020 Version 19.3.0.0.0 Copyright (c) 1982, 2019, Oracle. All rights reserved. Connected to: Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.3.0.0.0 SQL> grant restricted session to public; Grant succeeded. SQL> alter system enable restricted session; ★ System altered. SQL> alter system disable restricted session; System altered. SQL> revoke restricted session from public; Revoke succeeded. SQL> exit Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.3.0.0.0 [oracle@localhost ~]$ ps -ef | grep mmon oracle 28639 1 0 11:54 ? 00:00:00 ora_mmon_orclcdb oracle 28733 18645 0 11:55 pts/2 00:00:00 grep --color=auto mmon [oracle@localhost ~]$ ps -ef | grep m00 oracle 28644 1 0 11:54 ? 00:00:00 ora_m000_orclcdb oracle 28646 1 0 11:54 ? 00:00:00 ora_m001_orclcdb oracle 28648 1 0 11:54 ? 00:00:00 ora_m002_orclcdb oracle 28676 1 0 11:54 ? 00:00:00 ora_m003_orclcdb oracle 28701 1 0 11:54 ? 00:00:00 ora_m004_orclcdb oracle 28745 18645 0 11:55 pts/2 00:00:00 grep --color=auto m00 [oracle@localhost ~]$
今回の経験を通し、PGA_AGGREGATE_LIMITの設計はそもそもどうあるべきかを考えさせられる。いままで、デフォルトでPGA_AGGREGATE_TARGETの2倍になるので、上限としては十分余裕がある設計になっていると思っていた。今回の場合もバックグラウンドプロセスによるPGA肥大化が起きなければ問題はなかっただろう。しかし、そもそもオンプレの場合、OSの上限まで余裕があるにも関わらず、クエリが異常終了する、ということを望むことは少ないだろう。その意味では0に設定する、またはSGA（Hugepage）サイズを除いたユーザ領域のサイズに対し、若干の安全率を残した値を明示的に設定するという考え方でもよいように思う。あえて2倍という中途半端なリミットを設けることに意味はないのではないか。この機能はむしろDB統合やクラウドなど、複数DBでリソースをシェアする状況において、それぞれのリソース制限をかけたい場合に積極的に活用すべきだろうと思う。
◆参考
[1]Oracle Database Problem Solving and Troubleshooting Handbook (English Edition),pp.240-244
[2]Database Reference 19c, PGA_AGGREGATE_LIMIT
[3]Database Administrator’s Guide, Restricting Access to an Open Database
[4]Is it possible to explicitly restart MMON without bouncing a database?
[5]SQL Language Reference, XMLFOREST
以上
2020-05-29 12:25
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の仕組みは枯れたアーキテクチャではなく、バージョンが上がるにつれ確実に改良されてきていることがよく分かった。
以上
