[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 メーリングリストの案内