Thread: Performance analysis of plpgsql code

Performance analysis of plpgsql code

From
"Karl O. Pinc"
Date:
Hi,

I'm having a hard time finding the poorly performing
statements in my plpgsql procedures, many of which
are triggers.  Am I missing something?

I can get the query plans by starting up a new
connection and doing:
SET DEBUG_PRINT_PLAN TO TRUE;
SET CLIENT_MIN_MESSAGES TO DEBUG1;
And then running code that exercises my functions.
Then I can find the queries that, in theory,
could have problems.  But problems remain
after this.

What I'd really like is a SET variable (or maybe
a clause in CREATE FUNCTION) that causes any
functions compiled to issue EXPLAIN ANALYZE output
and the query text itself, to be RAISEd.
Then I could watch the performance as it ran.

Short of that I think I'm going to be reduced to
writing a C function that returns the real
system time so I can spatter my code with
RAISE statements that indicate actual execution
time.

Is there a better approach?
Does anybody have such a C function handy?


Karl <kop@meme.com>
Free Software:  "You don't pay back, you pay forward."
                  -- Robert A. Heinlein


Re: Performance analysis of plpgsql code

From
Michael Fuhr
Date:
On Mon, Jun 27, 2005 at 11:30:45PM +0000, Karl O. Pinc wrote:
>
> Short of that I think I'm going to be reduced to
> writing a C function that returns the real
> system time so I can spatter my code with
> RAISE statements that indicate actual execution
> time.

See timeofday().

http://www.postgresql.org/docs/8.0/static/functions-datetime.html#FUNCTIONS-DATETIME-CURRENT

--
Michael Fuhr
http://www.fuhr.org/~mfuhr/

Re: Performance analysis of plpgsql code

From
"Karl O. Pinc"
Date:
On 06/27/2005 06:33:03 PM, Michael Fuhr wrote:
> On Mon, Jun 27, 2005 at 11:30:45PM +0000, Karl O. Pinc wrote:
> >
> > Short of that I think I'm going to be reduced to
> > writing a C function that returns the real
> > system time so I can spatter my code with
> > RAISE statements that indicate actual execution
> > time.
>
> See timeofday().

That only gives you the time at the start of the transaction,
so you get no indication of how long anything in the
transaction takes.


Karl <kop@meme.com>
Free Software:  "You don't pay back, you pay forward."
                  -- Robert A. Heinlein


Re: Performance analysis of plpgsql code

From
Michael Glaesemann
Date:
On Jun 28, 2005, at 10:54 AM, Karl O. Pinc wrote:

>
> On 06/27/2005 06:33:03 PM, Michael Fuhr wrote:
>
>> On Mon, Jun 27, 2005 at 11:30:45PM +0000, Karl O. Pinc wrote:
>> >
>> > Short of that I think I'm going to be reduced to
>> > writing a C function that returns the real
>> > system time so I can spatter my code with
>> > RAISE statements that indicate actual execution
>> > time.
>> See timeofday().
>>
>
> That only gives you the time at the start of the transaction,
> so you get no indication of how long anything in the
> transaction takes.

I recommend you look again.

<http://www.postgresql.org/docs/8.0/interactive/functions-
datetime.html#FUNCTIONS-DATETIME-CURRENT>

Michael Glaesemann
grzm myrealbox com

Re: Performance analysis of plpgsql code

From
Michael Fuhr
Date:
On Tue, Jun 28, 2005 at 01:54:08AM +0000, Karl O. Pinc wrote:
> On 06/27/2005 06:33:03 PM, Michael Fuhr wrote:
>
> >See timeofday().
>
> That only gives you the time at the start of the transaction,
> so you get no indication of how long anything in the
> transaction takes.

Did you read the documentation or try it?  Perhaps you're thinking
of now(), current_timestamp, and friends, which don't advance during
a transaction; but as the documentation states, "timeofday() returns
the wall-clock time and does advance during transactions."

I just ran tests on versions of PostgreSQL going back to 7.2.8 and
in all of them timeofday() advanced during a transaction.  Does it
not work on your system?  If not then something's broken -- what
OS and version of PostgreSQL are you using?

--
Michael Fuhr
http://www.fuhr.org/~mfuhr/

Re: Performance analysis of plpgsql code

From
"Karl O. Pinc"
Date:
On 06/27/2005 08:34:19 PM, Michael Fuhr wrote:
> On Tue, Jun 28, 2005 at 01:54:08AM +0000, Karl O. Pinc wrote:
> > On 06/27/2005 06:33:03 PM, Michael Fuhr wrote:
> >
> > >See timeofday().
> >
> > That only gives you the time at the start of the transaction,
> > so you get no indication of how long anything in the
> > transaction takes.
>
> Did you read the documentation or try it?  Perhaps you're thinking
> of now(), current_timestamp, and friends, which don't advance during
> a transaction; but as the documentation states, "timeofday() returns
> the wall-clock time and does advance during transactions."

Very sorry.  I did not read through the complete documentation.

> I just ran tests on versions of PostgreSQL going back to 7.2.8 and
> in all of them timeofday() advanced during a transaction.

For all your work a documentation patch is appended that
I think is easier to read and might avoid this problem
in the future.  If you don't read all the way through the
current cvs version then you might think, as I did,
that timeofday() is a CURRENT_TIMESTAMP related function.

Sorry, but 3 lines wrap in the patch
in my email client.  :(


Karl <kop@meme.com>
Free Software:  "You don't pay back, you pay forward."
                  -- Robert A. Heinlein


--- func.sgml    2005-06-26 17:05:35.000000000 -0500
+++ func.sgml.new    2005-06-27 21:51:05.301097896 -0500
@@ -5787,15 +5787,6 @@
     </para>

     <para>
-    There is also the function <function>timeofday()</function>, which
for historical
-    reasons returns a <type>text</type> string rather than a
<type>timestamp</type> value:
-<screen>
-SELECT timeofday();
-<lineannotation>Result: </lineannotation><computeroutput>Sat Feb 17
19:07:32.000126 2001 EST</computeroutput>
-</screen>
-   </para>
-
-   <para>
      It is important to know that
      <function>CURRENT_TIMESTAMP</function> and related functions
return
      the start time of the current transaction; their values do not
@@ -5803,8 +5794,7 @@
      the intent is to allow a single transaction to have a consistent
      notion of the <quote>current</quote> time, so that multiple
      modifications within the same transaction bear the same
-    time stamp. <function>timeofday()</function>
-    returns the wall-clock time and does advance during transactions.
+    time stamp.
     </para>

     <note>
@@ -5815,6 +5805,18 @@
     </note>

     <para>
+    There is also the function <function>timeofday()</function> which
+    returns the wall-clock time and advances during transactions.  For
+    historical reasons <function>timeofday()</function> returns a
+    <type>text</type> string rather than a <type>timestamp</type>
+    value:
+<screen>
+SELECT timeofday();
+<lineannotation>Result: </lineannotation><computeroutput>Sat Feb 17
19:07:32.000126 2001 EST</computeroutput>
+</screen>
+   </para>
+
+   <para>
      All the date/time data types also accept the special literal value
      <literal>now</literal> to specify the current date and time.
Thus,
      the following three all return the same result:


Re: Performance analysis of plpgsql code

From
Michael Fuhr
Date:
On Tue, Jun 28, 2005 at 03:03:06AM +0000, Karl O. Pinc wrote:
>
> For all your work a documentation patch is appended that
> I think is easier to read and might avoid this problem
> in the future.

Patches should go to the pgsql-patches list -- the people who review
and apply patches might not be following this thread.

--
Michael Fuhr
http://www.fuhr.org/~mfuhr/