statspackの使用例としてしばしば見かけるものの一つに、ライブラリキャッシュのヒット率がある。Oracleでは同一と見なされないSQLの書き方とかバインド変数の効果とかについての記述と共に記されることが多い。また、ヒット率はおおむねどの文献でも95％～99%以上を保ちましょう、と書かれている。
このエントリでは、あえてライブラリキャッシュにヒットしないSQLを流し続けたとき、何が起きるのかをstatspackレポートを通して確認してみる。やることとしては2つのプログラムの実行時間とstatspackレポートを比較する。1つは、SELECT文のWHEREをバインド変数にし、もう1つは、バインド変数を使わず毎回静的なSQLを実行させ続ける。
環境
準備
下記のような2列を持つテーブル・主キーにインデックスを作成し、100万行追加しておく。
DROP TABLE million_rows_table PURGE; CREATE TABLE million_rows_table ( column_pk_int INT NOT NULL , column_vchar VARCHAR2(20) , CONSTRAINT million_rows_table_pk PRIMARY KEY ( column_pk_int ) ENABLE ); INSERT INTO million_rows_table(column_pk_int, column_vchar) SELECT ROWNUM, dbms_random.string('X', 20) FROM (SELECT ROWNUM FROM all_catalog WHERE ROWNUM <= 1000), (SELECT ROWNUM FROM all_catalog WHERE ROWNUM <= 1000); COMMIT;
各プログラムを流す前に、バッファキャッシュ・共有プールのキャッシュをクリアしておく……で充分なんだろうけど。実行時間の計測は、それぞれのプログラムを流す前にOracleを再起動してから行った。
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH SHARED_POOL;
検証用プログラム
静的なSQLの実行
下記のような静的なSQLを100万回実行する。
SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 1 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 2 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 3 ...
このエントリで言うところの「あえてヒットさせないSQL」とは上記のようなものを指す。バインド変数使えるところをあえて使っていない、とも言える。
Javaプログラム上では、文字列連結で毎回異なるSQL文字列を作成し、Statementを使用してそのSQL文を実行する。
public class LibraryZeroHit { public static void main(String[] args) throws Exception { long start = System.currentTimeMillis(); final String sqlStr = "SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = "; try (Connection connection = DriverManager.getConnection( "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "xxxx"); Statement statement = connection.createStatement();) { int j=0; for (int i=1; i<=1_000_000; i++) { try (ResultSet r = statement.executeQuery(sqlStr + i);) { while (r.next()) { int pkValue = r.getInt("column_pk_int"); j++; } } } System.out.println(j); } long end = System.currentTimeMillis(); System.out.println(end - start); } }
バインド変数
StatementをPreparedStatementに変更し、SQL文の文字列をバインド変数にした以外は同一の内容。
public class LibraryAllHit { public static void main(String[] args) throws Exception { long start = System.currentTimeMillis(); final String sqlStr = "SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = ?"; try (Connection connection = DriverManager.getConnection( "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "xxxx"); PreparedStatement sql = connection.prepareStatement(sqlStr);) { int j=0; for (int i=1; i<=1_000_000; i++) { sql.setInt(1, i); try (ResultSet r = sql.executeQuery();) { while (r.next()) { int pkValue = r.getInt("column_pk_int"); j++; } } } System.out.println(j); } long end = System.currentTimeMillis(); System.out.println(end - start); } }
感想とか
v$sqlの確認
まずV$SQLを確認してみる。下記のようなクエリを実行してみる。
SELECT sql_text FROM v$sql WHERE sql_text LIKE 'SELECT column_pk_int FROM%';
すると、静的SQLのケースでは下記のような結果がドバッと返ってきて、あぁライブラリキャッシュに同じようなSQL文がたまりまくってるな、ということが分かる。
SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999895 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999941 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999763 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999870 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999995 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999661 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999891 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999707 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999942 SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = 999815
次に、バインド変数の方でも同様にv$sqlを確認してみると、下記1件だけが返ってくる。
SELECT column_pk_int FROM million_rows_table WHERE column_pk_int = :1
statspack
Instance Efficiency Indicatorsを見る。
| 種類 | 静的 | バインド |
|---|---|---|
| Library Hit | 43.13% | 99.85% |
| Soft Parse | 1.18% | 77.83% |
| Execute to Parse | 0.86% | 99.92% |
Library Hitを見ると静的の場合は50%を切っている。0くらいになるんかなと思ったけど、Oracleが内部的に他にもいろんなSQL発行してるからこんなもんなのかな、といった感じ。
Soft Parseがゼロ付近になるのは当然、Execute to Parseがゼロ付近になるのも理屈に合っている。
Statisticを見てみる
| Statistic | 静的 | バインド |
|---|---|---|
| parse time elapsed | 1,131.1 | 0.6 |
| hard parse elapsed time | 837.5 | 0.6 |
解析関連に大きく差がついてるのが分かる。
今回の実験は、同一条件の比較かというとちょっと異なるものなので、単純に比較することはできないのだけど。そうはいっても、上記表の数値だけを見ればCPUリソースは数百倍の差となっている。たとえばhard parse elapsed timeでは片や0.6とほぼゴミレベルなのが、片や837.5である。
このエントリのように主キーでひっかけて1件だけひっかける処理はオンラインではありふれたものである。このとき、たいていは静的SQLでもバインド変数でも実行時間はほぼゼロ秒で返ってくると予想できる。しかし、内部的には人間の目には気付かないけれどもCPUの無駄遣いをしている。まぁこういうのは、レスポンスタイムではなくスループットで見つける事になるんでしょうかね。
個人的に興味深かったのが、静的の場合のstatspackにだけは下記のようなMemory Resize Operationsという項目が存在していたところ。
Memory Resize Operations DB/Inst: XE/XE Snaps: 142- 143
-> Status: ERR: ERRor, COM: COMplete, PEN: PENding
-> Delta - Target change in size (MB)
-> Num Ops - number of identical Operations initiated concurrently
Elap Init Delta(M) Final Num
Start Time (s) Cache Size(M) & Mode Size(M) Sta Ops
------------- ----- -------------- -------- --------- -------- --- -----
0104 17:45:55 0 D:buffer cache 52 -4 IMM 48 COM 1
0104 17:45:55 0 shared pool 184 +4 IMM 188 COM 1
0104 17:46:19 0 D:buffer cache 48 -4 IMM 44 COM 1
0104 17:46:19 0 shared pool 188 +4 IMM 192 COM 1このセクションが意味しているのは、バッファキャッシュのサイズが52M→48M→44Mと縮小され、逆に共有プールのサイズが184M→188M→192Mと拡張されたことを示している。
これは自動共有メモリー管理によるもの。ライブラリキャッシュがガンガン増えるもんだから、その時点では余ってるバッファキャッシュを減らして、そちらに回したものだと思われる。昔はこれを手動でやっていたって言うんだから驚きなんだよなぁ（小並感）
ライブラリキャッシュが静的SQLで埋め尽くされるのみならず共有プールの拡張を促してバッファキャッシュの縮小に繋がる、というのは中々にエキサイティングな体験であった。
