Обсуждение: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

Поиск

Список

Период

Сортировка

Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Piotr Gasidło

Дата:

26 июля 2010 г., 08:35:56

Hello,

I've found strange problem in my database (8.4.4, but also 9.0beta3,
default postgresql.conf, shared_buffers raised to 256MB).

EXPLAIN ANALYZE SELECT ...
Total runtime: 4.782 ms
Time: 25,970 ms

SELECT ...
...
(21 rows)

Time: 23,042 ms

Test done in psql connected by socket to server (same host, using
\timing to get runtime).

Does big difference in "Total runtime" and "Time" is normal?

I've notice, that removing one index (not used in query,ocache_*_ukey,
used by me only to have data integrity)  gives me:

EXPLAIN ANALYZE SELECT ...
Total runtime: 3.439 ms
Time: 13,324 ms

Why such big difference in timing (vs. query with this index)?

Query is:
select oc_h_id,oc_duration,SUM(oc_count) FROM ocache WHERE
oc_date_from >= '2010-07-22'::date AND oc_date_from >=
'2010-07-24'::date AND oc_h_id =

ANY('{"32842","3095","27929","2229","22769","3098","33433","22559","226","2130","226","2130","2229","3095","3098","22559","22769","27929","32842","33433"}'::int[])
GROUP BY oc_h_id, oc_duration;

EXPLAIN ANALYZE is:

 HashAggregate  (cost=42060.58..42095.53 rows=2796 width=12) (actual
time=4.357..4.368 rows=21 loops=1)
   ->  Append  (cost=0.00..41850.91 rows=27955 width=12) (actual
time=0.432..3.928 rows=1439 loops=1)
         ->  Seq Scan on ocache  (cost=0.00..17.20 rows=6 width=12)
(actual time=0.002..0.002 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Bitmap Heap Scan on ocache_2010_7 ocache
(cost=357.41..8117.29 rows=5466 width=12) (actual time=0.430..0.582
rows=196 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_7_oc_h_id_key
(cost=0.00..356.04 rows=16397 width=0) (actual time=0.174..0.174
rows=1156 loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2010_8 ocache
(cost=370.91..9067.15 rows=6060 width=12) (actual time=0.175..0.615
rows=562 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_8_oc_h_id_key
(cost=0.00..369.39 rows=18181 width=0) (actual time=0.156..0.156
rows=1124 loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2010_9 ocache
(cost=389.47..9891.79 rows=6703 width=12) (actual time=0.158..0.513
rows=448 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_9_oc_h_id_key
(cost=0.00..387.80 rows=20108 width=0) (actual time=0.140..0.140
rows=896 loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2010_10 ocache
(cost=268.42..6735.90 rows=4721 width=12) (actual time=0.107..0.300
rows=229 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_10_oc_h_id_key
(cost=0.00..267.24 rows=14162 width=0) (actual time=0.096..0.096
rows=458 loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2010_11 ocache
(cost=139.48..3340.84 rows=2395 width=12) (actual time=0.046..0.047
rows=4 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_11_oc_h_id_key
(cost=0.00..138.88 rows=7184 width=0) (actual time=0.040..0.040 rows=8
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2010_12 ocache
(cost=108.78..1766.50 rows=1223 width=12) (actual time=0.041..0.041
rows=0 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2010_12_oc_h_id_key
(cost=0.00..108.48 rows=3668 width=0) (actual time=0.040..0.040 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_1 ocache
(cost=70.63..432.15 rows=246 width=12) (actual time=0.036..0.036
rows=0 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_1_oc_h_id_key
(cost=0.00..70.57 rows=738 width=0) (actual time=0.035..0.035 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_2 ocache
(cost=65.72..368.20 rows=204 width=12) (actual time=0.038..0.038
rows=0 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_2_oc_h_id_key
(cost=0.00..65.67 rows=612 width=0) (actual time=0.038..0.038 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_3 ocache
(cost=60.36..290.04 rows=147 width=12) (actual time=0.037..0.037
rows=0 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_3_oc_h_id_key
(cost=0.00..60.32 rows=442 width=0) (actual time=0.036..0.036 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_4 ocache
(cost=59.75..243.87 rows=118 width=12) (actual time=0.034..0.034
rows=0 loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_4_oc_h_id_key
(cost=0.00..59.72 rows=353 width=0) (actual time=0.033..0.033 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_5 ocache
(cost=54.99..190.27 rows=86 width=12) (actual time=0.032..0.032 rows=0
loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_5_oc_h_id_key
(cost=0.00..54.97 rows=257 width=0) (actual time=0.031..0.031 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_6 ocache
(cost=32.64..182.12 rows=80 width=12) (actual time=1.299..1.299 rows=0
loops=1)
               Recheck Cond: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               Filter: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               ->  Bitmap Index Scan on ocache_2011_6_ukey
(cost=0.00..32.62 rows=837 width=0) (actual time=0.224..0.224
rows=2510 loops=1)
                     Index Cond: ((oc_date_from >= '2010-07-22'::date)
AND (oc_date_from >= '2010-07-24'::date))
         ->  Bitmap Heap Scan on ocache_2011_7 ocache
(cost=55.15..195.99 rows=90 width=12) (actual time=0.033..0.033 rows=0
loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_7_oc_h_id_key
(cost=0.00..55.12 rows=271 width=0) (actual time=0.033..0.033 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_8 ocache
(cost=54.99..192.43 rows=87 width=12) (actual time=0.033..0.033 rows=0
loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_8_oc_h_id_key
(cost=0.00..54.97 rows=261 width=0) (actual time=0.033..0.033 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_9 ocache
(cost=54.99..188.23 rows=85 width=12) (actual time=0.033..0.033 rows=0
loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_9_oc_h_id_key
(cost=0.00..54.97 rows=256 width=0) (actual time=0.032..0.032 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Bitmap Heap Scan on ocache_2011_10 ocache
(cost=54.84..183.72 rows=82 width=12) (actual time=0.032..0.032 rows=0
loops=1)
               Recheck Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date))
               ->  Bitmap Index Scan on ocache_2011_10_oc_h_id_key
(cost=0.00..54.82 rows=247 width=0) (actual time=0.032..0.032 rows=0
loops=1)
                     Index Cond: (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[]))
         ->  Seq Scan on ocache_2011_11 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2011_12 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_1 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_2 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_3 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_4 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_5 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_6 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_7 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_8 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_9 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_10 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_11 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2012_12 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_1 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_2 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_3 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_4 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_5 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_6 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_7 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_8 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_9 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_10 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_11 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.000..0.000 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
         ->  Seq Scan on ocache_2013_12 ocache  (cost=0.00..17.20
rows=6 width=12) (actual time=0.001..0.001 rows=0 loops=1)
               Filter: ((oc_date_from >= '2010-07-22'::date) AND
(oc_date_from >= '2010-07-24'::date) AND (oc_h_id = ANY

('{32842,3095,27929,2229,22769,3098,33433,22559,226,2130,226,2130,2229,3095,3098,22559,22769,27929,32842,33433}'::integer[])))
 Total runtime: 4.725 ms
(137 rows)

Paritions are rather small, some of them are empty:

> select count(*) from ocache;
 count
--------
 907688
(1 row)


> \d ocache
                      Table "public.ocache"
        Column         |            Type             | Modifiers
-----------------------+-----------------------------+-----------
 oc_count              | integer                     |
 oc_to_id              | integer                     |
 oc_hc_ids             | integer[]                   |
 oc_h_id               | integer                     |
 oc_hg_id              | integer                     |
 oc_hg_category        | numeric(2,1)                |
 oc_r_id               | integer                     |
 oc_date_from          | date                        |
 oc_date_to            | date                        |
 oc_duration           | integer                     |
 oc_transport          | integer                     |
 oc_price_min          | numeric                     |
 oc_price_max          | numeric                     |
 oc_rc_ids             | integer[]                   |
 oc_orc_ids            | integer[]                   |
 oc_fc_ids             | integer[]                   |
 oc_ofc_id_1           | integer                     |
 oc_ap_ids_from1       | integer[]                   |
 oc_bc_ids_from        | integer[]                   |
 oc_obc_ids_from       | integer[]                   |
 oc_o_ids              | integer[]                   |
 oc_price_avg          | numeric                     |
 oc_o_date_updated_min | timestamp without time zone |
 oc_o_date_updated_max | timestamp without time zone |
Number of child tables: 48 (Use \d+ to list them.)

Data partitioned by month (oc_date_from column, tables created for
years: 2010, 2011, 2012, 2013), example child table:

> \d+ ocache_2010_12
                              Table "public.ocache_2010_12"
        Column         |            Type             | Modifiers |
Storage  | Description
-----------------------+-----------------------------+-----------+----------+-------------
 oc_count              | integer                     |           | plain    |
 oc_to_id              | integer                     |           | plain    |
 oc_hc_ids             | integer[]                   |           | extended |
 oc_h_id               | integer                     |           | plain    |
 oc_hg_id              | integer                     |           | plain    |
 oc_hg_category        | numeric(2,1)                |           | main     |
 oc_r_id               | integer                     |           | plain    |
 oc_date_from          | date                        |           | plain    |
 oc_date_to            | date                        |           | plain    |
 oc_duration           | integer                     |           | plain    |
 oc_transport          | integer                     |           | plain    |
 oc_price_min          | numeric                     |           | main     |
 oc_price_max          | numeric                     |           | main     |
 oc_rc_ids             | integer[]                   |           | extended |
 oc_orc_ids            | integer[]                   |           | extended |
 oc_fc_ids             | integer[]                   |           | extended |
 oc_ofc_id_1           | integer                     |           | plain    |
 oc_ap_ids_from1       | integer[]                   |           | extended |
 oc_bc_ids_from        | integer[]                   |           | extended |
 oc_obc_ids_from       | integer[]                   |           | extended |
 oc_o_ids              | integer[]                   |           | extended |
 oc_price_avg          | numeric                     |           | main     |
 oc_o_date_updated_min | timestamp without time zone |           | plain    |
 oc_o_date_updated_max | timestamp without time zone |           | plain    |
Indexes:
    "ocache_2010_12_oc_ap_ids_from1_key" gist (oc_ap_ids_from1)
    "ocache_2010_12_oc_h_id_key" btree (oc_h_id)
    "ocache_2010_12_oc_hg_id_key" btree (oc_hg_id)
    "ocache_2010_12_oc_obc_ids_from_key" gist (oc_obc_ids_from)
    "ocache_2010_12_oc_r_id_key" btree (oc_r_id)
    "ocache_2010_12_oc_to_id_key" btree (oc_to_id)
Check constraints:
    "ocache_2010_12_oc_date_from_check" CHECK (oc_date_from >=
'2010-12-01'::date AND oc_date_from <= '2011-01-01'::date)
Inherits: ocache
Has OIDs: no
Options: fillfactor=80

--
Piotr Gasidło

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Piotr Gasidło

Дата:

26 июля 2010 г., 08:44:25

W dniu 26 lipca 2010 10:35 użytkownik Piotr Gasidło
<quaker@barbara.eu.org> napisał:
>> \d+ ocache_2010_12
>                              Table "public.ocache_2010_12"
> Indexes:
> (...)

Missed index in listing:
    "ocache_2010_12_ukey" UNIQUE, btree (oc_date_from, oc_date_to,
oc_h_id, oc_transport, oc_ofc_id_1) WITH (fillfactor=80)

--
Piotr Gasidło

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Craig Ringer

Дата:

26 июля 2010 г., 09:15:30

On 26/07/10 16:35, Piotr Gasidło wrote:
> Hello,
>
> I've found strange problem in my database (8.4.4, but also 9.0beta3,
> default postgresql.conf, shared_buffers raised to 256MB).
>
> EXPLAIN ANALYZE SELECT ...
> Total runtime: 4.782 ms
> Time: 25,970 ms
>
> SELECT ...
> ...
> (21 rows)
>
> Time: 23,042 ms
>
> Test done in psql connected by socket to server (same host, using
> \timing to get runtime).
>
> Does big difference in "Total runtime" and "Time" is normal?

Given that EXPLAIN ANALYZE doesn't transfer large rowsets to the client,
it can't really be time taken to transfer the data, which is the usual
difference between 'explain analyze' timings and psql client-side timings.

Given that, I'm wondering if the difference in this case is planning
time. I can't really imagine the query planner taking 20 seconds (!!) to
run, though, no matter how horrifyingly complicated the query and table
structure were, unless there was something going wrong.

Another possibility, then, is that for some reason queries are being
delayed from starting or delayed before results are being returned, so
the server completes them in a short amount of time but it takes a while
for psql to find out they're finished.

In your position, at this point I'd be doing things like hooking a
debugger up to the postgres backend and interrupting its execution
periodically to see what it's up to while this query runs. I'd also be
using wireshark to look at network activity to see if there were any
clues there. I'd be using "top", "vmstat" and "iostat" to examine
system-level load if it was practical to leave the system otherwise
idle, so I could see if CPU/memory/disk were in demand, and for how long.

--
Craig Ringer

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Vitalii Tymchyshyn

Дата:

26 июля 2010 г., 09:25:31

26.07.10 12:15, Craig Ringer написав(ла):
> On 26/07/10 16:35, Piotr Gasidło wrote:
>
>> Hello,
>>
>> I've found strange problem in my database (8.4.4, but also 9.0beta3,
>> default postgresql.conf, shared_buffers raised to 256MB).
>>
>> EXPLAIN ANALYZE SELECT ...
>> Total runtime: 4.782 ms
>> Time: 25,970 ms
>>
>> SELECT ...
>> ...
>> (21 rows)
>>
>> Time: 23,042 ms
>>
>> Test done in psql connected by socket to server (same host, using
>> \timing to get runtime).
>>
>> Does big difference in "Total runtime" and "Time" is normal?
>>
> Given that EXPLAIN ANALYZE doesn't transfer large rowsets to the client,
> it can't really be time taken to transfer the data, which is the usual
> difference between 'explain analyze' timings and psql client-side timings.
>
> Given that, I'm wondering if the difference in this case is planning
> time. I can't really imagine the query planner taking 20 seconds (!!) to
> run, though, no matter how horrifyingly complicated the query and table
> structure were, unless there was something going wrong.
>
Actually it's 20ms, so I suspect your point about planning time is correct.
Piotr: You can try preparing your statement and then analyzing execute
time to check if this is planning time.

Best regards, Vitalii Tymchyshyn

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Craig Ringer

Дата:

26 июля 2010 г., 09:57:13

On 26/07/10 17:25, Vitalii Tymchyshyn wrote:
> 26.07.10 12:15, Craig Ringer написав(ла):
>> On 26/07/10 16:35, Piotr Gasidło wrote:
>>
>>> Hello,
>>>
>>> I've found strange problem in my database (8.4.4, but also 9.0beta3,
>>> default postgresql.conf, shared_buffers raised to 256MB).
>>>
>>> EXPLAIN ANALYZE SELECT ...
>>> Total runtime: 4.782 ms
>>> Time: 25,970 ms

>> Given that, I'm wondering if the difference in this case is planning
>> time. I can't really imagine the query planner taking 20 seconds (!!) to
>> run, though, no matter how horrifyingly complicated the query and table
>> structure were, unless there was something going wrong.
>>
> Actually it's 20ms, so I suspect your point about planning time is correct.

Oh, a commas-as-fraction-separator locale.

That makes sense. Thanks for the catch.

--
Craig Ringer

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Piotr Gasidło

Дата:

26 июля 2010 г., 10:04:26

2010/7/26 Vitalii Tymchyshyn <tivv00@gmail.com>:
> 26.07.10 12:15, Craig Ringer написав(ла):
> (...)
> Piotr: You can try preparing your statement and then analyzing execute time
> to check if this is planning time.

You are right.

I've done simple PREPARE (without params, etc).

> REPARE query as select oc_h_id,oc_duration,SUM(oc_count) FROM ocache WHERE oc_date_from >= '2010-07-22'::date AND
oc_date_from>= '2010-07-24'::date AND oc_h_id =
ANY('{"32842","3095","27929","2229","22769","3098","33433","22559","226","2130","226","2130","2229","3095","3098","22559","22769","27929","32842","33433"}'::int[])
GROUPBY oc_h_id, oc_duration; 
PREPARE
Time: 19,873 ms

> EXPLAIN ANALYZE EXECUTE query;
...
Total runtime: 3.237 ms
Time: 5,118 ms

> EXECUTE query;
 oc_h_id | oc_duration | sum
---------+-------------+------
   27929 |           7 |  546
    3098 |           7 |  552
   27929 |          14 |  512
    3098 |          14 |  444
   22769 |          14 |  984
   32842 |          14 |  444
   27929 |          22 |    4
   27929 |          15 |   44
   32842 |           7 |  552
   22769 |           7 | 1356
    2229 |           7 |  496
     226 |          14 |  536
    2130 |           7 |  536
    2130 |          14 |  448
     226 |           7 |  584
    2229 |          14 |  400
   33433 |          14 |  444
    3095 |           7 |  552
   33433 |           7 |  552
    3095 |          14 |  444
   27929 |           8 |   40
(21 rows)

Time: 3,494 ms

The time matches EXPLAIN ANALYZE runtime.

Compared to not prepared query, its big difference!

> select oc_h_id,oc_duration,SUM(oc_count) FROM ocache WHERE oc_date_from >= '2010-07-22'::date AND oc_date_from >=
'2010-07-24'::dateAND oc_h_id =
ANY('{"32842","3095","27929","2229","22769","3098","33433","22559","226","2130","226","2130","2229","3095","3098","22559","22769","27929","32842","33433"}'::int[])
GROUPBY oc_h_id, oc_duration; 
 oc_h_id | oc_duration | sum
---------+-------------+------
   27929 |           7 |  546
    3098 |           7 |  552
   27929 |          14 |  512
    3098 |          14 |  444
   22769 |          14 |  984
   32842 |          14 |  444
   27929 |          22 |    4
   27929 |          15 |   44
   32842 |           7 |  552
   22769 |           7 | 1356
    2229 |           7 |  496
     226 |          14 |  536
    2130 |           7 |  536
    2130 |          14 |  448
     226 |           7 |  584
    2229 |          14 |  400
   33433 |          14 |  444
    3095 |           7 |  552
   33433 |           7 |  552
    3095 |          14 |  444
   27929 |           8 |   40
(21 rows)

Time: 22,571 ms

Ok. Is there any way to tune postgresql, to shorten planning time for
such queries?

--
Piotr Gasidło

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Tom Lane

Дата:

27 июля 2010 г., 04:19:14

=?UTF-8?Q?Piotr_Gasid=C5=82o?= <quaker@barbara.eu.org> writes:
> Ok. Is there any way to tune postgresql, to shorten planning time for
> such queries?

You've got a ridiculously large number of partitions.  Use fewer.

            regards, tom lane

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Lew

Дата:

27 июля 2010 г., 19:54:55

Piotr Gasidło wrote:
>>>> EXPLAIN ANALYZE SELECT ...
>>>> Total runtime: 4.782 ms
>>>> Time: 25,970 ms

Vitalii Tymchyshyn wrote:
>> Actually it's 20ms, so I suspect your point about planning time is correct.

Craig Ringer wrote:
> Oh, a commas-as-fraction-separator locale.
>
> That makes sense. Thanks for the catch.

Strangely, the runtime is shown with a period for the separator, though.

--
Lew

Re: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...

От

Vitalii Tymchyshyn

Дата:

28 июля 2010 г., 11:07:17

27.07.10 02:03, Lew написав(ла):
> Piotr Gasidło wrote:
>>>>> EXPLAIN ANALYZE SELECT ...
>>>>> Total runtime: 4.782 ms
>>>>> Time: 25,970 ms
>
> Strangely, the runtime is shown with a period for the separator, though.
>
One value is calculated on server by EXPLAIN ANALYZE command, another is
calculated by psql itself.

Best regards, Vitalii Tymchyshyn

Вход в личный кабинет

Восстановление пароля

Подтверждение аккаунта

Изменение пароля

Обсуждение: Big difference in time returned by EXPLAIN ANALYZE SELECT ... AND SELECT ...