« VBOX_E_IPRT_ERROR (0x80BB0005) / VirtualBox 6.1.32 r14929 (いろいろでるなぁw) | トップページ | Oracle vagrant-projects »

2022年3月21日 (月)

古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #13

随分間が空いてしまったのです、覚えてますかねw 前回のネタ。私もほぼ忘れてました orz. w

思い出しながら進めましょう:)

Previously on Mac De Oracle
前回は、CTASだと、内部的にdirect path writeされてしまうのでクリーンアウトが必要な状況にはならないという動きを確認しました。

scattered read同様に、sequential readだとどうなの?(という遠くから声が聞こえたきがしたのでw)

とはいえ、遅延ブロッククリーンアウトって、自分の理解だと、全表走査時の動きだと思っているので、多分、起きないよなーと。頭の上に雲型の吹き出した出た状態でイメージしているところ。


では、試してみましょう。

これまでと異なる箇所は、sequential read でぐるぐるループさせたいので、該当表に主キー索引を作成します。また、table full scanではなく、index unique scan で全行アクセスさせてみます。(この動きが大きく異なる部分です)





strong>0) 対象表のdrop/create と主キー作成
対象表のHOGE2は削除して作り直し。このテストケースでは主キーアクセスさせるため、合わせて主キーも作成しておきます。
SCOTT@orcl> @droppurge_create_hoge2_with_pk.sql
1* drop table hoge2 purge

Table dropped.

Elapsed: 00:00:00.51
1* create table hoge2 (id number, data varchar2(2000), constraint pk_hoge2 primary key (id) using index)

Table created.

Elapsed: 00:00:00.07
1* select segment_name,blocks from user_segments where segment_name like '%HOGE2%'

no rows selected

Elapsed: 00:00:00.13


1) 統計をクリアするためOracle再起動


$ sudo service oracle restart

[sudo] password for oracle:

Restarting oracle (via systemctl): [ OK ]



2) PDBのscottでログインしてclient_infoをセット
v$sessionのclient_info列の'TargetSession'文字列で他のSCOTTユーザーのセッションを特定するため。

SCOTT@orcl> @set_client_info
1 begin
2 DBMS_APPLICATION_INFO.SET_CLIENT_INFO('Target Session');
3* end;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SCOTT@orcl>


3) CDBのSYSで統計取得(初回)
内容は省略! (思い出したいかたはこの辺りを参照ください。。


4) PDBのSCOTTユーザーでNOAPPENDヒント付きIASを実行(データサイズは、コミットクリーンアウトではクリーンアウト仕切れないサイズ)/ 未コミット

NOAPPENDヒントを利用している理由は前回までの内容を見ていただければわかりますが、direct path writeさせたないためです。これによりコミットクリーンアウトではクリーンアウトできない状況、つまり、遅延ブロッククリーンアウトが必要となる状態を作っています。

SCOTT@orcl> @ias_noappend_from_hoge.sql
1* insert /*+ noappend */ into hoge2 select * from hoge

200000 rows created.

Elapsed: 00:00:19.63
14:32:40 SCOTT@orcl>


5) CDBのSYSで統計取得(未コミット)

検証中に統計値が変動したもののみ記載

狙い通りdirect path writeは抑止できていることは確認できます。
(CDB)システム統計

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sysstat DBWR checkpoint buffers written 22,918
sysstat DBWR checkpoints 72
sysstat DBWR thread checkpoint buffers written 22,918
sysstat DBWR transaction table writes 22
sysstat DBWR undo block writes 983
sysstat cleanouts only - consistent read gets 0
sysstat commit cleanout failures: block lost 0
sysstat commit cleanout failures: callback failure 0
sysstat commit cleanouts 1,601
sysstat commit cleanouts successfully completed 1,601
sysstat consistent gets 122,604
sysstat db block changes 564,554
sysstat deferred (CURRENT) block cleanout applications 12
sysstat free buffer requested 70,607
sysstat immediate (CR) block cleanout applications 0
sysstat immediate (CURRENT) block cleanout applications 1,752
sysstat no work - consistent read gets 67,108
sysstat physical reads 66,750
sysstat physical reads direct 66,709
sysstat physical writes 22,918
sysstat physical writes from cache 22,918
sysstat physical writes non checkpoint 22,918
sysstat redo blocks written 967,108
sysstat redo size 479,412,088
sysstat redo writes 378

(PDB) SCOTTのセッション統計
こちらから見てもdirect path writeは発生していません

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sesstat cleanouts only - consistent read gets 0
sesstat commit cleanout failures: block lost 0
sesstat commit cleanouts 1,589
sesstat commit cleanouts successfully completed 1,589
sesstat consistent gets 122,204
sesstat db block changes 564,506
sesstat deferred (CURRENT) block cleanout applications 7
sesstat free buffer requested 70,595
sesstat immediate (CR) block cleanout applications 0
sesstat immediate (CURRENT) block cleanout applications 1,748
sesstat no work - consistent read gets 66,884
sesstat physical reads 66,740
sesstat physical reads direct 66,709
sesstat redo size 478,945,336


該当期間の待機イベント記録されていないですよね。狙い通りなので準備としては問題なしです。

EVENT                                                            WAIT_CLASS
---------------------------------------------------------------- -----------------
SQL*Net message from client Idle
log buffer space Configuration
events in waitclass Other Other
direct path read User I/O
log file switch (private strand flush incomplete) Configuration
log file switch completion Configuration
log file sync Commit
db file sequential read User I/O
SQL*Net message to client Network
Disk file operations I/O User I/O
db file scattered read User I/O

6) CDB or PDBのSYSユーザで接続し、buffer cacheをflushする

SYS@orclcdb> @flush_buffercache.sql
1* alter system flush buffer_cache

System altered.

Elapsed: 00:00:09.04
14:36:26 SYS@orclcdb>


7) CDBのSYSで統計取得(buffer cacheをflush後)
strong>(CDB)システム統計

検証中に統計値が変動したもののみ記載

バッファキャッシュをフラッシュしたのでキャッシュから書き出されたことを示す physical writes from cache および関連する統計値が上昇しています。これも想定通りの挙動ですね。

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sysstat DBWR checkpoint buffers written 0
sysstat DBWR checkpoints 0
sysstat DBWR thread checkpoint buffers written 0
sysstat DBWR transaction table writes 8
sysstat DBWR undo block writes 1912
sysstat cleanouts only - consistent read gets 0
sysstat commit cleanout failures: block lost 0
sysstat commit cleanout failures: callback failure 0
sysstat commit cleanouts 43
sysstat commit cleanouts successfully completed 43
sysstat consistent gets 20793
sysstat db block changes 429
sysstat deferred (CURRENT) block cleanout applications 21
sysstat free buffer requested 1013
sysstat immediate (CR) block cleanout applications 0
sysstat immediate (CURRENT) block cleanout applications 9
sysstat no work - consistent read gets 12321
sysstat physical reads 977
sysstat physical reads direct 0
sysstat physical writes 47900
sysstat physical writes from cache 47900
sysstat physical writes non checkpoint 47900
sysstat redo blocks written 2017
sysstat redo size 994652
sysstat redo writes 23

(PDB) SCOTTのセッション統計

キャッシュをフラッシュしただけなので、該当セッションの統計には変化がありません。(まあ、そうですよねw)


SOURCE NAME VALUE
------- ---------------------------------------------------- ---------------
sesstat cleanouts only - consistentread gets 0
sesstat commit cleanout failures: block lost 0
sesstat commit cleanouts 0
sesstat commit cleanouts successfully completed 0
sesstat consistent gets 0
sesstat db block changes 0
sesstat deferred (CURRENT) block cleanout applications 0
sesstat free buffer requested 0
sesstat immediate (CR) block cleanout applications 0
sesstat immediate (CURRENT) block cleanout applications 0
sesstat no work - consistent read gets 0
sesstat physical reads 0
sesstat physical reads direct 0
sesstat physical writes 0
sesstat physical writes direct 0
sesstat physical writes from cache 0
sesstat physical writes non checkpoint 0
sesstat redo blocks written 0
sesstat redo size 0

8) PDBのSCOTTユーザーでコミットの実行

SCOTT@orcl> commit;

Commit complete.

Elapsed: 00:00:00.01


9) CDBのSYSで統計取得(コミット後)
strong>(CDB)システム統計
コミット時点ではクリーンアウト仕切れないほどの更新ブロック数かつ、コミット前にバッファキャッシュをフラッシュしているので、コミット時のクリーンアウトもできない状態なっています(これも事前の準備の通りの結果。なので問題なし)
commit cleanouts と commit cleanout failures: block lost がポイントです。コミット時にクリーンアウトできる量(過去の記事を参照のこと)の閾値以下の量ですら、事前にキャッシュからフラッシュしまっているので、クリーンアウトに失敗(できないようにしたので当然ですが)しています。両方の統計値が同一であるとくことは、コミットクリーンアウトしようとした全てでくりアウトできなかった。理由はキャッシュに該当ブロックがキャッシュから落ちていたから(意図的に落としたわけですが)ということを意味します。予定通りですね。

コミットの時点で最低現おこなうクリーンアウトもさせていないですが、このケースでは 11140 ブロックをコミット時にクリーンアウトしようとしているので、コミット時のクリーンアウトが行われていたとしても 50,000 ブロック以上は遅延されていたことになりますね。今回は、 66,667 ブロックがク後続のSQLで参照されるついでにクリーンアウトされることになります。

検証中に統計値が変動したもののみ記載

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sysstat DBWR checkpoint buffers written 0
sysstat DBWR checkpoints 0
sysstat DBWR thread checkpoint buffers written 0
sysstat DBWR transaction table writes 0
sysstat DBWR undo block writes 0
sysstat cleanouts only - consistent read gets 0
sysstat commit cleanout failures: block lost 11140
sysstat commit cleanout failures: callback failure 0
sysstat commit cleanouts 11140
sysstat commit cleanouts successfully completed 0
sysstat consistent gets 34
sysstat db block changes 1
sysstat deferred (CURRENT) block cleanout applications 0
sysstat free buffer requested 8
sysstat immediate (CR) block cleanout applications 0
sysstat immediate (CURRENT) block cleanout applications 0
sysstat no work - consistent read gets 5
sysstat physical reads 8
sysstat physical reads direct 0
sysstat physical writes 0
sysstat physical writes from cache 0
sysstat physical writes non checkpoint 0
sysstat redo blocks written 3
sysstat redo size 456
sysstat redo writes 3

(PDB) SCOTTのセッション統計
セッションレベルでみるよりはっきり見るとことができます。

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sesstat cleanouts only - consistent read gets 0
sesstat commit cleanout failures: block lost 11140
sesstat commit cleanouts 11140
sesstat commit cleanouts successfully completed 0
sesstat consistent gets 0
sesstat db block changes 1
sesstat deferred (CURRENT) block cleanout applications 0
sesstat free buffer requested 1
sesstat immediate (CR) block cleanout applications 0
sesstat immediate (CURRENT) block cleanout applications 0
sesstat no work - consistent read gets 0
sesstat physical reads 1
sesstat physical reads direct 0
sesstat physical writes 0
sesstat physical writes direct 0
sesstat physical writes from cache 0
sesstat physical writes non checkpoint 0
sesstat redo blocks written 0
sesstat redo size 176


10) PDBのSCOTTユーザーで遅延ブロッククリーンアウト有無確認(対象表を主キーによる一意検索で全行アクセス)

さて、事前に想定している実行計画になっているかプランだけ確認しておきましょう。主キーによる索引ユニークスキャンであることが確認できます。想定通りです。この実行計画で、200,000 行をグルグル参照した場合、遅延されたブロッククリーンアウトが行われるでしょうか。。。。(してくれないと思いますが。。。試してみましょう)

SCOTT@orcl> set autot trace exp
14:41:47 SCOTT@orcl> select * from hoge2 where id = 1;
Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
Plan hash value: 3319133482

----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1015 | 1 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| HOGE2 | 1 | 1015 | 1 (0)| 00:00:01 |
|* 2 | INDEX UNIQUE SCAN | PK_HOGE2 | 1 | | 1 (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("ID"=1)

SCOTT@orcl> set autot off
SCOTT@orcl>
SCOTT@orcl> @table_unique_scan_hoge2.sql
1 begin
2 for i in 1..&1 loop
3 for hoge2_rec in (select * from hoge2 where id = i) loop
4 null;
5 end loop;
6 end loop;
7* end;
Enter value for 1: 200000
old 2: for i in 1..&1 loop
new 2: for i in 1..200000 loop

PL/SQL procedure successfully completed.

Elapsed: 00:00:14.94
14:39:36 SCOTT@orcl>


11) CDBのSYSで統計取得(遅延ブロッククリーンアウト有無確認。対象表を主キーによる一意検索で全行アクセス)
strong>(CDB)システム統計

クリーンアウトが行われていれば、データブロックの総数 66,667 ブロックは少なくともクリーンアップの対象になっているはずですが。。。。。
cleanout系の統計値に動きはありませんよね。

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sysstat DBWR checkpoint buffers written 21
sysstat DBWR checkpoints 0
sysstat DBWR thread checkpoint buffers written 0
sysstat DBWR transaction table writes 5
sysstat DBWR undo block writes 5
sysstat cleanouts only - consistent read gets 0
sysstat commit cleanout failures: block lost 0
sysstat commit cleanout failures: callback failure 15
sysstat commit cleanouts 366
sysstat commit cleanouts successfully completed 351
sysstat consistent gets 632775
sysstat db block changes 7848
sysstat deferred (CURRENT) block cleanout applications 169
sysstat free buffer requested 76662
sysstat immediate (CR) block cleanout applications 0
sysstat immediate (CURRENT) block cleanout applications 169
sysstat no work - consistent read gets 21822
sysstat physical reads 69501
sysstat physical reads direct 0
sysstat physical writes 21
sysstat physical writes from cache 21
sysstat physical writes non checkpoint 10
sysstat redo blocks written 5132
sysstat redo size 2536084
sysstat redo writes 28

(PDB) SCOTTのセッション統計

physical reads は、67706 ブロックなのでほ、HOGE2表の索引と表のセグメントサイズほどは物理読み込みされたということになります。ただ、cleanouts only - consistent read gets などのクリーンアウトを示す統計値はほぼ動いていません。ようするに、db file sequential readとなる index unique scan ではブロッククリーンアウトは発生しないということを意味しています。

おおおーーー。だったら、グルグル系の処理で一行ごとに処理するのが最高じゃん! という単純な話ではないので要注意ですからねw

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sesstat cleanouts only - consistent read gets 0
sesstat commit cleanout failures: block lost 0
sesstat commit cleanouts 4
sesstat commit cleanouts successfully completed 4
sesstat consistent gets 600005
sesstat db block changes 14
sesstat deferred (CURRENT) block cleanout applications 2
sesstat free buffer requested 74540
sesstat immediate (CR) block cleanout applications 0
sesstat immediate (CURRENT) block cleanout applications 2
sesstat no work - consistent read gets 0
sesstat physical reads 67706
sesstat physical reads direct 0
sesstat physical writes 0
sesstat physical writes direct 0
sesstat physical writes from cache 0
sesstat physical writes non checkpoint 0
sesstat redo blocks written 0
sesstat redo size 2152


10) PDBのSCOTTユーザーで遅延ブロッククリーンアウト有無確認(sacattered read)

single block readを行うindex unique scanではクリーンアウトが発生しなかったということは、全表走査させる table full scan かつ scattered readさせれば発生するのではないでしょうか? という確認です。
auto traceで統計情報をみると、なにやら、REDOログが大量に生成されてますよね。。。これは!!!

SCOTT@orcl> @table_full_scan_hoge2.sql
1* alter session set "_serial_direct_read" = never

Session altered.

Elapsed: 00:00:00.01
1* alter session set "_very_large_object_threshold" = 20400

Session altered.

Elapsed: 00:00:00.00
set autot trace exp stat

1* select * from hoge2

200000 rows selected.

Elapsed: 00:00:06.55

Execution Plan
----------------------------------------------------------
Plan hash value: 1530105727

---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 172K| 167M| 18223 (1)| 00:00:01 |
| 1 | TABLE ACCESS FULL| HOGE2 | 172K| 167M| 18223 (1)| 00:00:01 |
---------------------------------------------------------------------------

Note
-----
- dynamic statistics used: dynamic sampling (level=2)


Statistics
----------------------------------------------------------
10 recursive calls
1 db block gets
147157 consistent gets
377 physical reads
5866968 redo size
406775148 bytes sent via SQL*Net to client
147265 bytes received via SQL*Net from client
13335 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
200000 rows processed

set autot off

14:56:56 SCOTT@orcl>


11) CDBのSYSで統計取得(遅延ブロッククリーンアウト有無確認。対象表を主キーによる一意検索で全行アクセス)
strong>(CDB)システム統計

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sysstat DBWR checkpoint buffers written 1121
sysstat DBWR checkpoints 0
sysstat DBWR thread checkpoint buffers written 0
sysstat DBWR transaction table writes 36
sysstat DBWR undo block writes 347
sysstat cleanouts only - consistent read gets 66676
sysstat commit cleanout failures: block lost 0
sysstat commit cleanout failures: callback failure 0
sysstat commit cleanouts 806
sysstat commit cleanouts successfully completed 806
sysstat consistent gets 174296
sysstat db block changes 80773
sysstat deferred (CURRENT) block cleanout applications 383
sysstat free buffer requested 2095
sysstat immediate (CR) block cleanout applications 66676
sysstat immediate (CURRENT) block cleanout applications 75
sysstat no work - consistent read gets 27953
sysstat physical reads 1842
sysstat physical reads direct 0
sysstat physical writes 1121
sysstat physical writes from cache 1121
sysstat physical writes non checkpoint 981
sysstat redo blocks written 16550
sysstat redo size 8074260
sysstat redo writes 351

(PDB) SCOTTのセッション統計
HOGE2の表のクリーンアウト対象ブロック数、66,667 きっちり同じ数字が現れました。しかも cleanoutに関わる統計でかつ、大量のREDOログも生成されています。でました〜〜〜w クリーンアウト。全表走査かつ、scattered readで。

SOURCE  NAME                                                           VALUE
------- ---------------------------------------------------- ---------------
sesstat cleanouts only - consistent read gets 66667
sesstat commit cleanout failures: block lost 0
sesstat commit cleanouts 1
sesstat commit cleanouts successfully completed 1
sesstat consistent gets 153731
sesstat db block changes 66718
sesstat deferred (CURRENT) block cleanout applications 0
sesstat free buffer requested 690
sesstat immediate (CR) block cleanout applications 66667
sesstat immediate (CURRENT) block cleanout applications 0
sesstat no work - consistent read gets 16317
sesstat physical reads 680
sesstat physical reads direct 0
sesstat redo size 5877252




まとめ

index unique scanでグルグルさせつつ、全行アクセスしても発生しないですよね!
single block readになるunique index scanでは、遅延ブロッククリーンアウトは発生しない。(想像通りでよかったw)
で、そのあとで全表走査(scattered read)させてみると、やはり、遅延ブロッククリーンアウトは発生するわけですよ。面白いです。ほんと。



さあ、5月末まで追い込みだw ブログ書かないとw (頑張って、アドベントカレンダー全部俺やっとくほうが実は楽なのかもしれないw)

では、また。



古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #1
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #2
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #3
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #4
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #5
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #6
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #7
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #8
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #9
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #10
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #11
古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #12



|

コメント

コメントを書く