古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #5 Tweet
前回はバッファキャッシュの10%を超えるデータブロックへのINSERT文の実行とCOMMITの実行で、バッファキャッシュの13%-15%程度はCOMMIT時にクリーンアウトされ、残りは遅延ブロッククリーンアウト（先送り）される。
direct path readではないSELECT文による(前回のケースでは scattered read）)遅延ブロッククリーンアウトは、１度のみ発生するという状況を確認しました。
ところで、
前回のエントリで、2度、全表走査（前回の検証ではscattered read）を実行しているのですが、物理読み込みは発生させていません。（INSERT→COMMIT→SELECT→SELECTという流れで、十分なバッファキャッシュがあるので、当然ではあるのですがw）
バッファキャッシュに乗ったままのブロックが遅延クリーンアウトされていたわけです。
前回のエントリ：古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #4
--------------------------------------------------------------------------| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |--------------------------------------------------------------------------| 0 | SELECT STATEMENT | | 194K| 188M| 18189 (1)| 00:00:01 || 1 | TABLE ACCESS FULL| HOGE | 194K| 188M| 18189 (1)| 00:00:01 |--------------------------------------------------------------------------
1. 遅延ブロッククリーンアウトを発生させた場合。遅延ブロッククリーンアウト対象のデータがバッファキャッシュ上ににあるためクリーンアウトに伴う物理読み込みはない。
Statistics---------------------------------------------------------- 46 recursive calls 13 db block gets 91636 consistent gets 7 physical reads 967348 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 2 sorts (memory) 0 sorts (disk) 200000 rows processed
2. 直後に再度全表走査した場合も、キャッシュヒットしているので、物理読み込みはない
Statistics---------------------------------------------------------- 0 recursive calls 0 db block gets 80061 consistent gets 0 physical reads 0 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 200000 rows processed
前述の1.2.それぞれの実行で物理読み込みだったなにか変化はあるのだろうか。。。予想では、上記に加えてscattered readに伴う物理読み込みが増えるだけのはずです。その動きを見てみることにします。（こういう動きを見ていると楽しいですよねw）
手順は前回と同じですが、各全表走査の前にインスタンスを再起動してバッファキャッシュを空にしておきます。
(buffer cacheをflushすればいいじゃん。という声も聞こえてきそうですが、今回は再起動でクリアしました。はいw)
前回から多少変更したスクリプトも載せておきます（本文中にもありますが）、細かい解説は後述
$ cat table_full_scan.sqlalter session set "_serial_direct_read" = never.l/alter session set "_very_large_object_threshold" = 1056.l/!echo set autot trace exp statset autot trace exp statselect * from hoge.l/!echo set autot offset autot off
0) 対象表をdrop/create
オブジェクト作り直し
SCOTT@orcl> @droppurge_create_hogeTable dropped.Table created.SCOTT@orcl> select segment_name,blocks from user_segments where segment_name like '%HOGE%';no rows selected
1) 統計をクリアするのにインスタンス再起動
$ sudo service oracle restart
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('TargetSession'); 3* end;PL/SQL procedure successfully completed.Elapsed: 00:00:00.00SCOTT@orcl>
3) CDBのSYSで統計取得（初回）
内容は省略！（統計差分取得のためのベースラインを取得しているだけ）
SYS$orclcdb> @show_stat scott
4) PDBのSCOTTユーザーでデータINSERT（データ量2倍、コミットなし）
SCOTT@orcl> @insert_each_rows_2 1* begin for i in 1..200000 loop insert into hoge values(i, lpad('*', 2000, '*')); end loop; end;PL/SQL procedure successfully completed.Elapsed: 00:00:29.48SCOTT@orcl>
5) CDBのSYSで統計取得（INSERT後、未コミット）
未コミットの状態なので特に、気にせず、ふーーーん。ぐらいの感じで眺めていただければいいですね。前回同様に、commit cleanouts, commit cleanouts successfully completed, deferred (CURRENT) block cleanout applications, immediate (CURRENT) block cleanout applicationsといったクリーンアウト関連統計が極わずかありますが、この時点で発生しているのは本題ではないので気にしなくてOK
差分のある統計のみ記載
(CDB）システム統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sysstat DBWR checkpoint buffers written 23589sysstat DBWR checkpoints 2sysstat DBWR thread checkpoint buffers written 22643sysstat DBWR transaction table writes 50sysstat DBWR undo block writes 848sysstat cleanouts and rollbacks - consistent read gets 5sysstat commit cleanout failures: callback failure 20sysstat commit cleanouts 1320sysstat commit cleanouts successfully completed 1300sysstat consistent gets 124041sysstat db block changes 757165sysstat deferred (CURRENT) block cleanout applications 715sysstat immediate (CR) block cleanout applications 5sysstat immediate (CURRENT) block cleanout applications 196sysstat no work - consistent read gets 46398sysstat physical reads 4063sysstat physical writes 23589sysstat physical writes from cache 23589sysstat physical writes non checkpoint 23494
(PDB) SCOTTのセッション統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sesstat commit cleanouts 6sesstat commit cleanouts successfully completed 6sesstat consistent gets 49596sesstat db block changes 744727sesstat deferred (CURRENT) block cleanout applications 4sesstat immediate (CURRENT) block cleanout applications 1sesstat no work - consistent read gets 49sesstat physical reads 15
6) PDBのSCOTTユーザーでコミットの実行
SCOTT@orcl> commit;
Commit complete.
7) CDBのSYSで統計取得（コミット後）
前回同様ノイズもなく、綺麗にコミット時のクリーンアウトが発生しています。バッファキャッシュの約14-5%程度なのは前回と変わらずですね。
差分のある統計のみ記載
(CDB）システム統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sysstat commit cleanouts 55700sysstat commit cleanouts successfully completed 55700sysstat db block changes 1
(PDB) SCOTTのセッション統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sesstat commit cleanouts 55700sesstat commit cleanouts successfully completed 55700sesstat db block changes 1
8) Oracle Databaseを再起動してバッファキャッシュをクリア
ここが前回と違う手順で、クリーンアウトされないブロックはずーーーーーっと残るよね。ということの確認でもあります。（alter system flush buffer_cacheでも同じことができるわけですが、ここでは再起動しています）
$ sudo service oracle restart[sudo] password for oracle:Restarting oracle (via systemctl): [ OK ]$
9) PDBのscottでログインし、client_infoをセット
disconnectしたので再度、client infoをセットし直し！
SCOTT@orcl> @set_client_info 1 begin 2 DBMS_APPLICATION_INFO.SET_CLIENT_INFO('TargetSession'); 3* end;PL/SQL procedure successfully completed.Elapsed: 00:00:00.00SCOTT@orcl>
10) CDBのSYSで統計取得（再起動後初回）
内容は省略！（再起動したので統計値の差分取得用ベースライン統計の取得）
SYS$orclcdb> @show_stat scott
11) PDBのSCOTTユーザーで、遅延ブロッククリーンアウト影響有無確認（対象表を全表走査）- scattered read / table full scan の1回目
ここでは待機イベントまでは確認できませんが、Table full scanと実行統計よりRedoログがたっぷり生成されていることは確認できます。SELECT文ですが。。。つまり、遅延ブロッククリーンアウトが発生しているということですね。確認は後述の統計で。
狙い通り、物理読み込みも発生しています！
Note)
"_very_large_object_threshold" = 1056 としているのは、direct path readとなる上限セグメントサイズをhoge表が超えているためdirect path readを抑止するためにこの隠しパラメータで上限値を引き上げ、scattered readになるように強制しています。
SCOTT@orcl> @table_full_scan.sql 1* alter session set "_serial_direct_read" = neverSession altered.Elapsed: 00:00:00.01 1* alter session set "_very_large_object_threshold" = 1056Session altered.Elapsed: 00:00:00.00set autot trace exp stat 1* select * from hoge200000 rows selected.Elapsed: 00:00:06.10Execution Plan----------------------------------------------------------Plan hash value: 2339479017--------------------------------------------------------------------------| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |--------------------------------------------------------------------------| 0 | SELECT STATEMENT | | 214K| 207M| 18223 (1)| 00:00:01 || 1 | TABLE ACCESS FULL| HOGE | 214K| 207M| 18223 (1)| 00:00:01 |--------------------------------------------------------------------------Note----- - dynamic statistics used: dynamic sampling (level=2)Statistics---------------------------------------------------------- 38 recursive calls 13 db block gets 91519 consistent gets 67073 physical reads 967432 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 5 sorts (memory) 0 sorts (disk) 200000 rows processedset autot offSCOTT@orcl>
12) CDBのSYSで統計取得（遅延ブロッククリーンアウト有無確認）/ scattered read / table full scan の１回目
遅延ブロッククリーンアウト関連統計値が上昇しているので、遅延ブロッククリーンアウトの発生が確認できます。ここまでは前回と同じ。（同じじゃないと困りますがw）
違う点は、事前にインスタンスを再起動しているため、physical reads が上昇しています。これは hoge表を scattered readで全表走査しているからです。（phsical read directは発生していない）バッファキャッシュを経由するのでconsistent gets,no work - consistent read gets も上昇しています。狙い通りです。
そして、重量な遅延ブロッククリーンアウトですが、バッファキャッシュでヒットしていた時と同数のブロックで発生しています。（ニッコリ
インスタンスの停止や起動があったとしても、クリーンアウトが先送りされたブロックはアクセスされない限りクリーンアウトされず残っているということを示しています！！！！（ここ試験にでますよー。嘘）
(CDB）システム統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sysstat cleanouts only - consistent read gets 10967sysstat commit cleanouts 7sysstat commit cleanouts successfully completed 7sysstat consistent gets 98967sysstat db block changes 11016sysstat deferred (CURRENT) block cleanout applications 3sysstat immediate (CR) block cleanout applications 10967sysstat immediate (CURRENT) block cleanout applications 2sysstat no work - consistent read gets 72543sysstat physical reads 67403
(PDB) SCOTTのセッション統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sesstat cleanouts only - consistent read gets 10967sesstat commit cleanouts 6sesstat commit cleanouts successfully completed 6sesstat consistent gets 98357sesstat db block changes 11012sesstat deferred (CURRENT) block cleanout applications 2sesstat immediate (CR) block cleanout applications 10967sesstat immediate (CURRENT) block cleanout applications 2sesstat no work - consistent read gets 72208sesstat physical reads 67397
13) Oracle Databaseを再起動してバッファキャッシュをクリア
再度、インスタンスを再起動して、バッファキャッシュをクリアします。後続の全表走査では、遅延ブロッククリーンアウトは発生せず、物理読み込み(この検証では scattered readさせています)を伴うTable full scanが行われるだけのはずです。
$ sudo service oracle restart[sudo] password for oracle:Restarting oracle (via systemctl): [ OK ]$
14) PDBのscottでログインし、client_infoをセット
disconnectしたので再度、client infoをセットし直し！
SCOTT@orcl> @set_client_info 1 begin 2 DBMS_APPLICATION_INFO.SET_CLIENT_INFO('TargetSession'); 3* end;PL/SQL procedure successfully completed.Elapsed: 00:00:00.00SCOTT@orcl>
15) CDBのSYSで統計取得（再起動後初回）
内容は省略！（再起動したのでベースラインとなる統計を取得）
SYS$orclcdb> @show_stat scott
16) PDBのSCOTTユーザーで、遅延ブロッククリーンアウト影響有無確認（対象表を全表走査）- scattered read / table full scan の2回目
実行統計から、physical readsが、発生しています。Redoは生成されていないことも読み取れるので、遅延ブロッククリーンアウトは発生していないことも確認できます。：） 想定通りですね。
SCOTT@orcl> @table_full_scan.sql 1* alter session set "_serial_direct_read" = neverSession altered.Elapsed: 00:00:00.00 1* alter session set "_very_large_object_threshold" = 1056Session altered.Elapsed: 00:00:00.00set autot trace exp stat 1* select * from hoge200000 rows selected.Elapsed: 00:00:06.44Execution Plan----------------------------------------------------------Plan hash value: 2339479017--------------------------------------------------------------------------| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |--------------------------------------------------------------------------| 0 | SELECT STATEMENT | | 214K| 207M| 18223 (1)| 00:00:01 || 1 | TABLE ACCESS FULL| HOGE | 214K| 207M| 18223 (1)| 00:00:01 |--------------------------------------------------------------------------Note----- - dynamic statistics used: dynamic sampling (level=2)Statistics---------------------------------------------------------- 30 recursive calls 0 db block gets 80211 consistent gets 66719 physical reads 0 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 5 sorts (memory) 0 sorts (disk) 200000 rows processedset autot offSCOTT@orcl>
17) CDBのSYSで統計取得（遅延ブロッククリーンアウト有無確認）/ scattered read / table full scan の2回目
physical reads は発生していますが、physical reads directではないことが確認できます。Table full scanをscattered readで読み込んでいるという想定通りの結果。
遅延ブロッククリーンアウトを示deferred (CURRENT) block cleanout applications 、immediate (CURRENT) block cleanout applicationsや、コミットクリーンアウトを示すcommit cleanouts 、commit cleanouts successfully completed という統計が極わずかに変動していますが、今回の検証ではノイズなので気にしたくてOK。
(CDB）システム統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sysstat DBWR checkpoint buffers written 11sysstat commit cleanouts 15sysstat commit cleanouts successfully completed 15sysstat consistent gets 87375sysstat db block changes 79sysstat deferred (CURRENT) block cleanout applications 12sysstat immediate (CURRENT) block cleanout applications 3sysstat no work - consistent read gets 83322sysstat physical reads 67028sysstat physical writes 11sysstat physical writes from cache 11sysstat physical writes non checkpoint 11
(PDB) SCOTTのセッション統計
SOURCE NAME VALUE------- ------------------------------------------------- --------------------sesstat commit cleanouts 2sesstat commit cleanouts successfully completed 2sesstat consistent gets 86936sesstat db block changes 29sesstat deferred (CURRENT) block cleanout applications 1sesstat no work - consistent read gets 83098sesstat physical reads 67023
まとめ
遅延ブロッククリーンアウトは、インスタンスを停止して残ったままということが確認できました。（クリアされるまで残るのですよねー）
クリーンアウトが遅延されているブロックが物理読み込みされた（アクセスされた）タイミングで遅延ブロッククリーンアウトが発生することも確認できました。（物理読み込みの有無には関係しない）
バッファキャッシュ上の遅延ブロッククリーンアウト同様、クリーンアウトされたブロックでは、再度、クリーンアウト対象になるような更新が発生しなければ、遅延ブロッククリーンアウトは発生しない
久しぶりにシステム統計やセッション統計を見ててワクワクしてきましたよーーーーっw
ところで、
冒頭でも記載しましたが、バッファキャッシュ上の遅延ブロッククリーンアウト（再掲）に加え、物理読み込みを伴う遅延ブロッククリーンアウトのauto traceの結果をまとめて記載しておきます。SELECT文ですが、REDOログが生成されている場合は遅延ブロッククリーンアウトが発生しているということになります。
実行計画
--------------------------------------------------------------------------| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |--------------------------------------------------------------------------| 0 | SELECT STATEMENT | | 194K| 188M| 18189 (1)| 00:00:01 || 1 | TABLE ACCESS FULL| HOGE | 194K| 188M| 18189 (1)| 00:00:01 |--------------------------------------------------------------------------
1. 遅延ブロッククリーンアウトを発生させた場合。遅延ブロッククリーンアウト対象のデータがバッファキャッシュ上ににあるためクリーンアウトに伴う物理読み込みはない。
Statistics---------------------------------------------------------- 46 recursive calls 13 db block gets 91636 consistent gets 7 physical reads 967348 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 2 sorts (memory) 0 sorts (disk) 200000 rows processed
2. 直後に再度全表走査した場合も、キャッシュヒットしているので、物理読み込みはない
Statistics---------------------------------------------------------- 0 recursive calls 0 db block gets 80061 consistent gets 0 physical reads 0 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 200000 rows processed
3. 遅延ブロッククリーンアウトを発生させた場合。遅延ブロッククリーンアウト対象のデータを物理読み込みし、バッファキャッシュに載せている動きが見えます。
Statistics---------------------------------------------------------- 38 recursive calls 13 db block gets 91519 consistent gets 67073 physical reads 967432 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 5 sorts (memory) 0 sorts (disk) 200000 rows processed
4. 3.の直後に再度全表走査した場合。事前にキャッシュをクリアしているため、物理読み込みがありますが、遅延ブロッククリーンアウトは発生していません。（Redoが生成されていないことで確認できます）
Statistics---------------------------------------------------------- 30 recursive calls 0 db block gets 80211 consistent gets 66719 physical reads 0 redo size 406775148 bytes sent via SQL*Net to client 147264 bytes received via SQL*Net from client 13335 SQL*Net roundtrips to/from client 5 sorts (memory) 0 sorts (disk) 200000 rows processed
ではでは。
次回は、scattered readのtable full scanではなく、direct path readだったらどうなるのか調べてみましょうか。。（いろいろな再現方法があるわけですが、手間のかからないお手軽な再現方法で確認してみようと思いますw）
洗濯機の修理が終わって一安心w ということで、次回へつづく。
・古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #1
・古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #2
・古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #3
・古くて新しい？ 遅延ブロッククリーンアウト (deferred block cleanout) #4
| 固定リンク
コメント