diff options
Diffstat (limited to 'src/backend/tcop/postgres.c')
| -rw-r--r-- | src/backend/tcop/postgres.c | 287 |
1 files changed, 122 insertions, 165 deletions
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 @@ -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 : "<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))); } |