2011年8月20日

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

板垣様

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

>「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@xxxxx [mailto:pgsql-jp-bounces@xxxxx] 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@xxxxx>:
> 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

投稿者 xml-rpc : 2011年8月20日 20:44
役に立ちました?:
過去のフィードバック 平均:(0) 総合:(0) 投票回数:(0)
本記事へのTrackback: http://hoop.euqset.org/blog/mt-tb2006.cgi/106245
トラックバック
コメント
コメントする




画像の中に見える文字を入力してください。