強敵！log file sync（1/2）

2019年10月23日『心臓外科医の術式』

1 相関図おさらい
2 アプリケーション開発者からの相談
3 血液検査の結果は？
4 原因の切り分け
5 結果は？
6 SQL トレースの結果は？

相関図おさらい

「心臓外科医の術式」、いろんなキャラクターが登場しますが、
今回もたろーちゃんの同期のAさんが再登場します。

アプリケーション開発者からの相談

システムの「心臓」こと、Oracle Database に日々携わるたろーちゃん。
そんなたろーちゃんのところに、アプリケーション開発者のAさんが訪ねてきました。
今回は何があったのでしょうか？

Aさん「たろーちゃん、ちょっと時間ある？」

たろー「うん、どうしたの？」

Aさん「今日、新しいシステムのカットオーバーだったんだけど、本番環境でデータベースのパフォーマンスが出てないんだ。」

たろー「うえー、また『その手の話』か・・・。」

Aさん「うん、また『その手の話』だよ。
開発環境で性能テストした時は問題が無かったんだ。ちょっと見てくれよ。」

Aさん

たろーちゃんは、データベースサーバの構成を詳しく聞くことにしました。

◆本番環境
　●シングル構成（19c Enterprise Edition）
　●Oracle Diagnostics Pack オプションあり。
　●ハードウェアリソースは潤沢

◆開発環境
　●シングル構成（19c Enterprise Edition）
　●Oracle Diagnostics Pack オプションあり。
　●予算の都合上、ハードウェアリソースは本番環境より劣る

たろー「ハードウェアリソースが潤沢な本番環境のほうが遅いってこと？」

Aさん「そうなんだ。以前のこともあって、お客様には開発環境も本番環境と同じ構成にして下さいってお願いしたんだけど・・・。どうしても予算を削りたいからという理由で、開発環境はリソースを少なくされてしまったんだ。」
※その時のシステムについては以前の『SQL実行計画の変更その２』の回を参照して下さい。

たろー「遅い SQL は分かってるの？」

Aさん「うーん、絞れてはいるんだけど、特定までは出来てないんだ。バッチ処理の概要を説明するね。」

そう言うとAさんは、バッチ処理の概要を説明し始めました。

① データベースリンク先のテーブルから処理対象となるレコードを読み込む
② ①の情報に従ってデータベースリンク元のテーブルを INSERT or UPDATE
③ ①の情報を処理済みとして UPDATE
④ COMMIT を実施

Aさん「これを１トランザクションとして、約１万回実行してるんだ。」

たろー「データベースリンクを使ってるのか。」

Aさん「そうだ、データベースリンクを使っている。」

たろー「簡単でいいから、構成図を描いてみてくれないか？」

たろーちゃんの要望通り、Aさんは構成図を描き始めました。

たろー「なるほど、シンプルな構成だな。
データベースリンク元が moto データベースで、
データベースリンク先が saki データベースか。」

Aさん「そう。現時点では、どちらのデータベースが遅いのかは分かっていないんだ。」

たろー「本番環境と開発環境で、どれくらいの時間の差があるんだ？」

Aさん「聞いて驚くなよ。このバッチ処理は本番環境だと約１時間かかる。
でも開発環境だと約３０秒で終わるんだ。」

たろー「なんだそりゃ？明らかに何かがおかしいな。」

Aさん「だろ？いくらなんでも差があり過ぎるんだよ。リソースが潤沢な本番環境が約１時間かかるのに、リソースが劣る開発環境のほうが早いなんて、お客様に説明が出来ないよ。」

たろー「とりあえず、本番環境の AWR レポートを見てみよう。」

たろーちゃんは、該当処理時間帯の本番環境の AWR レポートを確認することにしました。

■本番環境・moto データベース

■本番環境・saki データベース

たろー「うん？ moto データベースの log file sync 待機イベントが突出して多いな。」

Aさん「どういう意味の待機イベントなんだ？」

たろー「log file sync は、トランザクションによって生成された REDO 情報を、メモリから REDO ログファイルにフラッシュする際に発生する待機イベントだ。」

Aさん「ということは、IO がボトルネックなのか？」

たろー「一般的にはそうなんだけど・・・妙なんだ。」

Aさん「何が？」

たろー「Aさんは LGWR っていうバックグラウンドプロセスを知ってるかな？」

Aさん「ああ、聞いたことはある。前に教えてくれた必須バックグラウンドプロセスの１つだったよな？」

たろー「そうだ。その LGWR が REDO 情報を REDO ログファイルに書き込むんだけど、その際に発生する筈の log file parallel write っていう待機イベントが殆ど発生してないんだ。」

Aさん「えーっと、よく分からなくなってきたぞ（汗）
log file sync と log file parallel write は、どう違うんだ？」

たろー「簡単に言うと、log file sync はフォアグラウンドプロセスが待たされる際の待機イベントで、log file parallel write はバックグラウンドプロセス（つまり LGWR）が待たされる際の待機イベントだ。」

Aさん「ということは、LGWR は待たされずに REDO ログを書き込めてるのに、何故か別な問題でフォアグラウンドプロセスが待たされてるってことか？」

たろー「そういうことだ。今回はデータベースリンクを使っているし、それが何か関係しているのかもしれない。」

データベースリンクって厄介なんだよな。
調査しにくいし、DBA 的にはできれば使って欲しくない機能だ・・・。　

たろー「開発環境の AWR レポートも見てみるか。」

たろーちゃんは、開発環境の AWR レポートを確認することにしました。

■開発環境・moto データベース

■開発環境・saki データベース

たろー「思ったとおり、開発環境の AWR レポートでは log file sync は大したことないな。」

Aさん「Waits はどちらも 30,000 回なのに、本番環境は 2206.9 秒もかかってて、開発環境は 7.6 秒しかかかってないな。どうしてだろう・・・？」

たろー「うーむ・・・。診るまでもないと思うが、『血液検査』をしておくか。」

たろーちゃんは該当時間帯の V$ACTIVE_SESSION_HISTORY の情報を調べることにしました。
※ V$ACTIVE_SESSION_HISTORY に関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回をご参照下さい。

血液検査の結果は？

■本番環境・moto データベース

Aさん「うわぁ・・・。酷いなこれは。log file sync のオンパレードじゃないか。」

たろー「saki データベースも見てみよう。」

■本番環境・saki データベース

たろー「やっぱり saki データベースは何ともないな。Oracle Database が内部で発行している SQL が現れている程度だ。これでハッキリしたのは、ボトルネックは moto データベース側ということだ。」

Aさん「なるほど。」

たろー「開発環境も見てみよう。」

■開発環境・moto データベース

■開発環境・saki データベース

たろー「うむ。開発環境はどちらのデータベースも問題ないな。」

原因の切り分け

たろー「Aさん、データベースリンクが関係しているかどうか切り分けたいんだが、本番環境は自由に処理を流せるか？」

Aさん「本番環境で？」

たろー「ああ、事象が発生しない開発環境では意味がないからな。」

Aさん「本物のテーブルを使うのはダメだから、ダミーのテーブルを作って、それにアクセスするのは OK だよ。但し、日中帯に負荷をかけるのはダメだ。ただでさえ遅いからな。バッチ処理が動いていない深夜から早朝にかけてなら OK だよ。」

たろー「分かった。」

たろーちゃんとAさんは、上司にシフト勤務の申請をして、深夜から早朝に本番環境で処理を実行することにしました。

Aさん「たろーちゃん、どんな切り分け処理を行うんだ？」

たろー「Aさんから聞いた情報は、」

① データベースリンク先のテーブルから処理対象となるレコードを読み込む
② ①の情報に従ってデータベースリンク元のテーブルを INSERT or UPDATE
③ ①の情報を処理済みとして UPDATE
④ COMMIT を実施

たろー「とのことだから、③の処理を辞めてみたいんだ。」

① データベースリンク先のテーブルから処理対象となるレコードを読み込む
② ①の情報に従ってデータベースリンク元のテーブルを INSERT or UPDATE
~~③ ①の情報を処理済みとして UPDATE~~
④ COMMIT を実施

Aさん「なるほど。これならトランザクションは moto データベースに閉じた形になるのか。」

たろー「Aさん、このアプリケーションを作れるか？」

Aさん「ああ、簡単だ。既存の処理をコピーして作るだけだからな。」

Aさんはプログラムをサクっと作り、ダミーの別テーブルを CTAS（Create Table As Select）で作成しました。

たろー「よし、これで処理を流してみよう。」

結果は？

Aさん「おお、早い。１６秒で処理が終了したぞ。」

たろー「ふむ、これでデータベースリンクが関係していることは明らかだな。」

Aさん「データベースリンクを使うと、COMMIT が遅くなるものなのか？」

たろー「２つのデータベースの間で同期を取らないといけないから、確かに log file sync は増えるだろうけど、１時間もかかることはないと思うよ。だって、開発環境だと３０秒で処理が終了してるんだからな。」

Aさん「うーむ、一体なにが原因なんだ？？」

たろー「・・・・・・・・・・・・・・・。」

データベースリンクがなんらか関連していることは分かりましたが、ここから先、どう調査を進めていいのか、たろーちゃんは考えました。

たろー「Aさん、今さっき CTAS で作成したダミーテーブルに、元と同じ処理を流すことはできるか？」

Aさん「元と同じ処理？」

たろー「ああ。」

① データベースリンク先のテーブルから処理対象となるレコードを読み込む
② ①の情報に従ってデータベースリンク元のテーブルを INSERT or UPDATE
③ ①の情報を処理済みとして UPDATE
④ COMMIT を実施

たろー「この処理だ。」

Aさん「勿論、出来るよ。」

たろー「それでちょっと、SQL トレースを取ってみよう。どんな結果になるのか確認したいんだ。」

Aさん「分かった。」

Aさんは処理を実行し、たろーちゃんは SQL トレースを取得することにしました。

SQL トレースの結果は？

たろー「・・・本当に処理が終わらないな。」

Aさん「ああ。データも一緒だから、１時間コースだと思うよ。」

たろー「この待ち時間を利用して、比較用に開発環境でも SQL トレースを取っておこう。」

待ち時間を利用して、Aさんとたろーちゃんは開発環境でも SQL トレースを取得することにしました。

Aさん「お、開発環境で SQL トレースを取ってる間に、本番環境の処理が終了したみたいだ。」

たろー「よし、早速 tkprof をかけて、確認しよう。」

＜本番環境＞

SQL ID: 8ggw94h7mvxd7 Plan Hash: 0

COMMIT


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      6.53    2225.20          0          0     130000           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10001      6.53    2225.20          0          0     130000           0

Misses in library cache during parse: 0
Parsing user id: 77     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                               30000        5.81       2206.86
  SQL*Net message to dblink                   20000        0.00          0.01
  SQL*Net message from dblink                 20000        0.16         12.92
  rdbms ipc reply                             19996        0.01          0.68
  latch: messages                                 1        0.00          0.00

＜開発環境＞

SQL ID: 8ggw94h7mvxd7 Plan Hash: 0

COMMIT


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      5.55      23.14          0        375     130008           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10001      5.55      23.14          0        375     130008           0

Misses in library cache during parse: 0
Parsing user id: 85     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                               30000        0.00          7.60
  SQL*Net message to dblink                   20000        0.00          0.01
  SQL*Net message from dblink                 20000        0.03         11.12
  rdbms ipc reply                             20000        0.01          0.71
  enq: TX - contention                            1        0.00          0.00

たろー「はぁあ？なんなんだこの差は？！」

Aさん「やっぱり COMMIT に時間がかかってるのか？」

たろー「ああ。COMMIT 以外の処理、つまり、」

① データベースリンク先のテーブルから処理対象となるレコードを読み込む
② ①の情報に従ってデータベースリンク元のテーブルを INSERT or UPDATE
③ ①の情報を処理済みとして UPDATE
④ COMMIT を実施

たろー「上記の①、②、③は殆ど変わらない。④だけが遅いんだ。」

Aさん「一体、どーいうことなんだ？」

たろー「・・・・・・・・。どう調べたらいいのか、皆目見当が付かない。」

重苦しい空気が漂います。深夜にシフト出社したため、オフィスには誰もいません。

その静けさが、余計に時間を長く感じさせます。

久しぶりに脳内で the mysterious mallets の BGM が流れ始めてきた。
しかも今回は Extended Version だよ・・・。

たろー（データベースリンクで分散トランザクションが実行されている・・・。）

たろー（極端に遅い COMMIT・・・。）

たろー（でも IO が遅い訳じゃない・・・。）

たろー（リソースが潤沢な本番環境のほうが遅い・・・。）

たろー（データベースリンクを使わなければ早い・・・。）

今回はここまで。
この不可解な謎は、俺が必ず解いてみせる！
ジッチャンの名にかけて！！

クックック、今回のトリック。
決して君には見破れないよ。

投稿者プロフィール

DBひとりでできるもん運営チーム

「DBひとりでできるもん」運営チームです。
「親しみやすさと技術力」をテーマに、技術情報・サービス・インフラ系資格取得に役立つ情報、社員等の情報をお届けします。
70名弱の事業部員で鋭意、執筆中です。
少しでも当社を知って頂けるよう、愛情込めて頑張ります！
※facebook、X(旧twitter)、インスタグラムでは「DBひとりでできるもん」の更新情報を発信しています。