Re: getting elapsed query times

Aaron Burnett wrote:

> The first calls a function which essentially calls a handful of views.
>
> psql -d DB1 -c 'select execute_function_foo();'

"calls" a handful of views?

> What I am trying to get is the elapsed time logged for each individual query
> or view that the function calls, as though I entered "\timing" from within
> psql.

Aah, so you want query execution times for individual statements within
a PL/PgSQL function?

I'd expect to be able to use the GET DIAGNOSTICS statement, but
according to the documentation it doesn't support query timings.
Presumably there's a cost to timing statements that you would not
normally want to pay.

You can use `set log_duration = on' to do query duration logging server
side, but that'll still only log the runtime of the whole function.

You might just have to do it yourself. Add a TIMESTAMP WITHOUT TIME ZONE
variable to your function to store the query start time in, eg:

DECLARE
start_time TIMESTAMP WITHOUT TIME ZONE;

Before executing the query, update it with:

start_time := clock_timestamp();

and after the query finishes, log the run time with:

RAISE NOTICE 'Query execution time: %',(clock_timestamp() - start_time);

It's not perfect, in that your logged times include the time taken to
store the start time and to execute the query to log the finish time,
but it's not too bad.

Note that I've used clock_timestamp above, because it gets the real
clock time. current_timestamp, by contrast, will get you the time at the
start of the first statement of the current transaction, which is
usually what you want but not in this case.

> except I need that to show up in the nightly log for each sql statement.

Use 'RAISE NOTICE' from within the PL/PgSQL function.

Alternately, rather than doing everything within PL/PgSQL, just do it
from normal SQL, issued through psql. That way you can just use \timing .

For simple one-liners, instead of:

psql -d DB1 -c 'select execute_function_foo();'

you can write:

psql -d DB1 <<__END__
\timing
select execute_function_foo();
__END__

and in script files much the same applies; just prepend `\timing' to the
script.

--
Craig Ringer