[pgsql-jp: 40895] Re: auto_explainの実行計画について

nozawakz @ nttdata.co.jp nozawakz @ nttdata.co.jp
2011年 8月 20日 (土) 20:44:33 JST


板垣様

ご回答いただき、ありがとうございました。

>「5回以上」クエリを実行しない限り、prepare されません。
>サンプルコードで3回しか実行していないのが気になりました。

アドバイス頂き、ありがとうございます!
ご指摘の通り、3回しか実行しておりませんでした。

JAVAソースに
 pgstmt.setPrepareThreshold(2);
 boolean usingServerPrepare = pgstmt.isUseServerPrepare();
を加え、usingServerPrepareがtrueになっていることを
確認の上、実験してみました。

>「テーブル定義が変更された」のほうは確実にそのとおり動作するんですが、
>「統計情報が更新された」のほうは確証がありません。
>何か結果がわかったらお知らせしてもらえると嬉しいです。

下記、長文になりますが、
試験結果、対象テーブルとJAVAソースを張り付けようと思います。

結果としては、下記の9で再計画しているように見受けれます。

1⇒2⇒・・⇒9の順で時間が流れています。
5と9がポイントだと思っています。
 5⇒Preparedされた実行計画を使用している
 9⇒統計情報が更新されたため、キャッシュされた計画計画を破棄したので、再計画


1.-----------------------------------------------------------
【SQL文】
TRUNCATE t_test02;
SELECT count(*) from t_test02;
ANALYZE t_test02;

【JAVA側】
なし

【PostgreSQLログ】
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000026 elapsed 0.000000 user 0.000000 system sec
        !       [0.016997 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1089] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [59/36] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  TRUNCATE t_test02;
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000003 elapsed 0.000000 user 0.000000 system sec
        !       [0.016997 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1089] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [59/36] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  TRUNCATE t_test02;
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000001 elapsed 0.000000 user 0.000000 system sec
        !       [0.016997 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1089] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [59/36] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  TRUNCATE t_test02;
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000035 elapsed 0.000000 user 0.000000 system sec
        !       [0.019996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [66/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT count(*) from t_test02;
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000130 elapsed 0.000000 user 0.000000 system sec
        !       [0.019996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [66/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT count(*) from t_test02;
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000005 elapsed 0.000000 user 0.000000 system sec
        !       [0.019996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [66/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT count(*) from t_test02;
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000393 elapsed 0.001000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [66/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT count(*) from t_test02;
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000019 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [66/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT count(*) from t_test02;
LOG:  duration: 0.014 ms  plan:
        Aggregate  (cost=10.50..10.51 rows=1 width=0)
          ->  Seq Scan on t_test02  (cost=0.00..10.40 rows=40 width=0)
STATEMENT:  SELECT count(*) from t_test02;
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000025 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [68/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000003 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [68/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000001 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1093] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [68/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
-----------------------------------------------------------
2.
【SQL文】
なし

【JAVA側】
start SQL: 1 2011.08.21 at 03:52:21 JST
Execution: 1, usingServerPrepare: false
end SQL: 1 2011.08.21 at 03:52:21 JST

【PostgreSQLログ】
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000160 elapsed 0.000000 user 0.000000 system sec
        !       [0.000000 user 0.002999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/58 [0/520] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [2/5] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000958 elapsed 0.000000 user 0.001000 system sec
        !       [0.000000 user 0.003999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/149 [0/685] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/1 [2/6] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000011 elapsed 0.000000 user 0.000000 system sec
        !       [0.000000 user 0.003999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/3 [0/690] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [2/6] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000807 elapsed 0.000999 user 0.000000 system sec
        !       [0.000999 user 0.003999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/86 [0/793] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/1 [2/7] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000067 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.003999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/8 [0/825] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [2/7] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          1 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  duration: 0.046 ms  plan:
        Index Scan using idx_a02 on t_test02  (cost=0.00..8.27 rows=1 width=1963)
          Index Cond: (a07 = 1)
-----------------------------------------------------------
3.
【SQL文】
なし

【JAVA側】
start SQL: 2 2011.08.21 at 03:52:51 JST
Execution: 2, usingServerPrepare: true
end SQL: 2 2011.08.21 at 03:52:51 JST

【PostgreSQLログ】
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000043 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.004999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/848] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [3/8] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000066 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.004999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/848] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [3/8] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000004 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.004999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/848] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [3/8] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000147 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.004999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/848] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [3/8] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000022 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.005999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/2 [0/855] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [3/9] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  duration: 0.017 ms  plan:
        Index Scan using idx_a02 on t_test02  (cost=0.00..8.27 rows=1 width=1963)
          Index Cond: (a07 = $1)
-----------------------------------------------------------
4.
【SQL文】
INSERT INTO t_test02 (a01,a07) VALUES (1,1);

【JAVA側】
start SQL: 3 2011.08.21 at 03:53:21 JST
Execution: 3, usingServerPrepare: true
end SQL: 3 2011.08.21 at 03:53:21 JST

【PostgreSQLログ】
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000019 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.005999 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/855] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [5/12] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  duration: 0.014 ms  plan:
        Index Scan using idx_a02 on t_test02  (cost=0.00..8.27 rows=1 width=1963)
          Index Cond: (a07 = $1)


LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000044 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1096] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [70/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000047 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1096] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [70/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000035 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1096] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [70/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000086 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1096] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [70/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
LOG:  duration: 0.283 ms  plan:
        Result  (cost=0.00..0.01 rows=1 width=0)
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000363 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1096] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [70/39] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          4 read,          0 written, buffer hit rate = 20.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  INSERT INTO t_test02 (a01,a07) VALUES (1,1);
-----------------------------------------------------------
5.
【SQL文】
なし

【JAVA側】
start SQL: 4 2011.08.21 at 03:53:51 JST
Execution: 4, usingServerPrepare: true
end SQL: 4 2011.08.21 at 03:53:51 JST

【PostgreSQLログ】
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000021 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/2 [0/861] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [7/12] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  duration: 0.017 ms  plan:
        Index Scan using idx_a02 on t_test02  (cost=0.00..8.27 rows=1 width=1963)
          Index Cond: (a07 = $1)
-----------------------------------------------------------
6.
【SQL文】
ANALYZE t_test02;
\! date

【JAVA側】
なし

【PostgreSQLログ】
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000022 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1097] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [73/40] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000003 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1097] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [73/40] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000001 elapsed 0.000000 user 0.000000 system sec
        !       [0.020996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1097] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [73/40] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  ANALYZE t_test02;
-----------------------------------------------------------
7.
【SQL文】
なし

【JAVA側】
start SQL: 5 2011.08.21 at 03:54:21 JST
Execution: 5, usingServerPrepare: true
end SQL: 5 2011.08.21 at 03:54:21 JST

【PostgreSQLログ】
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000155 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/861] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [9/13] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000005 elapsed 0.000000 user 0.000000 system sec
        !       [0.000999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/861] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [9/13] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000557 elapsed 0.001000 user 0.000000 system sec
        !       [0.001999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/10 [0/871] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/1 [9/14] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000025 elapsed 0.000000 user 0.000000 system sec
        !       [0.001999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/4 [0/877] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [9/14] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
LOG:  duration: 0.021 ms  plan:
        Seq Scan on t_test02  (cost=0.00..1.01 rows=1 width=1963)
          Filter: (a07 = $1)
-----------------------------------------------------------
8.
【SQL文】
\! date
delete from t_test02 where a01='1';

【JAVA側】
なし

【PostgreSQLログ】
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000044 elapsed 0.000000 user 0.000000 system sec
        !       [0.021996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/2 [1/1102] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [75/44] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
        !       0.000147 elapsed 0.000000 user 0.000000 system sec
        !       [0.022996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1102] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [75/44] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000003 elapsed 0.000000 user 0.000000 system sec
        !       [0.022996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1102] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [75/44] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  PLANNER STATISTICS
DETAIL:  ! system usage stats:
        !       0.000206 elapsed 0.000000 user 0.000000 system sec
        !       [0.022996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [1/1102] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [75/44] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  duration: 0.027 ms  plan:
        Seq Scan on t_test02  (cost=0.00..1.01 rows=1 width=6)
          Filter: (a01 = '1'::bpchar)
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000127 elapsed 0.000000 user 0.000000 system sec
        !       [0.022996 user 0.011998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/1 [1/1103] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [75/44] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  delete from t_test02 where a01='1'
        ;
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
        !       0.000017 elapsed 0.000000 user 0.000000 system sec
        !       [0.001999 user 0.006998 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/882] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [13/16] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 100.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
STATEMENT:  SELECT * FROM t_test02 WHERE a07 = $1
-----------------------------------------------------------
9.
【SQL文】
なし

【JAVA側】
start SQL: 6 2011.08.21 at 03:54:51 JST
Execution: 6, usingServerPrepare: true
end SQL: 6 2011.08.21 at 03:54:51 JST

【PostgreSQLログ】
LOG:  duration: 0.012 ms  plan:
        Seq Scan on t_test02  (cost=0.00..1.01 rows=1 width=1963)
          Filter: (a07 = $1)

*********************************************
下記、対象テーブルとJAVAソース

1.対象テーブル
postgres=# \d t_test02;
           テーブル "public.t_test02"
 カラム |           型           |    修飾語
--------+------------------------+--------------
 a01    | character(12)          | not null
 a02    | character(15)          |
 a03    | character(3)           |
 a04    | integer                |
 a05    | character varying(24)  |
 a06    | character varying(255) |
 a07    | integer                |
 a08    | character varying(384) |
 a09    | date                   |
 a10    | date                   |
 a11    | character(7)           |
 a12    | character(7)           |
 a13    | character(7)           |
 a14    | integer                |
 a15    | integer                |
 a16    | character varying(384) |
 a17    | date                   |
 a18    | character(1)           | デフォルト 0
 a19    | date                   |
 a20    | character varying(20)  |
 a21    | character varying(20)  |
 a22    | date                   |
 a23    | date                   |
 a24    | character(1)           | デフォルト 0
インデックス:
    "t_test02_pkey" PRIMARY KEY, btree (a01)
    "idx_a02" btree (a07)

2.JAVAソース
import java.sql.*;
import java.text.*;
import java.util.*;

public class PreparedTest {

        public static void main(String[] args) {
                PreparedTest preparedtest =new PreparedTest();
                try {
                        preparedtest.selectPostgre();
                } catch (Exception e) {
                        e.printStackTrace();
                }
        }

        public void selectPostgre() throws Exception{

          /* ユーザ名 */
          String user = "postgres";
          /* パスワード */
          String pass = "nttdata";
          /* サーバ名 */
          String servername = "localhost";
          /* データベース名 */
          String dbname = "postgres";

                try {
                                /* ドライバクラスのロード */
                                Class.forName ("org.postgresql.Driver");


                                /* Connectionの作成 */
                                Connection conn = DriverManager.getConnection
                                ("jdbc:postgresql://" + servername + ":5432/" + dbname,user,pass);

                                // select文の場合
                                PreparedStatement pstmt = conn.prepareStatement("SELECT * FROM t_test02 WHERE a07 = ?;");

                                // PostgreSQL拡張インタフェースへキャストします。
                                org.postgresql.PGStatement pgstmt = (org.postgresql.PGStatement)pstmt;

                                // 2回目の実行で、サーバサイドの準備済み文が使用されるようになります。
                                pgstmt.setPrepareThreshold(2);

                                for (int i=1; i<=10; i++)
                                {

                                        java.util.Date date1 = new java.util.Date();
                                        SimpleDateFormat sdf1 = new SimpleDateFormat("yyyy.MM.dd 'at' HH:mm:ss z");
                                        System.out.println("\nstart SQL: " + i + " "+ sdf1.format(date1));  //Dateオブジェクトを表示

                                        pstmt.setInt(1,i);
                                        boolean usingServerPrepare = pgstmt.isUseServerPrepare();
                                        ResultSet rs = pstmt.executeQuery();
                                        rs.next();
                                        System.out.println("Execution: "+i+", usingServerPrepare: " + usingServerPrepare);
                                        rs.close();

                                        java.util.Date date2 = new java.util.Date();
                                        SimpleDateFormat sdf2 = new SimpleDateFormat("yyyy.MM.dd 'at' HH:mm:ss z");
                                        System.out.println("end SQL: " + i + " " + sdf2.format(date2));  //Dateオブジェクトを表示

                                        Thread.sleep(30000);
                                }

                } catch (SQLException e) {
                        throw e;
                } catch ( Exception e){
                        throw e;
                } finally{
                }
            }


}



以上、よろしくお願い致します。

-----Original Message-----
From: pgsql-jp-bounces @ ml.postgresql.jp [mailto:pgsql-jp-bounces @ ml.postgresql.jp] On Behalf Of Itagaki Takahiro
Sent: Friday, August 19, 2011 9:48 PM
To: PostgreSQL Japanese Mailing List
Subject: [pgsql-jp: 40893] Re: auto_explainの実行計画について

2011/8/19  <nozawakz @ nttdata.co.jp>:
> PostgreSQL 8.3の新機能として、SRA社のHPにも記載があるので

確かに記述はありますね。
----
テーブル定義が変更されたり、統計情報が更新された場合に、
キャッシュされたクエリを自動的に再計画するようにしました。
Automatically re-plan cached queries when table definitions change
or statistics are updated
----
「テーブル定義が変更された」のほうは確実にそのとおり動作するんですが、
「統計情報が更新された」のほうは確証がありません。
何か結果がわかったらお知らせしてもらえると嬉しいです。


ところで、JDBC をお使いのようですが、prepareThreshold の設定に
注意が必要かもしれません。具体的には、デフォルト設定だと
「5回以上」クエリを実行しない限り、prepare されません。
サンプルコードで3回しか実行していないのが気になりました。

http://jdbc.postgresql.org/documentation/head/connect.html

--
Itagaki Takahiro


pgsql-jp メーリングリストの案内