[pgsql-jp: 41088] Re: Question about "Total runtime"
Jun Ogawa
jogawa ＠ gmail.com
2012年 4月 18日 (水) 01:37:43 JST
笠原さま、花田さま、MauMauさま、Ishiiさま、
小川です。
コメントをありがとうございます。
実行計画は以下のようにしてとりました。
$ psql -f sql1.txt -U ogawa db_name > plan.log
このときのsql1.txtには
EXPLAIN ANALYZE SELECT A.time FROM A, B WHERE A.userid = 10 AND B.time = A.time
AND B.name = 'OGAWA' AND A.address = 'Yokohama' limit 1 ;
がかかれています。
＃ちなみにVERBOSEをつけたら、rowsは20390行になってしまいました。
手打ちは、
$ time psql -f sql2.txt -U ogawa db_name > /dev/null
としました。sql2.txtは上記から EXPLAIN ANALYZE を除いたものです。
この結果のrealで表示された時間は、javaでのログの時間(17秒)とほぼ一致したので、
javaやプロセス間通信の被疑は薄く、DBだと見ています。
MauMauさまがおっしゃるとおり、問い合わせ計画の作成がダウトではないかとは考えましたが、
その負荷／実行時間をとる術があるとは知りませんでした。
ありがとうございます＞笠原さま、花田さま
明日（あ、もう今日か）、さっそく試してみます。
ただ明日から来週まで問題が起きている現場には入れず、ローカルの疑似環境での試験になるため、
傾向をみるだけになってしまいますが、まずその結果をご報告いたします。
テーブルの構造や中身はほぼ同じですが、疑似環境で実行すると17秒ではなく、数秒です。
疑似環境と現地環境ではCPUのコアの割当が異なっている（疑似のほうがCPUリソースが潤沢に割り
当てられている）ため、Ishiiさんのご指摘にあるようにハードウェア資源が異なっていることも
原因としてあるなと気がつきました。割当も含めて、確認してみます。
周りにPostgreSQLに詳しい人がいないため、本当に助かります。
よろしくお願いいたします。
以上です。
Tue Apr 17 2012 22:32:01 GMT+0900 (JST), -san wrote;
>> あるいは
>> =# log_planner_stats TO 'on';
>> =# SQL文;
> すいません。SET が抜けてますね。
>
> =# SET log_planner_stats TO 'on';
> =# SQL文;
>
> --
> 笠原 辰仁
>
>
>> -----Original Message-----
>> From: pgsql-jp-bounces ＠ ml.postgresql.jp
>> [mailto:pgsql-jp-bounces ＠ ml.postgresql.jp] On Behalf Of
>> kasaharatt ＠ nttdata.co.jp
>> Sent: Tuesday, April 17, 2012 10:20 PM
>> To: pgsql-jp ＠ ml.postgresql.jp
>> Subject: [pgsql-jp: 41085] Re: Question about "Total runtime"
>>
>> 笠原です。
>>
>>>> このログ(実際にはrowsはTotal runtimeの次の行に出るはずですが)は、
>> EXPLAIN
>>>> ANALYZEの結果(実行計画)が 2954 行あるいうことですよね？これは
>> VERBOSEオプ
>>>> ションなどを指定していたとしても相当複雑なSQLです。
>> 確かに。計画そのものの行数が多いですね・・・
>>
>>> 問合わせ計画の作成時間を知る方法はあるでしょうか？ -> みなさん
>> さくっと思いつくところで、手軽なのは
>> =# \timing
>> =# EXPLAIN<SQL文>
>> でしょうか。
>>
>> あるいは
>> =# log_planner_stats TO 'on';
>> =# SQL文;
>> として出力されたログを確認するとかですかね。
>> (以下の★あたりを見てみる)
>>
>> (例)
>> LOG: PLANNER STATISTICS
>> DETAIL: ! system usage stats:
>> ! 0.000347 elapsed 0.000000 user 0.000000 system sec ★
>> ! [0.000999 user 0.001999 sys total] ★
>> ! 0/0 [0/0] filesystem blocks in/out
>> ! 0/106 [0/935] page faults/reclaims, 0 [0] swaps
>> ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
>> ! 0/0 [3/11] 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 t1, t2 WHERE t1.id=t2.id AND to_number(t1.name,
>> '000')< 10;
>>
>> --
>> 笠原 辰仁
>>
>>
>>> -----Original Message-----
>>> From: pgsql-jp-bounces ＠ ml.postgresql.jp
>>> [mailto:pgsql-jp-bounces ＠ ml.postgresql.jp] On Behalf Of MauMau
>>> Sent: Tuesday, April 17, 2012 9:51 PM
>>> To: PostgreSQL Japanese Mailing List
>>> Subject: [pgsql-jp: 41084] Re: Question about "Total runtime"
>>>
>>> 小川さん
>>>
>>> MauMauといいます。
>>>
>>> From: "花田 茂"<hanada ＠ metrosystems.co.jp>
>>>> このログ(実際にはrowsはTotal runtimeの次の行に出るはずですが)は、
>>> EXPLAIN
>>>> ANALYZEの結果(実行計画)が 2954 行あるいうことですよね？これは
>> VERBOSE
>>> オプ
>>>> ションなどを指定していたとしても相当複雑なSQLです。このことからす
>> る
>>> と、
>>>
>>> この花ださんのコメントを見て、SQL文の問合わせ計画の作成に時間がかかっ
>> て
>>> いるのではないか、と思いました。
>>> マニュアルの次の部分をご覧ください。
>>>
>>> http://www.postgresql.jp/document/pg910doc/html/using-explain.html
>>>
>>> [抜粋]
>>> EXPLAIN ANALYZEで表示されるTotal runtime（総実行時間）にはエクゼキュ
>> ー
>>> タの起動、停止時間も含まれますが、解析や書き換え、計画作成の時間は含
>> ま
>>> れません。
>>>
>>>
>>> 問合わせ計画の作成時間を知る方法はあるでしょうか？ -> みなさん
>>>
>>> 以上です。
>>>
>
--
Jun Ogawa
jogawa ＠ gmail.com
skype: junogawa1211
pgsql-jp メーリングリストの案内