« 古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #4 | トップページ | 古くて新しい? 遅延ブロッククリーンアウト (deferred block cleanout) #6 »

2021年9月 9日 (木)

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

前回はバッファキャッシュの10%を超えるデータブロックへのINSERT文の実行とCOMMITの実行で、バッファキャッシュの13%-15%程度はCOMMIT時にクリーンアウトされ、残りは遅延ブロッククリーンアウト(先送り)される。
direct path readではないSELECT文による(前回のケースでは scattered read))遅延ブロッククリーンアウトは、1度のみ発生するという状況を確認しました。

ところで、
前回のエントリで、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.sql
alter session set "_serial_direct_read" = never
.
l
/
alter session set "_very_large_object_threshold" = 1056
.
l
/

!echo set autot trace exp stat
set autot trace exp stat


select * from hoge
.
l
/

!echo set autot off
set autot off




0) 対象表をdrop/create
オブジェクト作り直し

SCOTT@orcl> @droppurge_create_hoge

Table 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.00
SCOTT@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.48
SCOTT@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 23589
sysstat DBWR checkpoints 2
sysstat DBWR thread checkpoint buffers written 22643
sysstat DBWR transaction table writes 50
sysstat DBWR undo block writes 848
sysstat cleanouts and rollbacks - consistent read gets 5
sysstat commit cleanout failures: callback failure 20
sysstat commit cleanouts 1320
sysstat commit cleanouts successfully completed 1300
sysstat consistent gets 124041
sysstat db block changes 757165
sysstat deferred (CURRENT) block cleanout applications 715
sysstat immediate (CR) block cleanout applications 5
sysstat immediate (CURRENT) block cleanout applications 196
sysstat no work - consistent read gets 46398
sysstat physical reads 4063
sysstat physical writes 23589
sysstat physical writes from cache 23589
sysstat physical writes non checkpoint 23494

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

SOURCE  NAME                                                             VALUE
------- ------------------------------------------------- --------------------
sesstat commit cleanouts 6
sesstat commit cleanouts successfully completed 6
sesstat consistent gets 49596
sesstat db block changes 744727
sesstat deferred (CURRENT) block cleanout applications 4
sesstat immediate (CURRENT) block cleanout applications 1
sesstat no work - consistent read gets 49
sesstat physical reads 15


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

SCOTT@orcl> commit;

Commit complete.


7) CDBのSYSで統計取得(コミット後)
前回同様ノイズもなく、綺麗にコミット時のクリーンアウトが発生しています。バッファキャッシュの約14-5%程度なのは前回と変わらずですね。

差分のある統計のみ記載

(CDB)システム統計

SOURCE  NAME                                                             VALUE
------- ------------------------------------------------- --------------------
sysstat commit cleanouts 55700
sysstat commit cleanouts successfully completed 55700
sysstat db block changes 1

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

SOURCE  NAME                                                             VALUE
------- ------------------------------------------------- --------------------
sesstat commit cleanouts 55700
sesstat commit cleanouts successfully completed 55700
sesstat 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.00
SCOTT@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" = never

Session altered.

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

Session altered.

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

1* select * from hoge

200000 rows selected.

Elapsed: 00:00:06.10

Execution 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 processed

set autot off
SCOTT@orcl>


12) CDBのSYSで統計取得(遅延ブロッククリーンアウト有無確認)/ scattered read / table full scan の1回目

遅延ブロッククリーンアウト関連統計値が上昇しているので、遅延ブロッククリーンアウトの発生が確認できます。ここまでは前回と同じ。(同じじゃないと困りますが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 10967
sysstat commit cleanouts 7
sysstat commit cleanouts successfully completed 7
sysstat consistent gets 98967
sysstat db block changes 11016
sysstat deferred (CURRENT) block cleanout applications 3
sysstat immediate (CR) block cleanout applications 10967
sysstat immediate (CURRENT) block cleanout applications 2
sysstat no work - consistent read gets 72543
sysstat physical reads 67403

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

SOURCE  NAME                                                             VALUE
------- ------------------------------------------------- --------------------
sesstat cleanouts only - consistent read gets 10967
sesstat commit cleanouts 6
sesstat commit cleanouts successfully completed 6
sesstat consistent gets 98357
sesstat db block changes 11012
sesstat deferred (CURRENT) block cleanout applications 2
sesstat immediate (CR) block cleanout applications 10967
sesstat immediate (CURRENT) block cleanout applications 2
sesstat no work - consistent read gets 72208
sesstat 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.00
SCOTT@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" = never

Session altered.

Elapsed: 00:00:00.00
1* alter session set "_very_large_object_threshold" = 1056

Session altered.

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

1* select * from hoge

200000 rows selected.

Elapsed: 00:00:06.44

Execution 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 processed

set autot off
SCOTT@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 11
sysstat commit cleanouts 15
sysstat commit cleanouts successfully completed 15
sysstat consistent gets 87375
sysstat db block changes 79
sysstat deferred (CURRENT) block cleanout applications 12
sysstat immediate (CURRENT) block cleanout applications 3
sysstat no work - consistent read gets 83322
sysstat physical reads 67028
sysstat physical writes 11
sysstat physical writes from cache 11
sysstat physical writes non checkpoint 11

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

SOURCE  NAME                                                             VALUE
------- ------------------------------------------------- --------------------
sesstat commit cleanouts 2
sesstat commit cleanouts successfully completed 2
sesstat consistent gets 86936
sesstat db block changes 29
sesstat deferred (CURRENT) block cleanout applications 1
sesstat no work - consistent read gets 83098
sesstat 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


|

コメント

コメントを書く