Обсуждение: 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