Markus Bertheau â wrote:

Hi, I have the following strange situation:


oocms=# explain analyze select count(1) from objects where class = 'Picture';
                                                  QUERY PLAN
Aggregate  (cost=278.16..278.16 rows=1 width=0) (actual time=44.121..44.123 
rows=1 loops=1)
  ->  Seq Scan on objects  (cost=0.00..267.65 rows=4205 width=0) (actual 
time=0.030..33.325 rows=4308 loops=1)
        Filter: ("class" = 'Picture'::text)
Total runtime: 44.211 ms

oocms=# explain analyze select class_get_number_of_objects('Picture');
                                     QUERY PLAN
Result  (cost=0.00..0.01 rows=1 width=0) (actual time=27.019..27.022 rows=1 
Total runtime: 27.062 ms

I.e. a function takes 27 ms to do what takes an equivalent piece of sql 43 ms. How can this be explained?

Some more info:

In explain analyze, there is a per-row overhead of 2 gettimeofday() calls. This is usually very low and hidden in I/O, but on queries where you go through a lot of rows, but things are cached in ram, it can show up.
So the explain analyze is going deep into the SQL query.
With a stored procedure, explain analyze only runs the procedure, it doesn't instrument the actual function. So you don't have that per-row overhead.

For an alternate accurate view. Try:
# \timing
# explain analyze select count(1) from objects where class = 'Picture';
# explain analyze select class_get_number_of_objects('Picture');

\timing will also give you the time it takes to run the query, but it doesn't instrument anything.


Attachment: signature.asc
Description: OpenPGP digital signature

Reply via email to