Thread: Weird waste time when UNION ALL to an empty result set
Based on this article ( http://thenoyes.com/littlenoise/?p=167 ) I was trying to make the same in Pg to see the effects (pg 9.1.1). I found this: postgres=# explain(buffers true, costs true, analyze true ) select i from random_values; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------- Seq Scan on random_values (cost=0.00..16897.00 rows=1000000 width=4) (actual time=0.362..2804.651 rows=1000000 loops=1) Buffers: shared hit=576 read=6321 Total runtime: 5340.656 ms (3 rows) Time: 5342.060 ms postgres=# explain (buffers true, costs true, analyze true ) (select i from random_values) UNION ALL (SELECT NULL LIMIT 0); QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------- Result (cost=0.00..16897.02 rows=1000001 width=4) (actual time=0.203..13160.797 rows=1000000 loops=1) Buffers: shared hit=608 read=6289 -> Append (cost=0.00..16897.02 rows=1000001 width=4) (actual time=0.196..7925.918 rows=1000000 loops=1) Buffers: shared hit=608 read=6289 -> Seq Scan on random_values (cost=0.00..16897.00 rows=1000000 width=4) (actual time=0.190..2852.144 rows=1000000 loops=1) Buffers: shared hit=608 read=6289 -> Limit (cost=0.00..0.01 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=1) -> Result (cost=0.00..0.01 rows=1 width=0) (never executed) Total runtime: 15680.066 ms (9 rows) Time: 15681.999 ms 10 seconds to UNION *nothing*? Is an expected behavior? -- -- Emanuel Calvo Helpame.com
Emanuel Calvo <postgres.arg@gmail.com> writes: > postgres=# explain (buffers true, costs true, analyze true ) (select i > from random_values) UNION ALL (SELECT NULL LIMIT 0); > QUERY PLAN > -------------------------------------------------------------------------------------------------------------------------------------- > Result (cost=0.00..16897.02 rows=1000001 width=4) (actual > time=0.203..13160.797 rows=1000000 loops=1) > Buffers: shared hit=608 read=6289 > -> Append (cost=0.00..16897.02 rows=1000001 width=4) (actual > time=0.196..7925.918 rows=1000000 loops=1) > Buffers: shared hit=608 read=6289 > -> Seq Scan on random_values (cost=0.00..16897.00 > rows=1000000 width=4) (actual time=0.190..2852.144 rows=1000000 > loops=1) > Buffers: shared hit=608 read=6289 > -> Limit (cost=0.00..0.01 rows=1 width=0) (actual > time=0.007..0.007 rows=0 loops=1) > -> Result (cost=0.00..0.01 rows=1 width=0) (never executed) > Total runtime: 15680.066 ms > (9 rows) > 10 seconds to UNION *nothing*? Is an expected behavior? I'm inclined to read this result as showing that EXPLAIN ANALYZE has very high per-node overhead on your machine. That is not too uncommon on machines that don't have any way to read the clock without a kernel call. You might try comparing straight execution times (without using EXPLAIN) to get a clearer idea of how much it costs to pass data through Append/Result. (It's not free, no.) regards, tom lane
2011/11/10 Tom Lane <tgl@sss.pgh.pa.us>: > Emanuel Calvo <postgres.arg@gmail.com> writes: >> postgres=# explain (buffers true, costs true, analyze true ) (select i >> from random_values) UNION ALL (SELECT NULL LIMIT 0); >> QUERY PLAN >> -------------------------------------------------------------------------------------------------------------------------------------- >> Result (cost=0.00..16897.02 rows=1000001 width=4) (actual >> time=0.203..13160.797 rows=1000000 loops=1) >> Buffers: shared hit=608 read=6289 >> -> Append (cost=0.00..16897.02 rows=1000001 width=4) (actual >> time=0.196..7925.918 rows=1000000 loops=1) >> Buffers: shared hit=608 read=6289 >> -> Seq Scan on random_values (cost=0.00..16897.00 >> rows=1000000 width=4) (actual time=0.190..2852.144 rows=1000000 >> loops=1) >> Buffers: shared hit=608 read=6289 >> -> Limit (cost=0.00..0.01 rows=1 width=0) (actual >> time=0.007..0.007 rows=0 loops=1) >> -> Result (cost=0.00..0.01 rows=1 width=0) (never executed) >> Total runtime: 15680.066 ms >> (9 rows) > >> 10 seconds to UNION *nothing*? Is an expected behavior? > > I'm inclined to read this result as showing that EXPLAIN ANALYZE has > very high per-node overhead on your machine. That is not too uncommon > on machines that don't have any way to read the clock without a kernel > call. You might try comparing straight execution times (without > using EXPLAIN) to get a clearer idea of how much it costs to pass data > through Append/Result. (It's not free, no.) > Well, you are right. I'd executed without explain and the timing is not highly different. Thanks for the "EXPLAIN" ! -- -- Emanuel Calvo Helpame.com