Performance analysis of plpgsql code
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
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/
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
Import Notes
Reply to msg id not found: 1119923648l.11411l.0l@mofo
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/
Import Notes
Reply to msg id not found: 1119923648l.11411l.0l@mofo
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
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/
Import Notes
Reply to msg id not found: 1119927786l.11411l.3l@mofo
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:On 06/27/2005 10:03:06 PM, Karl O. Pinc wrote:
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:---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster
Karl <kop@meme.com>
Free Software: "You don't pay back, you pay forward."
-- Robert A. Heinlein
Patch applied. Thanks. Your documentation changes can be viewed in
five minutes using links on the developer's page,
http://www.postgresql.org/developer/testing.
---------------------------------------------------------------------------
Karl O. Pinc wrote:
On 06/27/2005 10:03:06 PM, Karl O. Pinc wrote:
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:---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmasterKarl <kop@meme.com>
Free Software: "You don't pay back, you pay forward."
-- Robert A. Heinlein---------------------------(end of broadcast)---------------------------
TIP 7: don't forget to increase your free space map settings
--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073