[pgsql-jp: 40896] Re: auto_explainの実行計画について
Yoshiyuki Asaba
ysyk.asaba @ gmail.com
2011年 8月 21日 (日) 01:06:34 JST
浅羽です。
> >「テーブル定義が変更された」のほうは確実にそのとおり動作するんですが、
> >「統計情報が更新された」のほうは確証がありません。
> >何か結果がわかったらお知らせしてもらえると嬉しいです。
>
> 下記、長文になりますが、
> 試験結果、対象テーブルとJAVAソースを張り付けようと思います。
>
> 結果としては、下記の9で再計画しているように見受けれます。
9.0.4で同じく実験してみました。analyzeするとプランを作りなおすようです。
test=# CREATE TABLE t (a int primary key);
test=# insert into t value (1);
test=# analyze;
test=# prepare a as SELECT * FROM t where a = $1;
test=# explain execute a(1);
QUERY PLAN
-------------------------------------------------
Seq Scan on t (cost=0.00..5.01 rows=1 width=4)
Filter: (a = $1)
(2 rows)
test=# select pg_backend_pid();
pg_backend_pid
----------------
6121
(1 row)
test=# insert into t select generate_series(2, 1000);
INSERT 0 999
test=# analyze t;
ANALYZE
test=# explain execute a(1);
QUERY PLAN
----------------------------------------------------------------
Index Scan using t_pkey on t (cost=0.00..8.27 rows=1 width=4)
Index Cond: (a = $1)
(2 rows)
* gdbで動作確認
(gdb) attach 6121
(gdb) b AddRelcacheInvalidationMessage
Breakpoint 1 at 0x77ca8b: file inval.c, line 355.
(gdb) b ResetPlanCache
Breakpoint 2 at 0x77ef58: file plancache.c, line 1123.
(gdb) b RevalidateCachedPlan
Breakpoint 3 at 0x77e21f: file plancache.c, line 457.
(gdb) b PlanCacheRelCallback
Breakpoint 4 at 0x77ec23: file plancache.c, line 986.
(gdb) b pg_plan_query
Breakpoint 5 at 0x69f93b: file postgres.c, line 751.
* ANALYZE実行
(gdb) c
Continuing.
(gdb) bt
#0 AddRelcacheInvalidationMessage (hdr=0x17c15d0, dbId=16384,
relId=16385) at inval.c:355
#1 0x000000000077cd67 in RegisterRelcacheInvalidation (dbId=16384,
relId=16385) at inval.c:445
#2 0x000000000077d1b2 in PrepareForTupleInvalidation
(relation=0x7fdf581efee0, tuple=0x184ab20) at inval.c:653
#3 0x000000000077d747 in CacheInvalidateHeapTuple
(relation=0x7fdf581efee0, tuple=0x184ab20) at inval.c:1057
#4 0x0000000000478dc7 in heap_inplace_update
(relation=0x7fdf581efee0, tuple=0x184ab20) at heapam.c:3540
#5 0x000000000059be77 in vac_update_relstats (relation=0x195a1c0,
num_pages=5, num_tuples=1000, hasindex=1 '\001', frozenxid=0) at
vacuum.c:570
#6 0x000000000053d74a in do_analyze_rel (onerel=0x195a1c0,
vacstmt=0x1776600, update_reltuples=1 '\001', inh=0 '\000') at
analyze.c:542
#7 0x000000000053cc7c in analyze_rel (relid=16385, vacstmt=0x1776600,
bstrategy=0x17f4270, update_reltuples=1 '\001') at analyze.c:227
#8 0x000000000059b84b in vacuum (vacstmt=0x1776600, relid=0,
do_toast=1 '\001', bstrategy=0x17f4270, for_wraparound=0 '\000',
isTopLevel=1 '\001') at vacuum.c:246
ここでSHAREDINVALRELCACHE_IDが送られる。
* EXPLAIN EXECUTE
(gdb) c
Breakpoint 4, PlanCacheRelCallback (arg=0, relid=16817) at plancache.c:986
(gdb) bt
#0 PlanCacheRelCallback (arg=0, relid=16817) at plancache.c:986
#1 0x000000000077ceb7 in LocalExecuteInvalidationMessage
(msg=0xba1ea0) at inval.c:506
#2 0x000000000068d5c7 in ReceiveSharedInvalidMessages
(invalFunction=0x77cd8c <LocalExecuteInvalidationMessage>,
resetFunction=0x77cf70 <InvalidateSystemCaches>) at sinval.c:121
#3 0x000000000077d1d3 in AcceptInvalidationMessages () at inval.c:673
#4 0x00000000004959de in AtStart_Cache () at xact.c:768
SHAREDINVALRELCACHE_IDを受けて、plan->deadをマークする
Breakpoint 5, pg_plan_query (querytree=0x17d9978, cursorOptions=0,
boundParams=0x0) at postgres.c:751
(gdb) bt
#0 pg_plan_query (querytree=0x17d9978, cursorOptions=0,
boundParams=0x0) at postgres.c:751
#1 0x000000000069fa26 in pg_plan_queries (querytrees=0x17da5d0,
cursorOptions=0, boundParams=0x0) at postgres.c:822
#2 0x000000000077e404 in RevalidateCachedPlan (plansource=0x17a68a0,
useResOwner=1 '\001') at plancache.c:566
#3 0x000000000056b895 in ExplainExecuteQuery (execstmt=0x16d1d40,
es=0x7fff0a1ccd50, queryString=0x1775be0 "explain execute a(1);",
params=0x0) at prepare.c:672
#4 0x0000000000556267 in ExplainOneUtility (utilityStmt=0x16d1d40,
es=0x7fff0a1ccd50, queryString=0x1775be0 "explain execute a(1);",
params=0x0) at explain.c:313
#5 0x00000000005561b0 in ExplainOneQuery (query=0x17a4598,
es=0x7fff0a1ccd50, queryString=0x1775be0 "explain execute a(1);",
params=0x0) at explain.c:277
#6 0x0000000000555f78 in ExplainQuery (stmt=0x1776670,
queryString=0x1775be0 "explain execute a(1);", params=0x0,
dest=0x17a44d8) at explain.c:198
プランを作りなおし。
2011年8月20日20:44 <nozawakz @ nttdata.co.jp>:
> 板垣様
>
> ご回答いただき、ありがとうございました。
>
> >「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
>
--
Yoshiyuki Asaba
ysyk.asaba @ gmail.com
pgsql-jp メーリングリストの案内