database/postgres
database/postgres
1
0
Fork 0
mirror of https://github.com/postgres/postgres.git synced 2025-04-24 10:47:04 +03:00
Code

Coordinate log_line_prefix options 'm' and 'n' to share a timeval.

Browse Source 
Commit f828654e introduced the 'n' option, but it invoked
gettimeofday() independently of the 'm' option. If both options were
in use (or multiple 'n' options), or if 'n' was in use along with
csvlog, then the reported times could be different for the same log
message.

To fix, initialize a global variable with gettimeofday() once per log
message, and use that for both formats.

Don't bother coordinating the time for the 't' option, which has much
lower resolution.

Per complaint by Alvaro Herrera.
This commit is contained in:
Jeff Davis 2015-09-07 15:40:49 -07:00
parent d94c36a45a
commit b1e1862a12
1 changed files with 23 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

32
src/backend/utils/error/elog.c
View File

@ -143,10 +143,14 @@ static int errordata_stack_depth = -1; /* index of topmost active frame */
static int recursion_depth = 0; /* to detect actual recursion */ static int recursion_depth = 0; /* to detect actual recursion */
/* buffers for formatted timestamps that might be used by both /*
* log_line_prefix and csv logs. * Saved timeval and buffers for formatted timestamps that might be used by
* both log_line_prefix and csv logs.
*/ */
static struct timeval saved_timeval;
static bool saved_timeval_set = false;
#define FORMATTED_TS_LEN 128 #define FORMATTED_TS_LEN 128
static char formatted_start_time[FORMATTED_TS_LEN]; static char formatted_start_time[FORMATTED_TS_LEN];
static char formatted_log_time[FORMATTED_TS_LEN]; static char formatted_log_time[FORMATTED_TS_LEN];
@ -2195,12 +2199,16 @@ write_console(const char *line, int len)
static void static void
setup_formatted_log_time(void) setup_formatted_log_time(void)
{ {
struct timeval tv;
pg_time_t stamp_time; pg_time_t stamp_time;
char msbuf[8]; char msbuf[8];
gettimeofday(&tv, NULL); if (!saved_timeval_set)
stamp_time = (pg_time_t) tv.tv_sec; {
gettimeofday(&saved_timeval, NULL);
saved_timeval_set = true;
}
stamp_time = (pg_time_t) saved_timeval.tv_sec;
/* /*
* Note: we expect that guc.c will ensure that log_timezone is set up (at * Note: we expect that guc.c will ensure that log_timezone is set up (at
@ -2213,7 +2221,7 @@ setup_formatted_log_time(void)
pg_localtime(&stamp_time, log_timezone)); pg_localtime(&stamp_time, log_timezone));
/* 'paste' milliseconds into place... */ /* 'paste' milliseconds into place... */
sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000)); sprintf(msbuf, ".%03d", (int) (saved_timeval.tv_usec / 1000));
memcpy(formatted_log_time + 19, msbuf, 4); memcpy(formatted_log_time + 19, msbuf, 4);
} }
@ -2440,11 +2448,16 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
break; break;
case 'n': case 'n':
{ {
struct timeval tv;
char strfbuf[128]; char strfbuf[128];
gettimeofday(&tv, NULL); if (!saved_timeval_set)
sprintf(strfbuf, "%ld.%03d", tv.tv_sec, (int)(tv.tv_usec / 1000)); {
gettimeofday(&saved_timeval, NULL);
saved_timeval_set = true;
}
sprintf(strfbuf, "%ld.%03d", saved_timeval.tv_sec,
(int)(saved_timeval.tv_usec / 1000));
if (padding != 0) if (padding != 0)
appendStringInfo(buf, "%*s", padding, strfbuf); appendStringInfo(buf, "%*s", padding, strfbuf);
@ -2825,6 +2838,7 @@ send_message_to_server_log(ErrorData *edata)
initStringInfo(&buf); initStringInfo(&buf);
saved_timeval_set = false;
formatted_log_time[0] = '\0'; formatted_log_time[0] = '\0';
log_line_prefix(&buf, edata); log_line_prefix(&buf, edata);