*
*
* 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 $
*
*-------------------------------------------------------------------------
*/
#include "storage/proc.h"
#include "storage/procarray.h"
#include "storage/spin.h"
+#include "utils/timestamp.h"
/* GUC variables */
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);
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)
{
* 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
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;
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;
}
*
*
* 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
*/
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
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);
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;
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();
* 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,
*/
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);
/*
* Close down transaction statement, if one is open.
*/
- finalize_command();
+ finish_xact_command();
/*
* If there were no parsetrees, return EmptyQueryResponse message.
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)
* 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.
* 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);
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;
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();
/* 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);
* 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
}
/*
- * 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)
* 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);
* 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);
/*
- * 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;
}
}
{
if (xact_started)
{
+ /* Cancel any active statement timeout before committing */
+ disable_sig_alarm(true);
+
+ /* Now commit the command */
ereport(DEBUG3,
(errmsg_internal("CommitTransactionCommand")));
/* We don't have a transaction command open anymore */
xact_started = false;
- command_initialized = false;
-
+
/* Now we can allow interrupts again */
RESUME_INTERRUPTS();
}
{
const char *query_string;
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
+
query_string = pq_getmsgstring(&input_message);
pq_getmsgend(&input_message);
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);
break;
case 'B': /* bind */
+ /* Set statement_timestamp() */
+ SetCurrentStatementStartTimestamp();
/*
* this message is complex enough that it seems best to put
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);
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
}
/* commit the function-invocation transaction */
- finalize_command();
+ finish_xact_command();
send_ready_for_query = true;
break;
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);
case 'S': /* sync */
pq_getmsgend(&input_message);
- finalize_command();
+ finish_xact_command();
send_ready_for_query = true;
break;
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)));
}
projects / postgresql / commitdiff