Forum OpenACS Q&A: Measuring Pl/Pgsql performance

I have a complicated Pl/PGsql proc that takes 5 seconds to run and Im looking for a way to measure internal timing so I can figure out what is slow.

I tried doing variations of

v_now := now();
raise notice ''timestamp %'', v_now;

but postgres tells the proc that now() is always the time when it was invoked.

Can anywone suggest a way to measure timing inside of pl/pgsql procs or do I just need to crawl through all the pieces by hand myself?

thanks,

Carl

Collapse
Posted by Don Baccus on
use current_timestamp rather than now()
Collapse
Posted by Rocael Hernández Rizzardini on
you can call your proc from a select and use
explain analyze
or just explain
that could be a way to know
for examples, check this work in progress:
http://www.viaro.net/wimpy/scalability-wp-oacs4x.htm
or the great Jeff's http://xarg.net/writing/tuning/forums-scale
Collapse
Posted by Carl Coryell-Martin on
Hmm, current_timestamp seems to return the same time all the time as well.
Collapse
Posted by Matthew Walker on

It looks like you need timeofday (), see the Postgresql docs down the bottom. Most of the date and time functions do not advance during a transaction.

Collapse
Posted by Don Baccus on
current_timestamp does NOT return the same value each time and it is the documented and prefered way to do this:

create function foo() returns timestamptz as 'begin return current_timestamp; end;' language 'plpgsql';
CREATE FUNCTION
openacs46=# select foo();
              foo
-------------------------------
2003-06-19 00:32:23.515002+00
(1 row)

openacs46=# select foo();
              foo
-------------------------------
2003-06-19 00:32:25.632249+00
(1 row)

openacs46=# select foo();
              foo
-------------------------------
2003-06-19 00:32:31.894221+00
(1 row)

Collapse
Posted by Jonathan Ellis on
hmm, you didn't have a transaction in there. My 7.2.4 install does show it returning the same value:

bf2=# create function foo() returns timestamptz as 'begin return current_timestamp; end;' language 'plpgsql';
CREATE
bf2=# begin transaction;
BEGIN
bf2=# select foo();
              foo
-------------------------------
 2003-06-18 22:48:07.619026-04
(1 row)

bf2=# select current_timestamp;
          timestamptz
-------------------------------
 2003-06-18 22:48:07.619026-04
(1 row)
timeofday() worked perfectly.

dev-mdb=# select load_contact(1317040);
NOTICE:  Start Time 2003-06-19 08:49:46.3277-07
NOTICE:  Loading Contact ID 1317040
NOTICE:  Timestamp 1: 2003-06-19 08:49:46.593492-07
NOTICE:  Adding missing FROM-clause entry for table "acs_object_id_seq"
NOTICE:  Timestamp 2: 2003-06-19 08:49:55.557404-07

...

NOTICE:  Timestamp 11: 2003-06-19 08:50:33.023047-07
NOTICE:  Timestamp 12: 2003-06-19 08:50:33.026157-07
 load_contact 
--------------------
             219817
(1 row)

dev-mdb=# 

Next I need to figure out why creating a person (which happens between timestamp 1 and 2) should take 10 seconds and why the complete insert takes 47 seconds.

Best,

Carl