読者です 読者をやめる 読者になる 読者になる

kagamihogeの日記

kagamihogeの日記です。

ライブラリキャッシュにヒットしないSQLを流し続けたときのstatspackを見る

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);
    }

}

実行結果

試行回数は、めんどくさくなってので1回だけにしておいた。

種類 1
静的SQL 1594953
バインド変数 341078

感想とか

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で埋め尽くされるのみならず共有プールの拡張を促してバッファキャッシュの縮小に繋がる、というのは中々にエキサイティングな体験であった。