Forum OpenACS Q&A: Measuring Pl/Pgsql performance

Posted by Carl Coryell-Martin on 06/14/03 01:36 AM

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

2: Re: Measuring Pl/Pgsql performance (response to 1)

Posted by Don Baccus on 06/14/03 04:01 PM

use current_timestamp rather than now()

3: Re: Measuring Pl/Pgsql performance (response to 1)

Posted by Rocael Hernández Rizzardini on 06/14/03 05:20 PM

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

4: Re: Measuring Pl/Pgsql performance (response to 1)

Posted by Carl Coryell-Martin on 06/17/03 01:08 AM

Hmm, current_timestamp seems to return the same time all the time as well.

5: Re: Measuring Pl/Pgsql performance (response to 4)

Posted by Matthew Walker on 06/17/03 02:54 PM

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.

6: Re: Measuring Pl/Pgsql performance (response to 1)

Posted by Don Baccus on 06/19/03 02:27 AM

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)

7: Re: Measuring Pl/Pgsql performance (response to 1)

Posted by Jonathan Ellis on 06/19/03 04:58 AM

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)

8: Re: Measuring Pl/Pgsql performance: timeofday() is it. (response to 1)

Posted by Carl Coryell-Martin on 06/19/03 05:55 PM

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