From 27c3e3de0939d93ae8adb50ab7e00c4a5ff2fa0d Mon Sep 17 00:00:00 2001 From: Tom Lane 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 or . 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 b59cea044b..3716a85dfb 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 3c77e8a70f..d89c01a62e 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 f6949f1437..a340a91fed 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 aac116b466..8164d7e5b0 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 92e870d99a..6b74c54d5a 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 b7c363d80c..227498d1f6 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 @@ -119,12 +119,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 * commands like COPY FROM STDIN. @@ -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 : "", + execute_is_fetch ? "FETCH from " : "", + (*portal_name) ? portal_name : "", 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 : "", + 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 : "", 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(" 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 fd40c1ebfd..f4f23c9dd3 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 e0f3c9d886..54db791f61 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 9af7a5f0d8..a32cad08d3 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 d42f4e1959..de85ce10d6 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 4e9e0c3f6f..47832c8b3f 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, -- 2.11.0