From 27c3e3de0939d93ae8adb50ab7e00c4a5ff2fa0d Mon Sep 17 00:00:00 2001
From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Tue, 20 Jun 2006 22:52:00 +0000
Subject: [PATCH] Remove redundant gettimeofday() calls to the extent practical
without changing semantics too much. statement_timestamp is now set
immediately upon receipt of a client command message, and the various places
that used to do their own gettimeofday() calls to mark command startup are
referenced to that instead. I have also made stats_command_string use that
same value for pg_stat_activity.query_start for both the command itself and
its eventual replacement by <IDLE> or <idle in transaction>. There was some
debate about that, but no argument that seemed convincing enough to justify
an extra gettimeofday() call.
---
src/backend/access/transam/xact.c | 13 +-
src/backend/commands/prepare.c | 4 +-
src/backend/postmaster/pgstat.c | 12 +-
src/backend/postmaster/postmaster.c | 14 +-
src/backend/storage/lmgr/proc.c | 73 +++----
src/backend/tcop/postgres.c | 287 ++++++++++++----------------
src/backend/utils/adt/timestamp.c | 56 +++++-
src/backend/utils/error/elog.c | 9 +-
src/backend/utils/mmgr/portalmem.c | 4 +-
src/include/libpq/libpq-be.h | 9 +-
src/include/utils/timestamp.h | 12 +-
11 files changed, 268 insertions(+), 225 deletions(-)
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index b59cea044b9..3716a85dfb2 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -10,7 +10,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.220 2006/04/25 00:25:17 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.221 2006/06/20 22:51:59 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -167,9 +167,10 @@ static SubTransactionId currentSubTransactionId;
static CommandId currentCommandId;
/*
- * This is the value of now(), ie, the transaction start time.
- * This does not change as we enter and exit subtransactions, so we don't
- * keep it inside the TransactionState stack.
+ * xactStartTimestamp is the value of transaction_timestamp().
+ * stmtStartTimestamp is the value of statement_timestamp().
+ * These do not change as we enter and exit subtransactions, so we don't
+ * keep them inside the TransactionState stack.
*/
static TimestampTz xactStartTimestamp;
static TimestampTz stmtStartTimestamp;
@@ -1386,7 +1387,9 @@ StartTransaction(void)
XactLockTableInsert(s->transactionId);
/*
- * now() and statement_timestamp() should be the same time
+ * set transaction_timestamp() (a/k/a now()). We want this to be the
+ * same as the first command's statement_timestamp(), so don't do a
+ * fresh GetCurrentTimestamp() call (which'd be expensive anyway).
*/
xactStartTimestamp = stmtStartTimestamp;
diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 3c77e8a70fe..d89c01a62e5 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -10,7 +10,7 @@
* Copyright (c) 2002-2006, PostgreSQL Global Development Group
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.52 2006/04/25 14:11:54 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.53 2006/06/20 22:51:59 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -373,7 +373,7 @@ StorePreparedStatement(const char *stmt_name,
entry->plan_list = plan_list;
entry->argtype_list = argtype_list;
entry->context = entrycxt;
- entry->prepare_time = GetCurrentTimestamp();
+ entry->prepare_time = GetCurrentStatementStartTimestamp();
entry->from_sql = from_sql;
MemoryContextSwitchTo(oldcxt);
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index f6949f14377..a340a91fed2 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -13,7 +13,7 @@
*
* Copyright (c) 2001-2006, PostgreSQL Global Development Group
*
- * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.129 2006/06/19 01:51:21 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.130 2006/06/20 22:52:00 tgl Exp $
* ----------
*/
#include "postgres.h"
@@ -1368,8 +1368,14 @@ pgstat_bestart(void)
/*
* To minimize the time spent modifying the entry, fetch all the
* needed data first.
+ *
+ * If we have a MyProcPort, use its session start time (for consistency,
+ * and to save a kernel call).
*/
- proc_start_timestamp = GetCurrentTimestamp();
+ if (MyProcPort)
+ proc_start_timestamp = MyProcPort->SessionStartTime;
+ else
+ proc_start_timestamp = GetCurrentTimestamp();
userid = GetSessionUserId();
/*
@@ -1464,7 +1470,7 @@ pgstat_report_activity(const char *cmd_str)
* To minimize the time spent modifying the entry, fetch all the
* needed data first.
*/
- start_timestamp = GetCurrentTimestamp();
+ start_timestamp = GetCurrentStatementStartTimestamp();
len = strlen(cmd_str);
len = pg_mbcliplen(cmd_str, len, PGBE_ACTIVITY_SIZE - 1);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index aac116b466a..8164d7e5b03 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -37,7 +37,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.487 2006/06/19 01:51:21 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.488 2006/06/20 22:52:00 tgl Exp $
*
* NOTES
*
@@ -99,7 +99,6 @@
#include "commands/async.h"
#include "lib/dllist.h"
#include "libpq/auth.h"
-#include "libpq/crypt.h"
#include "libpq/libpq.h"
#include "libpq/pqcomm.h"
#include "libpq/pqsignal.h"
@@ -2609,8 +2608,9 @@ BackendInitialize(Port *port)
ClientAuthInProgress = true; /* limit visibility of log messages */
- /* save start time for end of session reporting */
- gettimeofday(&(port->session_start), NULL);
+ /* save process start time */
+ port->SessionStartTime = GetCurrentTimestamp();
+ port->session_start = timestamptz_to_time_t(port->SessionStartTime);
/* set these to empty in case they are needed before we set them up */
port->remote_host = "";
@@ -2749,6 +2749,8 @@ BackendRun(Port *port)
char **av;
int maxac;
int ac;
+ long secs;
+ int usecs;
char protobuf[32];
int i;
@@ -2758,7 +2760,9 @@ BackendRun(Port *port)
* a new random sequence in the random() library function.
*/
random_seed = 0;
- srandom((unsigned int) (MyProcPid ^ port->session_start.tv_usec));
+ /* slightly hacky way to get integer microseconds part of timestamptz */
+ TimestampDifference(0, port->SessionStartTime, &secs, &usecs);
+ srandom((unsigned int) (MyProcPid ^ usecs));
/* ----------------
* Now, build the argv vector that will be given to PostgresMain.
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 92e870d99ae..6b74c54d5ab 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.174 2006/04/14 03:38:55 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.175 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -42,6 +42,7 @@
#include "storage/proc.h"
#include "storage/procarray.h"
#include "storage/spin.h"
+#include "utils/timestamp.h"
/* GUC variables */
@@ -73,7 +74,7 @@ static volatile bool deadlock_timeout_active = false;
volatile bool cancel_from_timeout = false;
/* statement_fin_time is valid only if statement_timeout_active is true */
-static struct timeval statement_fin_time;
+static TimestampTz statement_fin_time;
static void RemoveProcFromArray(int code, Datum arg);
@@ -1105,29 +1106,32 @@ ProcSendSignal(int pid)
bool
enable_sig_alarm(int delayms, bool is_statement_timeout)
{
- struct timeval fin_time;
+ TimestampTz fin_time;
struct itimerval timeval;
- /* Compute target timeout time if we will need it */
- if (is_statement_timeout || statement_timeout_active)
- {
- gettimeofday(&fin_time, NULL);
- fin_time.tv_sec += delayms / 1000;
- fin_time.tv_usec += (delayms % 1000) * 1000;
- if (fin_time.tv_usec >= 1000000)
- {
- fin_time.tv_sec++;
- fin_time.tv_usec -= 1000000;
- }
- }
-
if (is_statement_timeout)
{
- /* Begin statement-level timeout */
+ /*
+ * Begin statement-level timeout
+ *
+ * Note that we compute statement_fin_time with reference to the
+ * statement_timestamp, but apply the specified delay without any
+ * correction; that is, we ignore whatever time has elapsed since
+ * statement_timestamp was set. In the normal case only a small
+ * interval will have elapsed and so this doesn't matter, but there
+ * are corner cases (involving multi-statement query strings with
+ * embedded COMMIT or ROLLBACK) where we might re-initialize the
+ * statement timeout long after initial receipt of the message.
+ * In such cases the enforcement of the statement timeout will be
+ * a bit inconsistent. This annoyance is judged not worth the cost
+ * of performing an additional gettimeofday() here.
+ */
Assert(!deadlock_timeout_active);
+ fin_time = GetCurrentStatementStartTimestamp();
+ fin_time = TimestampTzPlusMilliseconds(fin_time, delayms);
statement_fin_time = fin_time;
- statement_timeout_active = true;
cancel_from_timeout = false;
+ statement_timeout_active = true;
}
else if (statement_timeout_active)
{
@@ -1145,10 +1149,10 @@ enable_sig_alarm(int delayms, bool is_statement_timeout)
* to the state variables. The deadlock checker may get run earlier
* than normal, but that does no harm.
*/
+ fin_time = GetCurrentTimestamp();
+ fin_time = TimestampTzPlusMilliseconds(fin_time, delayms);
deadlock_timeout_active = true;
- if (fin_time.tv_sec > statement_fin_time.tv_sec ||
- (fin_time.tv_sec == statement_fin_time.tv_sec &&
- fin_time.tv_usec >= statement_fin_time.tv_usec))
+ if (fin_time >= statement_fin_time)
return true;
}
else
@@ -1225,16 +1229,14 @@ disable_sig_alarm(bool is_statement_timeout)
static bool
CheckStatementTimeout(void)
{
- struct timeval now;
+ TimestampTz now;
if (!statement_timeout_active)
return true; /* do nothing if not active */
- gettimeofday(&now, NULL);
+ now = GetCurrentTimestamp();
- if (now.tv_sec > statement_fin_time.tv_sec ||
- (now.tv_sec == statement_fin_time.tv_sec &&
- now.tv_usec >= statement_fin_time.tv_usec))
+ if (now >= statement_fin_time)
{
/* Time to die */
statement_timeout_active = false;
@@ -1244,16 +1246,21 @@ CheckStatementTimeout(void)
else
{
/* Not time yet, so (re)schedule the interrupt */
+ long secs;
+ int usecs;
struct itimerval timeval;
+ TimestampDifference(now, statement_fin_time,
+ &secs, &usecs);
+ /*
+ * It's possible that the difference is less than a microsecond;
+ * ensure we don't cancel, rather than set, the interrupt.
+ */
+ if (secs == 0 && usecs == 0)
+ usecs = 1;
MemSet(&timeval, 0, sizeof(struct itimerval));
- timeval.it_value.tv_sec = statement_fin_time.tv_sec - now.tv_sec;
- timeval.it_value.tv_usec = statement_fin_time.tv_usec - now.tv_usec;
- if (timeval.it_value.tv_usec < 0)
- {
- timeval.it_value.tv_sec--;
- timeval.it_value.tv_usec += 1000000;
- }
+ timeval.it_value.tv_sec = secs;
+ timeval.it_value.tv_usec = usecs;
if (setitimer(ITIMER_REAL, &timeval, NULL))
return false;
}
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index b7c363d80cd..227498d1f67 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.488 2006/06/18 15:38:37 petere Exp $
+ * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.489 2006/06/20 22:52:00 tgl Exp $
*
* NOTES
* this is the "main" module of the postgres backend and
@@ -118,12 +118,6 @@ static volatile sig_atomic_t got_SIGHUP = false;
*/
static bool xact_started = false;
-/*
- * Flag to keep track of whether we have done statement initialization.
- * For extended query protocol this has to be remembered across messages.
- */
-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
@@ -170,8 +164,6 @@ static int ReadCommand(StringInfo inBuf);
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);
@@ -832,10 +824,6 @@ exec_simple_query(const char *query_string)
MemoryContext oldcontext;
List *parsetree_list;
ListCell *parsetree_item;
- struct timeval start_t,
- stop_t;
- bool save_log_duration = log_duration;
- int save_log_min_duration_statement = log_min_duration_statement;
bool save_log_statement_stats = log_statement_stats;
char *prepare_string = NULL;
bool was_logged = false;
@@ -848,14 +836,9 @@ exec_simple_query(const char *query_string)
pgstat_report_activity(query_string);
/*
- * We use save_log_* so "SET log_duration = true" and "SET
- * log_min_duration_statement = true" don't report incorrect time because
- * gettimeofday() wasn't called. Similarly, log_statement_stats has to be
- * captured once.
+ * We use save_log_statement_stats so ShowUsage doesn't report incorrect
+ * results because ResetUsage wasn't called.
*/
- if (save_log_duration || save_log_min_duration_statement != -1)
- gettimeofday(&start_t, NULL);
-
if (save_log_statement_stats)
ResetUsage();
@@ -866,7 +849,7 @@ exec_simple_query(const char *query_string)
* one of those, else bad things will happen in xact.c. (Note that this
* will normally change current memory context.)
*/
- initialize_command();
+ start_xact_command();
/*
* Zap any pre-existing unnamed statement. (While not strictly necessary,
@@ -895,7 +878,8 @@ exec_simple_query(const char *query_string)
*/
parsetree_list = pg_parse_query(query_string);
- if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1)
+ /* Log immediately if dictated by log_statement */
+ if (log_statement != LOGSTMT_NONE)
was_logged = log_after_parse(parsetree_list, query_string,
&prepare_string);
@@ -1075,7 +1059,7 @@ exec_simple_query(const char *query_string)
/*
* Close down transaction statement, if one is open.
*/
- finalize_command();
+ finish_xact_command();
/*
* If there were no parsetrees, return EmptyQueryResponse message.
@@ -1086,44 +1070,42 @@ exec_simple_query(const char *query_string)
QueryContext = NULL;
/*
- * Combine processing here as we need to calculate the query duration in
- * both instances.
+ * Emit duration logging if appropriate.
*/
- if (save_log_duration || save_log_min_duration_statement != -1)
+ if (log_duration || log_min_duration_statement >= 0)
{
- long usecs;
+ long secs;
+ int usecs;
+ int msecs;
- gettimeofday(&stop_t, NULL);
- if (stop_t.tv_usec < start_t.tv_usec)
- {
- stop_t.tv_sec--;
- stop_t.tv_usec += 1000000;
- }
- usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
- (long) (stop_t.tv_usec - start_t.tv_usec);
-
- /* Only print duration if we previously printed the statement. */
- if (was_logged && save_log_duration)
- ereport(LOG,
- (errmsg("duration: %ld.%03ld ms",
- (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
- (stop_t.tv_usec - start_t.tv_usec) / 1000),
- (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+ TimestampDifference(GetCurrentStatementStartTimestamp(),
+ GetCurrentTimestamp(),
+ &secs, &usecs);
+ msecs = usecs / 1000;
/*
- * Output a duration_statement to the log if the query has exceeded
- * the min duration, or if we are to print all durations.
+ * The odd-looking test for log_min_duration_statement being
+ * exceeded is designed to avoid integer overflow with very
+ * long durations: don't compute secs * 1000 until we've
+ * verified it will fit in int.
*/
- if (save_log_min_duration_statement == 0 ||
- (save_log_min_duration_statement > 0 &&
- usecs >= save_log_min_duration_statement * 1000))
- ereport(LOG,
- (errmsg("duration: %ld.%03ld ms statement: %s%s",
- (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
- (stop_t.tv_usec - start_t.tv_usec) / 1000),
- (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
- query_string,
- prepare_string ? prepare_string : "")));
+ if (log_duration ||
+ log_min_duration_statement == 0 ||
+ (log_min_duration_statement > 0 &&
+ (secs > log_min_duration_statement / 1000 ||
+ secs * 1000 + msecs >= log_min_duration_statement)))
+ {
+ if (was_logged)
+ ereport(LOG,
+ (errmsg("duration: %ld.%03d ms",
+ secs, msecs)));
+ else
+ ereport(LOG,
+ (errmsg("duration: %ld.%03d ms statement: %s%s",
+ secs, msecs,
+ query_string,
+ prepare_string ? prepare_string : "")));
+ }
}
if (save_log_statement_stats)
@@ -1178,7 +1160,7 @@ exec_parse_message(const char *query_string, /* string to execute */
* that this will normally change current memory context.) Nothing happens
* if we are already in one.
*/
- initialize_command();
+ start_xact_command();
/*
* Switch to appropriate context for constructing parsetrees.
@@ -1401,7 +1383,7 @@ exec_bind_message(StringInfo input_message)
* this will normally change current memory context.) Nothing happens if
* we are already in one.
*/
- initialize_command();
+ start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
@@ -1678,10 +1660,6 @@ exec_execute_message(const char *portal_name, long max_rows)
Portal portal;
bool completed;
char completionTag[COMPLETION_TAG_BUFSIZE];
- struct timeval start_t,
- stop_t;
- bool save_log_duration = log_duration;
- int save_log_min_duration_statement = log_min_duration_statement;
bool save_log_statement_stats = log_statement_stats;
bool execute_is_fetch = false;
@@ -1736,14 +1714,9 @@ exec_execute_message(const char *portal_name, long max_rows)
set_ps_display(portal->commandTag);
/*
- * We use save_log_* so "SET log_duration = true" and "SET
- * log_min_duration_statement = true" don't report incorrect time because
- * gettimeofday() wasn't called. Similarly, log_statement_stats has to be
- * captured once.
+ * We use save_log_statement_stats so ShowUsage doesn't report incorrect
+ * results because ResetUsage wasn't called.
*/
- if (save_log_duration || save_log_min_duration_statement != -1)
- gettimeofday(&start_t, NULL);
-
if (save_log_statement_stats)
ResetUsage();
@@ -1751,8 +1724,8 @@ exec_execute_message(const char *portal_name, long max_rows)
/* We have the portal, so output the source query. */
ereport(LOG,
(errmsg("statement: [protocol] %sEXECUTE %s [PREPARE: %s]",
- (execute_is_fetch) ? "FETCH from " : "",
- (*portal_name != '\0') ? portal_name : "<unnamed>",
+ execute_is_fetch ? "FETCH from " : "",
+ (*portal_name) ? portal_name : "<unnamed>",
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
@@ -1767,7 +1740,7 @@ exec_execute_message(const char *portal_name, long max_rows)
* Ensure we are in a transaction command (this should normally be the
* case already due to prior BIND).
*/
- initialize_command();
+ start_xact_command();
/*
* If we are in aborted transaction state, the only portals we can
@@ -1827,45 +1800,43 @@ exec_execute_message(const char *portal_name, long max_rows)
}
/*
- * Combine processing here as we need to calculate the query duration in
- * both instances.
+ * Emit duration logging if appropriate.
*/
- if (save_log_duration || save_log_min_duration_statement != -1)
+ if (log_duration || log_min_duration_statement >= 0)
{
- long usecs;
+ long secs;
+ int usecs;
+ int msecs;
- gettimeofday(&stop_t, NULL);
- if (stop_t.tv_usec < start_t.tv_usec)
- {
- stop_t.tv_sec--;
- stop_t.tv_usec += 1000000;
- }
- usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
- (long) (stop_t.tv_usec - start_t.tv_usec);
-
- /* Only print duration if we previously printed the statement. */
- if (log_statement == LOGSTMT_ALL && save_log_duration)
- ereport(LOG,
- (errmsg("duration: %ld.%03ld ms",
- (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
- (stop_t.tv_usec - start_t.tv_usec) / 1000),
- (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+ TimestampDifference(GetCurrentStatementStartTimestamp(),
+ GetCurrentTimestamp(),
+ &secs, &usecs);
+ msecs = usecs / 1000;
/*
- * Output a duration_statement to the log if the query has exceeded
- * the min duration, or if we are to print all durations.
+ * The odd-looking test for log_min_duration_statement being
+ * exceeded is designed to avoid integer overflow with very
+ * long durations: don't compute secs * 1000 until we've
+ * verified it will fit in int.
*/
- if (save_log_min_duration_statement == 0 ||
- (save_log_min_duration_statement > 0 &&
- usecs >= save_log_min_duration_statement * 1000))
- ereport(LOG,
- (errmsg("duration: %ld.%03ld ms statement: [protocol] %sEXECUTE %s [PREPARE: %s]",
- (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
- (stop_t.tv_usec - start_t.tv_usec) / 1000),
- (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
- (execute_is_fetch) ? "FETCH from " : "",
- (*portal_name != '\0') ? portal_name : "<unnamed>",
+ if (log_duration ||
+ log_min_duration_statement == 0 ||
+ (log_min_duration_statement > 0 &&
+ (secs > log_min_duration_statement / 1000 ||
+ secs * 1000 + msecs >= log_min_duration_statement)))
+ {
+ if (log_statement == LOGSTMT_ALL) /* already logged? */
+ ereport(LOG,
+ (errmsg("duration: %ld.%03d ms",
+ secs, msecs)));
+ else
+ ereport(LOG,
+ (errmsg("duration: %ld.%03d ms statement: [protocol] %sEXECUTE %s [PREPARE: %s]",
+ secs, msecs,
+ execute_is_fetch ? "FETCH from " : "",
+ (*portal_name) ? portal_name : "<unnamed>",
portal->sourceText ? portal->sourceText : "")));
+ }
}
if (save_log_statement_stats)
@@ -1891,7 +1862,7 @@ exec_describe_statement_message(const char *stmt_name)
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
- initialize_command();
+ start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
@@ -1969,7 +1940,7 @@ exec_describe_portal_message(const char *portal_name)
* Start up a transaction command. (Note that this will normally change
* current memory context.) Nothing happens if we are already in one.
*/
- initialize_command();
+ start_xact_command();
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
@@ -2008,55 +1979,24 @@ exec_describe_portal_message(const char *portal_name)
/*
- * Start xact if necessary, and set statement_timestamp() and optionally
- * statement_timeout.
+ * Convenience routines for starting/committing a single command.
*/
static void
-initialize_command(void)
+start_xact_command(void)
{
- if (!command_initialized)
+ if (!xact_started)
{
- SetCurrentStatementStartTimestamp();
+ ereport(DEBUG3,
+ (errmsg_internal("StartTransactionCommand")));
+ StartTransactionCommand();
/* Set statement timeout running, if any */
+ /* NB: this mustn't be enabled until we are within an xact */
if (StatementTimeout > 0)
enable_sig_alarm(StatementTimeout, true);
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;
}
}
@@ -2066,6 +2006,10 @@ 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")));
@@ -3127,8 +3071,7 @@ PostgresMain(int argc, char *argv[], const char *username)
/* We don't have a transaction command open anymore */
xact_started = false;
- command_initialized = false;
-
+
/* Now we can allow interrupts again */
RESUME_INTERRUPTS();
}
@@ -3235,6 +3178,9 @@ PostgresMain(int argc, char *argv[], const char *username)
{
const char *query_string;
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
+
query_string = pq_getmsgstring(&input_message);
pq_getmsgend(&input_message);
@@ -3251,6 +3197,9 @@ PostgresMain(int argc, char *argv[], const char *username)
int numParams;
Oid *paramTypes = NULL;
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
+
stmt_name = pq_getmsgstring(&input_message);
query_string = pq_getmsgstring(&input_message);
numParams = pq_getmsgint(&input_message, 2);
@@ -3270,6 +3219,8 @@ PostgresMain(int argc, char *argv[], const char *username)
break;
case 'B': /* bind */
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
/*
* this message is complex enough that it seems best to put
@@ -3283,6 +3234,9 @@ PostgresMain(int argc, char *argv[], const char *username)
const char *portal_name;
int max_rows;
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
+
portal_name = pq_getmsgstring(&input_message);
max_rows = pq_getmsgint(&input_message, 4);
pq_getmsgend(&input_message);
@@ -3292,11 +3246,14 @@ PostgresMain(int argc, char *argv[], const char *username)
break;
case 'F': /* fastpath function call */
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
+
/* Tell the collector what we're doing */
pgstat_report_activity("<FASTPATH> function call");
/* start an xact for this function invocation */
- initialize_command();
+ start_xact_command();
/*
* Note: we may at this point be inside an aborted
@@ -3325,7 +3282,7 @@ PostgresMain(int argc, char *argv[], const char *username)
}
/* commit the function-invocation transaction */
- finalize_command();
+ finish_xact_command();
send_ready_for_query = true;
break;
@@ -3383,6 +3340,9 @@ PostgresMain(int argc, char *argv[], const char *username)
int describe_type;
const char *describe_target;
+ /* Set statement_timestamp() (needed for xact) */
+ SetCurrentStatementStartTimestamp();
+
describe_type = pq_getmsgbyte(&input_message);
describe_target = pq_getmsgstring(&input_message);
pq_getmsgend(&input_message);
@@ -3413,7 +3373,7 @@ PostgresMain(int argc, char *argv[], const char *username)
case 'S': /* sync */
pq_getmsgend(&input_message);
- finalize_command();
+ finish_xact_command();
send_ready_for_query = true;
break;
@@ -3588,30 +3548,27 @@ static void
log_disconnections(int code, Datum arg)
{
Port *port = MyProcPort;
- struct timeval end;
+ long secs;
+ int usecs;
+ int msecs;
int hours,
minutes,
seconds;
- gettimeofday(&end, NULL);
- if (end.tv_usec < port->session_start.tv_usec)
- {
- end.tv_sec--;
- end.tv_usec += 1000000;
- }
- end.tv_sec -= port->session_start.tv_sec;
- end.tv_usec -= port->session_start.tv_usec;
+ TimestampDifference(port->SessionStartTime,
+ GetCurrentTimestamp(),
+ &secs, &usecs);
+ msecs = usecs / 1000;
- /* for stricter accuracy here we could round - this is close enough */
- hours = end.tv_sec / SECS_PER_HOUR;
- end.tv_sec %= SECS_PER_HOUR;
- minutes = end.tv_sec / SECS_PER_MINUTE;
- seconds = end.tv_sec % SECS_PER_MINUTE;
+ hours = secs / SECS_PER_HOUR;
+ secs %= SECS_PER_HOUR;
+ minutes = secs / SECS_PER_MINUTE;
+ seconds = secs % SECS_PER_MINUTE;
ereport(LOG,
- (errmsg("disconnection: session time: %d:%02d:%02d.%02d "
+ (errmsg("disconnection: session time: %d:%02d:%02d.%03d "
"user=%s database=%s host=%s%s%s",
- hours, minutes, seconds, (int) (end.tv_usec / 10000),
+ hours, minutes, seconds, msecs,
port->user_name, port->database_name, port->remote_host,
- port->remote_port[0] ? " port=" : "", port->remote_port)));
+ port->remote_port[0] ? " port=" : "", port->remote_port)));
}
diff --git a/src/backend/utils/adt/timestamp.c b/src/backend/utils/adt/timestamp.c
index fd40c1ebfdd..f4f23c9dd31 100644
--- a/src/backend/utils/adt/timestamp.c
+++ b/src/backend/utils/adt/timestamp.c
@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.163 2006/04/25 00:25:18 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.164 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -963,6 +963,39 @@ GetCurrentTimestamp(void)
return result;
}
+/*
+ * TimestampDifference -- convert the difference between two timestamps
+ * into integer seconds and microseconds
+ *
+ * Both inputs must be ordinary finite timestamps (in current usage,
+ * they'll be results from GetCurrentTimestamp()).
+ *
+ * We expect start_time <= stop_time. If not, we return zeroes; for current
+ * callers there is no need to be tense about which way division rounds on
+ * negative inputs.
+ */
+void
+TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
+ long *secs, int *microsecs)
+{
+ TimestampTz diff = stop_time - start_time;
+
+ if (diff <= 0)
+ {
+ *secs = 0;
+ *microsecs = 0;
+ }
+ else
+ {
+#ifdef HAVE_INT64_TIMESTAMP
+ *secs = (long) (diff / USECS_PER_SEC);
+ *microsecs = (int) (diff % USECS_PER_SEC);
+#else
+ *secs = (long) diff;
+ *microsecs = (int) ((diff - *secs) * 1000000.0);
+#endif
+ }
+}
/*
* Convert a time_t to TimestampTz.
@@ -985,6 +1018,27 @@ time_t_to_timestamptz(time_t tm)
return result;
}
+/*
+ * Convert a TimestampTz to time_t.
+ *
+ * This too is just marginally useful, but some places need it.
+ */
+time_t
+timestamptz_to_time_t(TimestampTz t)
+{
+ time_t result;
+
+#ifdef HAVE_INT64_TIMESTAMP
+ result = (time_t) (t / USECS_PER_SEC +
+ ((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY));
+#else
+ result = (time_t) (t +
+ ((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY));
+#endif
+
+ return result;
+}
+
void
dt2time(Timestamp jd, int *hour, int *min, int *sec, fsec_t *fsec)
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index e0f3c9d8868..54db791f613 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -42,7 +42,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.169 2006/03/05 15:58:46 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.170 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -1408,7 +1408,7 @@ log_line_prefix(StringInfo buf)
if (MyProcPort)
{
appendStringInfo(buf, "%lx.%x",
- (long) (MyProcPort->session_start.tv_sec),
+ (long) (MyProcPort->session_start),
MyProcPid);
}
break;
@@ -1440,7 +1440,7 @@ log_line_prefix(StringInfo buf)
strftime(strfbuf, sizeof(strfbuf),
/* leave room for milliseconds... */
- /* Win32 timezone names are too long so don't print them. */
+ /* Win32 timezone names are too long so don't print them */
#ifndef WIN32
"%Y-%m-%d %H:%M:%S %Z",
#else
@@ -1474,12 +1474,11 @@ log_line_prefix(StringInfo buf)
case 's':
if (MyProcPort)
{
- time_t stamp_time = MyProcPort->session_start.tv_sec;
char strfbuf[128];
strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
- localtime(&stamp_time));
+ localtime(&MyProcPort->session_start));
appendStringInfoString(buf, strfbuf);
}
break;
diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c
index 9af7a5f0d86..a32cad08d30 100644
--- a/src/backend/utils/mmgr/portalmem.c
+++ b/src/backend/utils/mmgr/portalmem.c
@@ -12,7 +12,7 @@
* Portions Copyright (c) 1994, Regents of the University of California
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.87 2006/04/25 14:11:58 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.88 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -202,7 +202,7 @@ CreatePortal(const char *name, bool allowDup, bool dupSilent)
portal->atStart = true;
portal->atEnd = true; /* disallow fetches until query is set */
portal->visible = true;
- portal->creation_time = GetCurrentTimestamp();
+ portal->creation_time = GetCurrentStatementStartTimestamp();
/* put portal in table (sets portal->name) */
PortalHashTableInsert(portal, name);
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index d42f4e19598..de85ce10d63 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -11,7 +11,7 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
- * $PostgreSQL: pgsql/src/include/libpq/libpq-be.h,v 1.55 2006/03/05 15:58:56 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/libpq/libpq-be.h,v 1.56 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -31,6 +31,7 @@
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "utils/timestamp.h"
typedef enum CAC_state
@@ -80,7 +81,8 @@ typedef struct Port
* but since it gets used by elog.c in the same way as database_name and
* other members of this struct, we may as well keep it here.
*/
- struct timeval session_start; /* for session duration logging */
+ TimestampTz SessionStartTime; /* backend start time */
+ time_t session_start; /* same, in time_t format */
/*
* TCP keepalive settings.
@@ -97,7 +99,8 @@ typedef struct Port
int keepalives_count;
/*
- * SSL structures
+ * SSL structures (keep these last so that USE_SSL doesn't affect
+ * locations of other fields)
*/
#ifdef USE_SSL
SSL *ssl;
diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.h
index 4e9e0c3f6f7..47832c8b3fc 100644
--- a/src/include/utils/timestamp.h
+++ b/src/include/utils/timestamp.h
@@ -6,7 +6,7 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
- * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.60 2006/04/25 00:25:22 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.61 2006/06/20 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
@@ -177,6 +177,12 @@ typedef double fsec_t;
#define INTERVAL_PRECISION(t) ((t) & INTERVAL_PRECISION_MASK)
#define INTERVAL_RANGE(t) (((t) >> 16) & INTERVAL_RANGE_MASK)
+#ifdef HAVE_INT64_TIMESTAMP
+#define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) * 1000))
+#else
+#define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) / 1000.0))
+#endif
+
/* Set at postmaster start */
extern TimestampTz PgStartTime;
@@ -293,7 +299,11 @@ extern Datum pgsql_postmaster_start_time(PG_FUNCTION_ARGS);
extern TimestampTz GetCurrentTimestamp(void);
+extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
+ long *secs, int *microsecs);
+
extern TimestampTz time_t_to_timestamptz(time_t tm);
+extern time_t timestamptz_to_time_t(TimestampTz t);
extern int tm2timestamp(struct pg_tm * tm, fsec_t fsec, int *tzp, Timestamp *dt);
extern int timestamp2tm(Timestamp dt, int *tzp, struct pg_tm * tm,
--
GitLab