Markus Bertheau â wrote:
Hi, I have the following strange situation:
...
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.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 (ÐÐÐÐÑÐÐ: 4)
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 loops=1) Total runtime: 27.062 ms (ÐÐÐÐÑÐÐ: 2)
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:
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.
John =:->
signature.asc
Description: OpenPGP digital signature