Here is an updated patch. I broke out the statement_timestamp and
statement_timeout handling into separate functions, initialize_command()
and finalize_command(), which call the xact start/stop internally.
This clears up the API because now start/stop xact can be called
independent of the statement tracking operations.
It also makes all commands arriving in a single query string have the
same statement_timestamp (even if in different transactions), and share
the same statement_timeout timer.
I have also documented that statement_timeout is the tracked from the
time the command arrives at the server.
---------------------------------------------------------------------------
Bruce Momjian wrote:
>
> I am not happy with my patch and am going to try a more comprehensive
> restructuring --- will post later.
>
> ---------------------------------------------------------------------------
>
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <[email protected]> writes:
> > > > Tom Lane wrote:
> > > >> The patch as given strikes me as pretty broken --- it does not advance
> > > >> statement_timestamp when I would expect (AFAICS it only sets it during
> > > >> transaction start).
> > >
> > > > Uh, it does advance:
> > >
> > > But not once per statement --- in reality, you get a fairly arbitrary
> > > behavior that will advance in some cases and not others when dealing
> > > with a multi-statement querystring. Your example showing that it fails
> > > to advance in a psql -c string shows this ... don't you think most
> > > people would call that a bug?
> > >
> > > If it's "statement" timestamp then I think it ought to advance once per
> > > SQL statement, which this isn't doing. (As I already said, though, that
> > > isn't the behavior I really want. My point is just that the code's
> > > behavior is an extremely strange, nonintuitive definition of the word
> > > "statement".)
> > >
> > > > I have always been confused if
> > > > statement_timeout times queries inside server-side functions, for
> > > > example. I don't think it should.
> > >
> > > That's exactly my point; I agree that we don't want it doing that,
> > > but that being the case, "statement" isn't a great name for the units
> > > that we are actually processing. We're really wanting to do these
> > > things once per client command, or maybe per client query would be a
> > > better name.
> >
> > I have updated my patch based on community comments. One cleanup is
> > that I now set statement_timestamp(), and then base
> > transaction_timestamp() (aka now()) on the statement_timestamp of BEGIN,
> > which is a much cleaner API.
> >
> > As far as how often statement_timestamp() is called, when a "Q" query
> > arrives, it calls exec_simple_query(), which calls start_xact_command()
> > before it parses anything, setting the transaction start. It is called
> > inside the per-command loop, but it does nothing unless
> > finish_xact_command() was called to finish a transaction.
> >
> > (Is there some double-processing here for BEGIN because it will re-run
> > the initialization stuff?)
> >
> > I also documented how statement_timestamp behaves when multiple
> > statements are in the same query string, and when called from functions.
> >
> > One side-affect of tracking transaction_timestamp based on
> > statement_timestamp() is if multiple statements are sent in a single
> > query string, and multiple transactions are used, statement_timestamp
> > will be advanced so transaction_timestamp() can vary. Again, not ideal,
> > but probably the cleanest we are going to be able to do. If we decided
> > to just have statement_timestamp be the arrival of the string always, we
> > are going to incur additional gettimeofday() calls and the code is going
> > to be more complex.
> >
> > FYI, this is exactly how statement_timeout behaves, and no one has
> > complained about it.
> >
> > The only other approach would be to put the statement_timestamp()
> > setting call in exec_simple_query(), and in all the protocol-level
> > functions, and fastpath. You then also need to do a separate call for
> > transaction_timestamp() because you want that to advance if multiple
> > transactions are in the same query string.
> >
> > If we want to take that approach, should statement_timeout code also be
> > moved around?
> >
> > See my other post about the use of the term "statement". I don't think
> > most people think about sending multiple statements, so if we document
> > its behavior, that is good enough.
> >
--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.55
diff -c -c -r1.55 config.sgml
*** doc/src/sgml/config.sgml 23 Apr 2006 03:39:48 -0000 1.55
--- doc/src/sgml/config.sgml 24 Apr 2006 02:44:03 -0000
***************
*** 3279,3285 ****
<listitem>
<para>
Abort any statement that takes over the specified number of
! milliseconds. If <varname>log_min_error_statement</> is set to
<literal>ERROR</> or lower, the statement that timed out will also be
logged. A value of zero (the default) turns off the
limitation.
--- 3279,3286 ----
<listitem>
<para>
Abort any statement that takes over the specified number of
! milliseconds, starting from the time the command arrives at the server
! from the client. If <varname>log_min_error_statement</> is set to
<literal>ERROR</> or lower, the statement that timed out will also be
logged. A value of zero (the default) turns off the
limitation.
Index: doc/src/sgml/func.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/func.sgml,v
retrieving revision 1.314
diff -c -c -r1.314 func.sgml
*** doc/src/sgml/func.sgml 23 Apr 2006 03:39:50 -0000 1.314
--- doc/src/sgml/func.sgml 24 Apr 2006 02:44:11 -0000
***************
*** 5303,5308 ****
--- 5303,5317 ----
<primary>now</primary>
</indexterm>
<indexterm>
+ <primary>transaction_timestamp</primary>
+ </indexterm>
+ <indexterm>
+ <primary>statement_timestamp</primary>
+ </indexterm>
+ <indexterm>
+ <primary>clock_timestamp</primary>
+ </indexterm>
+ <indexterm>
<primary>timeofday</primary>
</indexterm>
***************
*** 5358,5364 ****
<row>
<entry><literal><function>current_timestamp</function></literal></entry>
<entry><type>timestamp with time zone</type></entry>
! <entry>Date and time; see <xref linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
--- 5367,5373 ----
<row>
<entry><literal><function>current_timestamp</function></literal></entry>
<entry><type>timestamp with time zone</type></entry>
! <entry>Date and time of start of current transaction; see <xref
linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
***************
*** 5474,5481 ****
<row>
<entry><literal><function>now</function>()</literal></entry>
<entry><type>timestamp with time zone</type></entry>
! <entry>Current date and time (equivalent to
! <function>current_timestamp</function>); see <xref
linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
--- 5483,5518 ----
<row>
<entry><literal><function>now</function>()</literal></entry>
<entry><type>timestamp with time zone</type></entry>
! <entry>Date and time of start of current transaction (equivalent to
! <function>CURRENT_TIMESTAMP</function>); see <xref
linkend="functions-datetime-current">
! </entry>
! <entry></entry>
! <entry></entry>
! </row>
!
! <row>
!
<entry><literal><function>transaction_timestamp</function>()</literal></entry>
! <entry><type>timestamp with time zone</type></entry>
! <entry>Date and time of start of current transaction (equivalent to
! <function>CURRENT_TIMESTAMP</function>); see <xref
linkend="functions-datetime-current">
! </entry>
! <entry></entry>
! <entry></entry>
! </row>
!
! <row>
!
<entry><literal><function>statement_timestamp</function>()</literal></entry>
! <entry><type>timestamp with time zone</type></entry>
! <entry>Date and time of start of current statement; see <xref
linkend="functions-datetime-current">
! </entry>
! <entry></entry>
! <entry></entry>
! </row>
!
! <row>
!
<entry><literal><function>clock_timestamp</function>()</literal></entry>
! <entry><type>timestamp with time zone</type></entry>
! <entry>Current date and time (changes during statement execution);
see <xref linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
***************
*** 5484,5490 ****
<row>
<entry><literal><function>timeofday</function>()</literal></entry>
<entry><type>text</type></entry>
! <entry>Current date and time; see <xref
linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
--- 5521,5528 ----
<row>
<entry><literal><function>timeofday</function>()</literal></entry>
<entry><type>text</type></entry>
! <entry>Current date and time (like <function>clock_timestamp</>), but
as a Unix-style <type>text</> value;
! see <xref linkend="functions-datetime-current">
</entry>
<entry></entry>
<entry></entry>
***************
*** 6072,6078 ****
</sect2>
<sect2 id="functions-datetime-current">
! <title>Current Date/Time</title>
<indexterm>
<primary>date</primary>
--- 6110,6116 ----
</sect2>
<sect2 id="functions-datetime-current">
! <title>Date/Time of Transaction Start</title>
<indexterm>
<primary>date</primary>
***************
*** 6085,6092 ****
</indexterm>
<para>
! The following functions are available to obtain the current date and/or
! time:
<synopsis>
CURRENT_DATE
CURRENT_TIME
--- 6123,6130 ----
</indexterm>
<para>
! The following functions are available to obtain the date and/or
! time of the start of the current transaction:
<synopsis>
CURRENT_DATE
CURRENT_TIME
***************
*** 6139,6150 ****
</para>
<para>
- The function <function>now()</function> is the traditional
- <productname>PostgreSQL</productname> equivalent to
- <function>CURRENT_TIMESTAMP</function>.
- </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
--- 6177,6182 ----
***************
*** 6152,6177 ****
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.
</para>
! <note>
! <para>
! Other database systems may advance these values more
! frequently.
! </para>
! </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>
--- 6184,6214 ----
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. Consider using <function>statement_timestamp</> or
! <function>clock_timestamp</> if you need something that changes
! more frequently.
</para>
! <para>
! <function>CURRENT_TIMESTAMP</> might not be the
! transaction start time on other database systems.
! For this reason, and for completeness,
! <function>transaction_timestamp</> is provided.
! The function <function>now()</function> is the traditional
! <productname>PostgreSQL</productname> equivalent to
! the SQL-standard <function>CURRENT_TIMESTAMP</function>.
! </para>
<para>
! <function>STATEMENT_TIMESTAMP</> is the time the statement
! arrived at the server from the client. It is not the time
! the command started execution. If multiple commands were
! sent as a single query string to the server, each command
! has the same <function>STATEMENT_TIMESTAMP</> because they
! all arrived at the same time. Also, commands executed
! by server-side functions have a <function>STATEMENT_TIMESTAMP</>
! based on the time the client sent the query that triggered
! the function, not the time the function was executed.
</para>
<para>
Index: src/backend/access/transam/xact.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/access/transam/xact.c,v
retrieving revision 1.219
diff -c -c -r1.219 xact.c
*** src/backend/access/transam/xact.c 29 Mar 2006 21:17:37 -0000 1.219
--- src/backend/access/transam/xact.c 24 Apr 2006 02:44:13 -0000
***************
*** 172,177 ****
--- 172,178 ----
* keep it inside the TransactionState stack.
*/
static TimestampTz xactStartTimestamp;
+ static TimestampTz stmtStartTimestamp;
/*
* GID to be used for preparing the current transaction. This is also
***************
*** 428,433 ****
--- 429,452 ----
}
/*
+ * GetCurrentStatementStartTimestamp
+ */
+ TimestampTz
+ GetCurrentStatementStartTimestamp(void)
+ {
+ return stmtStartTimestamp;
+ }
+
+ /*
+ * SetCurrentStatementStartTimestamp
+ */
+ void
+ SetCurrentStatementStartTimestamp(void)
+ {
+ stmtStartTimestamp = GetCurrentTimestamp();
+ }
+
+ /*
* GetCurrentTransactionNestLevel
*
* Note: this will return zero when not inside any transaction, one when
***************
*** 1367,1375 ****
XactLockTableInsert(s->transactionId);
/*
! * set now()
*/
! xactStartTimestamp = GetCurrentTimestamp();
/*
* initialize current transaction state fields
--- 1386,1394 ----
XactLockTableInsert(s->transactionId);
/*
! * now() and statement_timestamp() should be the same time
*/
! xactStartTimestamp = stmtStartTimestamp;
/*
* initialize current transaction state fields
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.485
diff -c -c -r1.485 postgres.c
*** src/backend/tcop/postgres.c 22 Apr 2006 01:26:00 -0000 1.485
--- src/backend/tcop/postgres.c 24 Apr 2006 02:44:16 -0000
***************
*** 119,124 ****
--- 119,129 ----
static bool xact_started = false;
/*
+ * Flag to keep track of whether we have done statement initialization.
+ */
+ static bool command_initialized = false;
+
+ /*
* Flag to indicate that we are doing the outer loop's read-from-client,
* as opposed to any random read from client that might happen within
* commands like COPY FROM STDIN.
***************
*** 164,169 ****
--- 169,176 ----
static bool log_after_parse(List *raw_parsetree_list,
const char *query_string, char
**prepare_string);
static List *pg_rewrite_queries(List *querytree_list);
+ static void initialize_command(void);
+ static void finalize_command(void);
static void start_xact_command(void);
static void finish_xact_command(void);
static bool IsTransactionExitStmt(Node *parsetree);
***************
*** 858,864 ****
* one of those, else bad things will happen in xact.c. (Note that this
* will normally change current memory context.)
*/
! start_xact_command();
/*
* Zap any pre-existing unnamed statement. (While not strictly
necessary,
--- 865,871 ----
* one of those, else bad things will happen in xact.c. (Note that this
* will normally change current memory context.)
*/
! initialize_command();
/*
* Zap any pre-existing unnamed statement. (While not strictly
necessary,
***************
*** 1067,1073 ****
/*
* Close down transaction statement, if one is open.
*/
! finish_xact_command();
/*
* If there were no parsetrees, return EmptyQueryResponse message.
--- 1074,1080 ----
/*
* Close down transaction statement, if one is open.
*/
! finalize_command();
/*
* If there were no parsetrees, return EmptyQueryResponse message.
***************
*** 1170,1176 ****
* that this will normally change current memory context.) Nothing
happens
* if we are already in one.
*/
! start_xact_command();
/*
* Switch to appropriate context for constructing parsetrees.
--- 1177,1183 ----
* that this will normally change current memory context.) Nothing
happens
* if we are already in one.
*/
! initialize_command();
/*
* Switch to appropriate context for constructing parsetrees.
***************
*** 1393,1399 ****
* this will normally change current memory context.) Nothing happens if
* we are already in one.
*/
! start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
--- 1400,1406 ----
* this will normally change current memory context.) Nothing happens if
* we are already in one.
*/
! initialize_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
***************
*** 1759,1765 ****
* Ensure we are in a transaction command (this should normally be the
* case already due to prior BIND).
*/
! start_xact_command();
/*
* If we are in aborted transaction state, the only portals we can
--- 1766,1772 ----
* Ensure we are in a transaction command (this should normally be the
* case already due to prior BIND).
*/
! initialize_command();
/*
* If we are in aborted transaction state, the only portals we can
***************
*** 1883,1889 ****
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
! start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
--- 1890,1896 ----
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
! initialize_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
***************
*** 1961,1967 ****
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
! start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
--- 1968,1974 ----
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
! initialize_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
***************
*** 2000,2015 ****
/*
! * Convenience routines for starting/committing a single command.
*/
static void
! start_xact_command(void)
{
! if (!xact_started)
{
! ereport(DEBUG3,
! (errmsg_internal("StartTransactionCommand")));
! StartTransactionCommand();
/* Set statement timeout running, if any */
if (StatementTimeout > 0)
--- 2007,2021 ----
/*
! * Start xact if necessary, and set statement_timestamp() and optionally
! * statement_timeout.
*/
static void
! initialize_command(void)
{
! if (!command_initialized)
{
! SetCurrentStatementStartTimestamp();
/* Set statement timeout running, if any */
if (StatementTimeout > 0)
***************
*** 2017,2035 ****
else
cancel_from_timeout = false;
! xact_started = true;
}
}
static void
! finish_xact_command(void)
{
! if (xact_started)
{
/* Cancel any active statement timeout before committing */
disable_sig_alarm(true);
! /* Now commit the command */
ereport(DEBUG3,
(errmsg_internal("CommitTransactionCommand")));
--- 2023,2070 ----
else
cancel_from_timeout = false;
! command_initialized = true;
}
+ start_xact_command();
}
static void
! finalize_command(void)
{
! if (command_initialized)
{
/* Cancel any active statement timeout before committing */
disable_sig_alarm(true);
! command_initialized = false;
! }
! finish_xact_command();
! }
!
!
! /*
! * Check if the newly-arrived query string needs to have an implicit
! * transaction started.
! */
! static void
! start_xact_command(void)
! {
! if (!xact_started)
! {
! ereport(DEBUG3,
! (errmsg_internal("StartTransactionCommand")));
!
! StartTransactionCommand();
!
! xact_started = true;
! }
! }
!
! static void
! finish_xact_command(void)
! {
! if (xact_started)
! {
ereport(DEBUG3,
(errmsg_internal("CommitTransactionCommand")));
***************
*** 3137,3143 ****
/* We don't have a transaction command open anymore */
xact_started = false;
!
/* Now we can allow interrupts again */
RESUME_INTERRUPTS();
}
--- 3172,3179 ----
/* We don't have a transaction command open anymore */
xact_started = false;
! command_initialized = false;
!
/* Now we can allow interrupts again */
RESUME_INTERRUPTS();
}
***************
*** 3305,3311 ****
pgstat_report_activity("<FASTPATH> function
call");
/* start an xact for this function invocation */
! start_xact_command();
/* switch back to message context */
MemoryContextSwitchTo(MessageContext);
--- 3341,3347 ----
pgstat_report_activity("<FASTPATH> function
call");
/* start an xact for this function invocation */
! initialize_command();
/* switch back to message context */
MemoryContextSwitchTo(MessageContext);
***************
*** 3328,3334 ****
}
/* commit the function-invocation transaction */
! finish_xact_command();
send_ready_for_query = true;
break;
--- 3364,3370 ----
}
/* commit the function-invocation transaction */
! finalize_command();
send_ready_for_query = true;
break;
***************
*** 3416,3422 ****
case 'S': /* sync */
pq_getmsgend(&input_message);
! finish_xact_command();
send_ready_for_query = true;
break;
--- 3452,3458 ----
case 'S': /* sync */
pq_getmsgend(&input_message);
! finalize_command();
send_ready_for_query = true;
break;
Index: src/backend/utils/adt/timestamp.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/adt/timestamp.c,v
retrieving revision 1.162
diff -c -c -r1.162 timestamp.c
*** src/backend/utils/adt/timestamp.c 6 Mar 2006 22:49:16 -0000 1.162
--- src/backend/utils/adt/timestamp.c 24 Apr 2006 02:44:17 -0000
***************
*** 920,925 ****
--- 920,937 ----
}
Datum
+ statement_timestamp(PG_FUNCTION_ARGS)
+ {
+ PG_RETURN_TIMESTAMPTZ(GetCurrentStatementStartTimestamp());
+ }
+
+ Datum
+ clock_timestamp(PG_FUNCTION_ARGS)
+ {
+ PG_RETURN_TIMESTAMPTZ(GetCurrentTimestamp());
+ }
+
+ Datum
pgsql_postmaster_start_time(PG_FUNCTION_ARGS)
{
PG_RETURN_TIMESTAMPTZ(PgStartTime);
Index: src/include/access/xact.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/access/xact.h,v
retrieving revision 1.81
diff -c -c -r1.81 xact.h
*** src/include/access/xact.h 24 Mar 2006 04:32:13 -0000 1.81
--- src/include/access/xact.h 24 Apr 2006 02:44:18 -0000
***************
*** 141,146 ****
--- 141,148 ----
extern SubTransactionId GetCurrentSubTransactionId(void);
extern CommandId GetCurrentCommandId(void);
extern TimestampTz GetCurrentTransactionStartTimestamp(void);
+ extern TimestampTz GetCurrentStatementStartTimestamp(void);
+ extern void SetCurrentStatementStartTimestamp(void);
extern int GetCurrentTransactionNestLevel(void);
extern bool TransactionIdIsCurrentTransactionId(TransactionId xid);
extern void CommandCounterIncrement(void);
Index: src/include/catalog/pg_proc.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/catalog/pg_proc.h,v
retrieving revision 1.405
diff -c -c -r1.405 pg_proc.h
*** src/include/catalog/pg_proc.h 5 Apr 2006 22:11:55 -0000 1.405
--- src/include/catalog/pg_proc.h 24 Apr 2006 02:44:25 -0000
***************
*** 1614,1619 ****
--- 1614,1625 ----
DESCR("convert time with time zone and date to timestamp with time zone");
DATA(insert OID = 1299 ( now PGNSP PGUID 12 f f t f s 0
1184 "" _null_ _null_ _null_ now - _null_ ));
DESCR("current transaction time");
+ DATA(insert OID = 2647 ( transaction_timestamp PGNSP PGUID 12 f f t f
s 0 1184 "" _null_ _null_ _null_ now - _null_ ));
+ DESCR("current transaction time");
+ DATA(insert OID = 2648 ( statement_timestamp PGNSP PGUID 12 f f t f s 0 1184
"" _null_ _null_ _null_ statement_timestamp - _null_ ));
+ DESCR("current statement time");
+ DATA(insert OID = 2649 ( clock_timestamp PGNSP PGUID 12 f f t f v 0 1184
"" _null_ _null_ _null_ clock_timestamp - _null_ ));
+ DESCR("current clock time");
/* OIDS 1300 - 1399 */
Index: src/include/utils/timestamp.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/timestamp.h,v
retrieving revision 1.59
diff -c -c -r1.59 timestamp.h
*** src/include/utils/timestamp.h 6 Mar 2006 22:49:17 -0000 1.59
--- src/include/utils/timestamp.h 24 Apr 2006 02:44:26 -0000
***************
*** 284,289 ****
--- 284,291 ----
extern Datum timestamptz_part(PG_FUNCTION_ARGS);
extern Datum now(PG_FUNCTION_ARGS);
+ extern Datum statement_timestamp(PG_FUNCTION_ARGS);
+ extern Datum clock_timestamp(PG_FUNCTION_ARGS);
extern Datum pgsql_postmaster_start_time(PG_FUNCTION_ARGS);
---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings
