BIGFILE で発生した buffer busy waits の傾向と対策

JPOUG Tech Talk Night #13 BIGFILE で発生した buffer busy waits の傾向と対策 柴田 歩(AYU)

自己紹介(柴田 歩, AYU) ▪ 日本オラクル株式会社 クラウド・テクノロジーコンサルティング事業本部 シニアプリンシパルコンサルタント 柴田 歩(しばた あゆむ, AYU) ▪ 2007年4月に中途で日本オラクルに入社 ▪ Oracle Database や OCI のコンサルとして様々なプロジェクトを歴任 ▪ やきうのお兄ちゃん な エンジニアとして暗躍中彡(^)(^) – Qiita https://qiita.com/ora_gonsuke777 – X(Twitter) @ora_gonsuke777 – ぜひフォローしてくださいね彡(^)(^) 2 2

• https://qiita.com/ora_gonsuke777
• https://twitter.com/ora_gonsuke777

過去コンテンツ ▪ DDD 2013 SQLチューニングに 必要な考え方と最新テクニック ▪ • DDD 2016 SQL性能を最大限に引き出す DB 12cクエリー・オプティマイザ 新機 能活用と統計情報運用の戦略 • http://www.oracle.com/technetwork/jp/on demand/ddd-2016-3373953-ja.html http://www.oracle.com/technetwo rk/jp/ondemand/ddd-20132051348-ja.html ▪ JPOUG Tech Talk Night #9 Autonomous Database で Oracle Database19c 新機能 を味わう ▪ https://www.slideshare.net/slideshow /autonomous-database-oracledatabase19c/201644673 ▪ Oracle Databaseを中心とした座談会 コレ ’19 – Oracle Code Tokyo 2019 開催 報告(パネリスト) ▪ http://www.jpoug.org/2019/09/17/c odetokyo19report ▪ Oracle Database or GoldenGate ▪ ▪ ブログ「ねら～ITエンジニア雑記」 コレ ▪ http://d.hatena.ne.jp/gonsuke777/ Advent Calendar 2018 https://adventar.org/calendars/3525 ▪ デモとディスカッションで体験する ▪ Oracle DBトラブル対応(2018年) https://www.slideshare.net/shibataay umu/oracle-db-111087832 ▪ - JPOUG Advent Calendar 2017 Day 15 - V$SQLとその周辺でER図を描い てみよう！ ▪ https://www.slideshare.net/shibataay umu/vsqler 3

• http://www.oracle.com/technetwork/jp/ondemand/ddd-2013-2051348-ja.html
• http://www.oracle.com/technetwork/jp/ondemand/ddd-2016-3373953-ja.html
• https://www.slideshare.net/slideshow/autonomous-database-oracle-database19c/201644673
• http://www.jpoug.org/2019/09/17/codetokyo19report
• https://adventar.org/calendars/3525
• https://www.slideshare.net/shibataayumu/oracle-db-111087832
• https://www.slideshare.net/shibataayumu/vsqler

免責事項／注意事項／おことわり ▪ 本資料において示されている見解は、 私自身の “独自研究”, ”独自検証”, ”独自解釈” に基づいた個人の見解となります。 ▪ 従って本資料は Oracle Corporation 及び 日本オラクル の 公式見解を必ずしも反映したものではなく、 マニュアル・サポートサイト等で公開されている情報や 実際の製品仕様・動作と異なる可能性があります。 ▪ この点は予めご了承ください。 ▪ 資料は(一部スライドを修正して)公開します。 4

目次 ▪ 1. よくある buffer busy waits ▪ 2. BIGFILE で発生した buffer busy waits ▪ 3. まとめ 5

1. よくある buffer busy waits 6

buffer busy waits とは ▪ buffer busy waits は下記のマニュアルに記載があります。 Oracle Database の待機イベントとなります。 – Oracle Database データベース・パフォーマンス・チューニング・ガイド 23ai 11 パフォーマンス・ビューを使用したインスタンスのチューニング buffer busy waits – https://docs.oracle.com/cd/G11854_01/tgdba/instance-tuning-using-performance-views.html#GUID-03401D0FDB3E-49E5-89E0-2F2A6164A5C0 – この待機は、複数のプロセスがバッファ・キャッシュ内のいくつかのバッファに同時にアクセス しようとしていることを示します。 – バッファのクラスごとに、待機統計についてV$WAITSTATを問い合せます。バッファ・ビジー待 機を持つ一般的なバッファ・クラスには、data block、segment header、undo headerおよび undo blockがあります。 – 次のV$SESSION_WAITパラメータ列をチェックします。 ✓ P1: ファイルID(file#) ✓ P2: ブロックID(block#) ✓ P3: クラスID(class#) 7

• https://docs.oracle.com/cd/G11854_01/tgdba/instance-tuning-using-performance-views.html#GUID-03401D0F-DB3E-49E5-89E0-2F2A6164A5C0

buffer busy waits は 複数プロセスの競合で発生 ▪ Oracle Database の複数プロセスがバッファ・キャッシュ上のブロッ クに同時アクセスした際に、競合が発生すると本待機イベントが発生し ます。 – RAC環境では gc buffer busy acquire/release も発生しますが、 根本原因は同じです。 ▪ この待機イベント/競合はいくつかの発生パターンが有るのですが、ま ず Right Growing Index と呼ばれる事象でデータ・ブロックの競合を 発生させてみます。 8

Right Growing Index とは(1) ▪ 一般的な B-Tree索引 の場合、索引のツリーは索引キーに使用した列値 の順番でソートされてリーフに格納されます。下記記事の図が良さげな ので引用します。 – How Oracle B-tree Indexes Work https://blog.toadworld. com/2017/05/08/howoracle-b-tree-indexeswork 索引の列値がソートされて リーフに格納される 9

• https://blog.toadworld.com/2017/05/08/how-oracle-b-tree-indexes-work

Right Growing Index とは(2) ▪ 索引に対する更新が単調増加するワークロード特性(例：列値が単調増 加するシーケンス番号、など)の場合、ソートされた索引ツリーの右端 のリーフに更新が集中します。 ▪ この特性を持つ索引への更新が複数プロセスで実行されると、 更新が集中する右端のリーフで競合が発生します。 10

Right Growing Index とは(3) ▪ 下図の右端のリーフで発生する競合 および 競合で発生する問題/性能遅 延が、いわゆる Right Growing Index と呼ばれる事象になります。 process process process process process 単調増加する値で索引を複数 プロセスが挿入/更新すると、 右端のリーフで競合が発生 11

Right Growing Index を発生させてみる ▪ Autonomous Database で Right Growing Index を発生させてみます。 – ADB を選んだのは I/Oネックを発生させたくなかったので。Exadata を手軽に安価に使える ADB は便利ですね(ｽﾃﾏ OCI Region VCN Private Subnet Public Subnet User 12 SSH Internet Internet Gateway Public Compute Oracle Services Network 10.0.1.0/24 10.0.0.0/24 SSH Private Compute SQL*Net Private SGW Endpoint IP SQL*Net Oracle Autonomous Database

テーブルと索引 ▪ TIMESTAMP列のみの超シンプル構造 CREATE TABLE BUFFER_BUSY_WAITS_TEST ( C1 TIMESTAMP ); CREATE INDEX BUFFER_BUSY_WAITS_TEST_I1 ON BUFFER_BUSY_WAITS_TEST(C1); 13

実行した SQL ▪ SYSTIMESTAMP関数をひたすらインサート、時間経過で単調増加する。 CONNECT ADMIN/<パスワード>@<Autonomous Database の接続文字列> SET ECHO ON; SET TIME ON; SET TIMING ON; BEGIN FOR i IN 1..1000000 LOOP INSERT INTO BUFFER_BUSY_WAITS_TEST VALUES(SYSTIMESTAMP); IF i MOD 1000 = 0 THEN COMMIT; END IF; END LOOP; COMMIT; END; / EXIT; 14

ワークロード ▪ 前ページの SQL を8多重で実行 – SSH接続が切れてもいいように nohup でバックグラウンド実行します。 export ORACLE_HOME=/usr/lib/oracle/23/client64 export PATH=${ORACLE_HOME}/bin:${PATH} export LD_LIBRARY_PATH=${ORACLE_HOME}/lib nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & nohup sqlplus /nolog @busy.sql >> $(date +busy_sql_%Y%m%d_%H%M%S_%4N_$$.log) 2>&1 & 15

実行結果 ▪ 1セッション辺りの実行時間はざっくり3分38秒程度 SQL> SET TIME ON; 10:17:15 SQL> SET TIMING ON; 10:17:15 SQL> BEGIN 10:17:15 2 FOR i IN 1..1000000 10:17:15 3 LOOP 10:17:15 4 INSERT INTO BUFFER_BUSY_WAITS_TEST VALUES(SYSTIMESTAMP); 10:17:15 5 IF i MOD 1000 = 0 THEN 10:17:15 6 COMMIT; 10:17:15 7 END IF; 10:17:15 8 END LOOP; 10:17:15 9 COMMIT; 10:17:15 10 END; 10:17:15 11 / PL/SQL procedure successfully completed. Elapsed: 00:03:38.05 10:20:53 SQL> EXIT; 16

ADB の Performance Hub で待機イベント状況を確認 ▪ buffer busy waits の発生を確認 – 茶色の帯のところです。 buffer busy waits の発生を確認 17

ASH(Active Session History) も確認
▪ SQL終了直後に GV$ACTIVE_SESSION_HISOTRY表をCSV出力
– SET MARKUP CSV ON; が地味に便利
CONNECT ADMIN/<パスワード>@<Autonomous Database の接続文字列>
SET ECHO ON;
SET TIME ON;
SET LINESIZE 32767;
SET PAGESIZE 32767;
SET TRIMSPOOL ON;
SET TERMOUT OFF;
SET FEEDBACK OFF;
SET MARKUP CSV ON;
ALTER SESSION SET NLS_DATE_FORMAT = 'YYYY/MM/DD HH24:MI:SS';
ALTER SESSION SET NLS_TIMESTAMP_FORMAT = 'YYYY/MM/DD HH24:MI:SS.FF';
SPOOL gv_active_session_history.csv
SELECT *
FROM GV$ACTIVE_SESSION_HISTORY
WHERE SAMPLE_TIME BETWEEN TO_TIMESTAMP('2025/04/25 10:16:00', 'YYYY/MM/DD HH24:MI:SS')
AND TO_TIMESTAMP('2025/04/25 10:22:00', 'YYYY/MM/DD HH24:MI:SS');
SPOOL OFF;
EXIT;
18

buffer busy waits の発生を ASH でも確認 ▪ 出力した CSV を Excel で開いて EVENT列など一部の列と行を抜粋 19

AWRレポートの Buffer Wait ～セクション ▪ AWRレポートの Buffer Wait Statisticsセクションの傾向は下記 – data block で競合が発生している。 20

buffer busy waits の対策は競合の分散 ▪ buffer busy waits は前ページまでで述べた通り 複数プロセスの競合で発生します。 ▪ 対策は競合の分散となります。 ▪ Right Growing Index に代表されるデータ・ブロック競合の場合は、 下記が有効な対策となります。 – HASH PARTITION + ローカル索引による索引のパーティション化 – 逆キー索引 21

HASH PARTITION で競合を分散してみる ▪ HASH PARTITION と ローカル索引(パーティション索引)で競合を分散 ▪ 他は先ほどのケースと同様に8多重でSQLを実行 DROP TABLE BUFFER_BUSY_WAITS_TEST PURGE; CREATE TABLE BUFFER_BUSY_WAITS_TEST ( C1 TIMESTAMP ) PARTITION BY HASH (C1) PARTITIONS 8 ; CREATE INDEX BUFFER_BUSY_WAITS_TEST_I1 ON BUFFER_BUSY_WAITS_TEST(C1) LOCAL; 22

実行結果(HASH PARTITION) ▪ 1セッション辺りの実行時間はざっくり1分32秒程度に改善 SQL> SET TIME ON; 08:56:43 SQL> SET TIMING ON; 08:56:43 SQL> BEGIN 08:56:43 2 FOR i IN 1..1000000 08:56:43 3 LOOP 08:56:43 4 INSERT INTO BUFFER_BUSY_WAITS_TEST VALUES(SYSTIMESTAMP); 08:56:43 5 IF i MOD 1000 = 0 THEN 08:56:43 6 COMMIT; 08:56:43 7 END IF; 08:56:43 8 END LOOP; 08:56:43 9 COMMIT; 08:56:43 10 END; 08:56:43 11 / PL/SQL procedure successfully completed. Elapsed: 00:01:32.50 08:58:16 SQL> EXIT; 23

ADB の Performance Hub で待機イベント状況を確認 ▪ HASH PARTITION で buffer busy waits の減少を確認できました。 – 茶色の帯のところです。 24 buffer busy waits の発生が減少した

逆キー索引で競合を分散してみる ▪ 逆キー索引で競合を分散 – 索引のCREATE文 に REVERSE句 を付与 DROP TABLE BUFFER_BUSY_WAITS_TEST PURGE; CREATE TABLE BUFFER_BUSY_WAITS_TEST ( C1 TIMESTAMP ); CREATE INDEX BUFFER_BUSY_WAITS_TEST_I1 ON BUFFER_BUSY_WAITS_TEST(C1) REVERSE; 25

実行結果(逆キー索引) ▪ 1セッション辺りの実行時間はざっくり1分弱秒程度に改善 SQL> SET TIME ON; 09:19:37 SQL> SET TIMING ON; 09:19:37 SQL> BEGIN 09:19:37 2 FOR i IN 1..1000000 09:19:37 3 LOOP 09:19:37 4 INSERT INTO BUFFER_BUSY_WAITS_TEST VALUES(SYSTIMESTAMP); 09:19:37 5 IF i MOD 1000 = 0 THEN 09:19:37 6 COMMIT; 09:19:37 7 END IF; 09:19:37 8 END LOOP; 09:19:37 9 COMMIT; 09:19:37 10 END; 09:19:37 11 / PL/SQL procedure successfully completed. Elapsed: 00:00:58.30 09:20:35 SQL> EXIT; 26

ADB の Performance Hub で待機イベント状況を確認 ▪ 逆キー索引でも buffer busy waits の減少を確認できました。 – 茶色の帯のところです。 buffer busy waits の発生が減少した 27

本章は Qiita記事にもしているのでご参照ください ▪ buffer busy waits を Right Growing Index で発生させてみる (Oracle Database) – https://qiita.com/ora_gonsuke777/items/87527715d1735ae0a3bc 28

• https://qiita.com/ora_gonsuke777/items/87527715d1735ae0a3bc

2. BIGFILEで発生した buffer busy waits 29

不可解な buffer busy waits による遅延 ▪ とあるシステムでバッチ処理の遅延が発生 ▪ 該当時間帯の AWRレポートの Top10待機イベントは buffer busy waits が大部分 30

遅延した SQL は異なるテーブルへの INSERT文が複数 ▪ 遅延した SQL は INSERT文で、それぞれ異なるテーブルへの INSERT～SELECT文が複数併走していた。 – 同一テーブルへの同時トランザクションは無し ▪ 異なるテーブルということは、よくある索引の競合ではなさそう……？ 31

該当時間帯の ASH の特徴 ▪ 事象発生中のASHでサンプリングされたセッションは以下の特徴がある。 – 大半が buffer busy waits で待機している。 – P1列(file# = ファイル番号) が 17番 – P2列(block# = ブロック番号) が 2番 32

類似事象の MOS Document(Doc ID 2579040.1) ▪ 下記ドキュメントの事象が今回のケースに類似していた。 – Doc ID 2579040.1 High buffer Busy Waits on file# XXXX and block# X https://support.oracle.com/epmos/faces/DocumentDisplay?id=2579040.1 – exadata : dbodsp12: High concurrency on "buffer busy waits“ Every blocker is waiting on file# 2001 and block# 2 – 一時表領域のセグメントを確保する際に一時表領域ファイルの特定領域(block#=2) を更新しようとして、そこで競合(buffer busy waits)が発生している。 – ドキュメント記載の対策は一時表領域の UNIFORM SIZE の拡張による セグメント拡張/新規確保の回数削減 – ただし今回のケースでは file# = 17 で発生 ← 一時表領域のファイルではなかった。 33

• https://support.oracle.com/epmos/faces/DocumentDisplay?id=2579040.1

競合は UNDO表領域のファイルヘッダーで発生 ▪ file# = 17 を DBA_DATA_FILES や V$DATAFILE で確認したところ、 UNDO表領域のデータファイルであることが判明した。 – このデータベースの UNDO表領域 は BIGFILE で作成されていた。 ▪ UNDO表領域BIGFILE の block# = 2、おそらくファイルヘッダーの 競合で buffer busy waits が発生したのではないかと推測 – 複数セッションの高負荷更新で UNDO Segmentが大量拡張してヘッダー競合した？ ▪ AWRレポートの Buffer Wait Statistics セクションで file header block の競合発生を確認 – すみません、これ今回あらためて確認して気づきました……(;^ω^) 34

対策は BIGFILE → SMALLFILE への変更 ▪ UNDO表領域は UNIFORM SIZE が指定不可のため、ファイルヘッダーの 競合を分散するために BIGFILE から SMALLFILE への変更を実施 – SMALLFILE にすることでファイル数が増えるため、 ファイルヘッダーの競合が分散する。 ▪ UNDO表領域を SMALLFILE に変更したところ、遅延は解消して解決！ – したかに見えた……。 35

buffer busy waits による遅延がまたまた発生 ▪ 同一のシステムでやはり同じバッチ処理の遅延が発生 ▪ 該当時間帯の AWRレポートの Top10待機イベントは buffer busy waits が多くなっている。 ▪ Buffer Wait Statisticsセクションでは file header block の競合を確認 – UNDO表領域のファイルヘッダー競合は解消したはずなんやが……彡(-)(-) 36

遅延した SQL は異なるテーブルへの INSERT文が複数 ▪ UNDO表領域の競合による遅延の時と状況が同じ……効果が出ていない？ 37

該当時間帯の ASH の特徴 ▪ 事象発生中のASHでサンプリングされたセッションは以下の特徴がある。 – buffer busy waits(or gc buffer busy release)で待機しているセッションが多い ▪ P1列(file# = ファイル番号) が 4100番 ← UNDO表領域ではない ▪ P2列(block# = ブロック番号) が 2番 ← ファイルヘッダー – enq: SS - contention で待機しているセッションも散在 ▪ SS は Sort Segment の略で SQL がソート処理で一時表領域を確保しようとしていると判断される。 – DFS lock handle で待機しているセッションもごく僅かにあり 38

類似事象の MOS Document(Doc ID 32996974.8) ▪ 下記ドキュメントの事象が今回のケースに類似していた。 – Doc ID 32996974.8 Cluster-wide hang and ‘DFS lock handle’ wait event under severe temp space pressure on an instance in RAC https://support.oracle.com/epmos/faces/DocumentDisplay?id=32996974.8 – This issue happens only under severe temp space pressure on an instance. – 一時表領域に高負荷が掛かるとハングが発生する(場合がある) – DFS lock handle でハングするセッションが発生して他セッションをブロックしてしまう事象 – ... waiting for ‘DFS lock handle’ wait event, with the p1 and p2 values are as follows: ※DFS lock handle で待機したセッションの p1列, p2列 に下記の特徴がある。 ▪ p1: 'type|mode'=0x43490005 ▪ p2: 'id1'=0xe – ASH の DFS lock handle で待機しているセッションの P1列 と P2列 を 16進数 に変換してみる。 ▪ P1: 1128857605 → (16進数変換) → 0x43490005 ▪ P2: 14 → (16進数変換) → 0xE – あ～～ほぼビンゴ……彡(-)(-) 39

• https://support.oracle.com/epmos/faces/DocumentDisplay?id=32996974.8

競合は TEMP表領域のファイルヘッダーで発生 ▪ file# = 4100 は DBA_TEMP_FILES や V$TEMPFILE で見つからなかったので すが、ドキュメントや待機イベント等の傍証より一時表領域のファイルと判断 – enq: SS - contention の発生より一時表領域を使おうとしていると判断される。 – このデータベースの TEMP表領域 は BIGFILE で作成されている。 ▪ SQL のソート処理で TEMP表領域への書き込みが大量発生して、 Doc ID 32996974.8 の事象によるハングが発生したと判断 ▪ 対策 は Doc ID 32996974.8 に記載されていた下記 – For mitigation : (※mitigation = 緩和策) 1. Add more temp files to the temporary tablespace (or) 2. Kill the FG process / PQ slave which is hung. ▪ このケースでは 1. の TEMPファイル追加を緩和策として採用して解決！ – 一時表領域を BIGFILE から SMALLFILE に変更してファイル数を増強 40

3. まとめ 41

まとめ ▪ buffer busy waits(or gc buffer busy acquire/release)は 複数プロセスの同時アクセスによる競合で発生する。 ▪ Right Growing Index に代表されるデータ・ブロック競合 – 対策は HASH PARTITION による競合の分散 – または 逆キー索引 による競合の分散、など ▪ ファイルヘッダーで発生する競合 – 対策はファイル数増強によるヘッダー競合の分散 (※BIGFILE表領域の場合は SMALLFILE への変更) – またはUNIFORM SIZE増強によるセグメント拡張回数の削減、など 42

buffer busy waits を分析するワイ 「よくわかんないけど、なんかわかった！」 ジークアクス っぽい何か (自主規制) 43

おわり ▪ご清聴、ありがとナス！！ 44