oracle

Oracle REDOログスイッチの影響を検証する

検証に至った経緯

大量データ件数をもつ(今回の例では以下の通り約174万件、336M)のテーブルを単純にinsert&selectしたところ約65027ミリ秒(3回実施した平均)でした。「これ少し遅くない??」と調べてみると、ログスイッチが9回も発生していました。INSERTするテーブルのサイズと、REDOログファイルのサイズをみるところでは50M×7回=350あたりが妥当な回数のように思えるのですが、、9回は多すぎない??まぁ、何れにせよREDOログファイルのサイズが小さすぎるので、REDOログファイルのサイズアップをする事思い立ちました。

念のために、V$ACTIVE_SESSION_HISTORYで発生している待機イベントを確認すると「log file switch (checkpoint incomplete)、log file parallel write、db file async I/O submit」が頻繁に出ています。特にlog file switch (checkpoint incomplete)はよくないです。これはREDOログファイルのチェックポイントが完了していないところに書き込みを試みて失敗しています。REDOログのローテーションが追い付いていないのでしょう。(これは予想ですがログスイッチの回数が想定より多いのもこの事象に関係しているのかも、、)

という事でREDOログファイルのサイズ拡張を行いどの程度パフォーマンスが改善されるか見てみます。REDOログファイルの拡張作業はこちらです。

参考までにですが、REDOログファイルの拡張前に /*+ append */ヒント句を使うとどの程度パフォーマンスなのか計ってみたところ約6248秒(3回実施した平均)と、なんと1/10以下、、ダイレクトパスインサートはREDOログへの書き込みがされないので(但し条件があります)早くなるとは予想していましたがここまで差がでるとは驚きでした。(ダイレクトパスが早いっていうより、通常のINSERTがあまりにも遅い事が後に判明します)予想した通りこちらはログスイッチは発生していませんでした。(重要:NO ARCHIVELOGモードになっているもしくは、INSERT先のテーブルのロギングモードがNOの場合に限り、ダイレクトパスインサートはREDOログファイルへの書き込みを行いません。)

REDOログファイル拡張前後の比較

当初、NO ARCHIVELOGモードだけで検証する予定でしたが、途中からダイレクトパスインサートであってもREDOログファイルへの書き込みがされる事を確認したくて頑張ってみました。以下が今回の検証結果です。理論上、何れの条件においても通常INSERTよりダイレクトパスのほうが高速になると予想していたのですが、例外もありました。(今回は誤差という事にして、原因の追究はこれ以上しない事にしましたww)今回はっきりしたのは、log file switch (checkpoint incomplete)の待機イベントだけは出してはいけないって事ですね。

※1 log file switch (checkpoint incomplete) 発生.。めちゃくちゃ遅い
※2 NO ARCHIVELOGモード+ロギングモードNOであっても、通常のINSERTならREDOログは書かれます。
※3 ダイレクトパスを使ってもアーカイブログモードでかつ、INSERT先のテーブルがロギング指定になっていればREDOログは書かれます。

REDOログファイル拡張前後の比較

検証に使ったSQL
-- 実際のinsert&select文
insert  into SOONI.TBL30 ( AUTO_ID,COL5,COL4,COL3,COL2,COL1 ) 
select  AUTO_ID,COL5,COL4,COL3,COL2,COL1 from TBL26 ;

-- ダイレクトパスINSERT
insert /*+ append */ into SOONI.TBL30 ( AUTO_ID,COL5,COL4,COL3,COL2,COL1 ) 
select  AUTO_ID,COL5,COL4,COL3,COL2,COL1 from TBL26 ;
insertする元テーブルのサイズ確認
SQL> select s.BYTES/1024/1024,s.BLOCKS*8192/1024/1024 from dba_segments s where s.SEGMENT_NAME='TBL26'
  2  ;

   S.BYTES/1024/1024    S.BLOCKS*8192/1024/1024
____________________ __________________________
                 336                        336

SQL> select count(*)  from TBL26
  2  ;

   COUNT(*)
___________
    1739995

SQL>
現状REDOログファイルの確認
SQL> select group#, thread#, sequence#, bytes/1024/1024 M_bytes, members, status
  2  from v$log t order by t.GROUP#,t.THREAD#
  3  ;

   GROUP#    THREAD#    SEQUENCE#    M_BYTES    MEMBERS      STATUS
_________ __________ ____________ __________ __________ ___________
        1          1         2155         50          2 INACTIVE
        2          1         2156         50          2 INACTIVE
        3          1         2157         50          2 CURRENT

SQL>

SQL> select group#, member from v$logfile order by 1,2
  2  ;

   GROUP#                                                                      MEMBER
_________ ___________________________________________________________________________
        1 /usr/oracle/app/fast_recovery_area/ORAU8/onlinelog/o1_mf_1_hw3oh9n1_.log
        1 /usr/oracle/app/oradata/ORAU8/onlinelog/o1_mf_1_hw3oh9dt_.log
        2 /usr/oracle/app/fast_recovery_area/ORAU8/onlinelog/o1_mf_2_hw3ohg71_.log
        2 /usr/oracle/app/oradata/ORAU8/onlinelog/o1_mf_2_hw3ohfx5_.log
        3 /usr/oracle/app/fast_recovery_area/ORAU8/onlinelog/o1_mf_3_hw3ohh0q_.log
        3 /usr/oracle/app/oradata/ORAU8/onlinelog/o1_mf_3_hw3ohgv7_.log

6行が選択されました。

SQL>
insertした際発生したログスイッチの確認
SQL> select
  2   thread#  -- アーカイブログスレッド番号
  3  ,sequence# -- アーカイブログ順序番号
  4  ,to_char(first_time, 'YYYY/MM/DD HH24:MI:SS') first_time  --最初のSCNから導出した時間
  5  from v$log_history
  6  order by SEQUENCE# desc
  7  fetch first 10 rows only
  8  ;

-- 以下青字今回のinsertで発生したスイッチです。
   THREAD#    SEQUENCE#             FIRST_TIME
__________ ____________ ______________________
         1         2138 2021/10/24 14:31:40
         1         2137 2021/10/24 14:31:30
         1         2136 2021/10/24 14:31:21
         1         2135 2021/10/24 14:31:10
         1         2134 2021/10/24 14:30:57
         1         2133 2021/10/24 14:30:51
         1         2132 2021/10/24 14:30:40
         1         2131 2021/10/24 14:30:39
         1         2130 2021/10/24 14:05:44
         1         2129 2021/10/24 13:10:45

10行が選択されました。

SQL>
スポンサーリンク