[pgsql-jp: 41092] Re: Question about "Total runtime"

[Jun Ogawa]

To: 笠原さま、花田さま、MauMauさま、Ishiiさま、片岡さま

小川です。
お世話になっております。

解決しました。問題は二つありました。

(1) 疑似環境と現場環境の時間（実行計画の作成時間も、Total runtimeも、realの時間も）の差が大きい
     疑似環境 <<< 現場環境
(2) SQLの単純な文に比べて、実行計画の作成時間、Total runtimeが大きい。（疑似環境であっても）

(1)はDBに私たちが使っているプロセス以外からの激しいアクセスがあったことが原因でした。
このプロセスは不要なので、外してもらったら、直りました。orz

(2)は不要な時刻分までスキャンが走り、余計にテーブルを舐めていたことが原因でした。

(1)が直ったら、要求仕様内の時間に収まったので、(2)は次回以降に見直します。

＃ありがちではありますが、案外、つまらないオチでした...。

数々のアドバイス、本当にありがとうございました。

以上です。

Thu Apr 19 2012 07:46:26 GMT+0900 (JST), Jun Ogawa-san wrote;
> To: 笠原さま、花田さま、MauMauさま、Ishiiさま、片岡さま
> 
> 小川です。
> お世話になっています。おかげさまでだいぶ整理できてきました。
> ＃このSQLの部分は過去の資産の流用で、開発者はいないので、文書とコードで追いかけています...。
> 
> 疑似環境で、
> =# \timing
> =# EXPLAIN<SQL文>
> をやったところ、
> 
> Time: 1461.619 ms
> 
> となりました。疑似環境もテーブルやレコードの中身は同じです。
> 
> Total runtime: 49.167 ms
> $ time psql -f sql2.txt -U ogawa db_name>  /dev/null
> 　　real    0m1.557s
> 　　user    0m0.023s
> 　　sys     0m0.007s
> 
> でした。
> 
> SQL文：
> 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 ;
> 
> のAとBは継承を使っており、A,Bの下にはそれぞれ576のテーブル(48時間を5分毎にまとめたテーブル）があります。
> それを全部 Seq_Scanしています。実際にその後の処理で必要なのは2時間分だけでしたので、このあたりは見直しポイントです。
> 
> ただAもBも576のテーブルのレコード数の総和(=576ぶんの総和)はそれぞれ20,000以下です。
> また疑似環境と現場環境の時間（実行計画の作成時間も、Total runtimeも、realの時間も）差がありすぎるため、ちょっと統計情報も比較してみようと思います。
> 
> 以上です。
> 
> Wed Apr 18 2012 14:09:25 GMT+0900 (JST), Hiroki Kataoka-san wrote;
>> 片岡です。
>>
>> 私もEXPLAINの結果のrowsの多さに疑問を感じてました。
>> よって、「パースに時間がかかってる」に1票。
>>
>> 皆さんからのアドバイスをもとに、パースに時間がかかっていることが間違いないようであれば、まずは、そんなに複雑なクエリーが本当に必要なのか（なにか根本的に間違えてないか？）等を検討してみてください。
>>
>> それでも複雑なクエリーにならざるを得ないなら、毎回パースすることを防ぐために問題のSELECT文をSQL関数にまとめてみてください。
>>
>> CREATE FUNCTION osoi_select (userid integer, name text, address text)
>> RETURNS SETOF record
>> AS $$
>>     SELECT a.time AS time FROM a, b  WHERE a.userid = $1 AND b.time  = a.time
>>     AND b.name = $2 AND a.address = $3 limit 1;
>> $$
>> LANGUAGE sql STABLE;
>>
>> ※上記の最後「STABLE」で良いかは確認してください。http://www.postgresql.jp/document/8.3/html/xfunc-volatility.html
>>
>> で、実際に問い合わせしている部分をSQL関数の呼び出しに置き換えます。
>>
>> SELECT c.time FROM osoi_select(10, 'OGAWA', 'Yokohama') AS c;
>>
>> 本当にパース時間が問題であれば、これでEXPLAIN ANALYZEに近い時間で問い合わせできるようになります。
>>
>> 2012年4月17日12:10 Jun Ogawa<jogawa ＠ gmail.com>:
>>> 小川と申します。お世話になっております。
>>>
>>> EXPLAIN ANALYZEの"Total runtime"の解釈について、質問させてください。
>>>
>>> 開発中のDBシステムの性能解析をしています。
>>>
>>> ある検索のSQL（後述）で、EXPLAIN ANALYZEをかけたところ、
>>>
>>> Total runtime: 3540.537 ms(2954 rows)
>>>
>>> と出ました。
>>>
>>> 一方、このSQLを呼び出しているJava側で開始前後の時間を図ると17秒かかっています。Java側ではSQL実行文の前後で時刻のログを出させています。
>>> ＃手入力でSQLを実行しても、感覚でこれくらいの時間かかっています。
>>>
>>> 実際の実行時間とTotal runtimeのこの13.5秒差はどう理解したらいいのでしょうか？
>>> またこの13.5秒を短縮するためのアドバイスがありましたら、よろしくお願いいたします。
>>>
>>> SQL文：
>>> 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 ;
>>>
>>> 環境：
>>> PostgreSQL : 8.3.3
>>> RedHat: 5.4
>>>
>>> 以上です。
>>>
>>> ---
>>> Jun Ogawa
>>> jogawa ＠ gmail.com
>>
>>
>>
> 

-- 
Jun Ogawa
jogawa ＠ gmail.com