REVIEW: Allow formatting in log_line_prefix
This is a review for patch
CAApHDvpAgtyPZB2kwa0MmTkSaYG9+vasHYjmjFaTNgXr1aDC4Q@mail.gmail.com
The patch is readable, applies fine and builds without warnings.
It contains sufficient documentation.
It works as it should, no crashes or errors.
It is well written, in fact it improves the readability of
the log_line_prefix function in backend/utils/error/elog.c.
I think that this is a useful feature as it can help to make
stderr logging more readable for humans.
I have a few gripes with the English:
- In the documentation patch:
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width. Whereas a positive
+ padding will pad on the left. Padding can be useful keep log
+ files more human readable.
I think that there should be a comma, not a period, before "whereas".
- The description for the function process_log_prefix_padding
should probably mention that it returns NULL if it encounters
bad syntax.
- This comment:
+ /* Format is invalid if it ends with the padding number */
should begin with lower case.
- In this comment:
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that this moves p passed the padding number
+ * if it exists.
+ */
It should be "past", not "passed".
If these details get fixed, I'll mark the patch ready for committer.
Yours,
Laurenz Albe
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
(Forgot to copy list)
From: David Rowley [mailto:dgrowleyml@gmail.com]
Sent: 19 September 2013 22:35
To: Albe Laurenz
Subject: Re: REVIEW: Allow formatting in log_line_prefix
Hi Laurenz,
Thanks for the review.
Please see my comments below and the updated patch attached.
On Thu, Sep 19, 2013 at 2:18 AM, Albe Laurenz <laurenz.albe@wien.gv.at
<mailto:laurenz.albe@wien.gv.at> > wrote:
This is a review for patch
CAApHDvpAgtyPZB2kwa0MmTkSaYG9+vasHYjmjFaTNgXr1aDC4Q@mail.gmail.com
<mailto:CAApHDvpAgtyPZB2kwa0MmTkSaYG9%2BvasHYjmjFaTNgXr1aDC4Q@mail.gmail.com
The patch is readable, applies fine and builds without warnings.
It contains sufficient documentation.
It works as it should, no crashes or errors.
It is well written, in fact it improves the readability of
the log_line_prefix function in backend/utils/error/elog.c.
I think that this is a useful feature as it can help to make
stderr logging more readable for humans.
I have a few gripes with the English:
- In the documentation patch:
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width. Whereas a positive
+ padding will pad on the left. Padding can be useful keep log
+ files more human readable.
I think that there should be a comma, not a period, before "whereas".
I've made the change you request here and also made a change to my last
sentence, which hopefully is an improvement.
- The description for the function process_log_prefix_padding
should probably mention that it returns NULL if it encounters
bad syntax.
I've added a comment before the function for this.
- This comment:
+ /* Format is invalid if it ends with the padding number */
should begin with lower case.
Fixed, but not quite sure of the reason for lack of caps at the moment.
- In this comment:
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that this moves p passed the padding number
+ * if it exists.
+ */
It should be "past", not "passed".
Fixed.
If these details get fixed, I'll mark the patch ready for committer.
Yours,
Laurenz Albe
Attachments:
log_line_formatting_v0.2.patchapplication/octet-stream; name=log_line_formatting_v0.2.patchDownload
diff -u -r b/postgresql/doc/src/sgml/config.sgml a/postgresql/doc/src/sgml/config.sgml
--- b/postgresql/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/postgresql/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
@@ -3942,7 +3942,13 @@
Unrecognized escapes are ignored. Other
characters are copied straight to the log line. Some escapes are
only recognized by session processes, and are ignored by
- background processes such as the main server process.
+ background processes such as the main server process. Status
+ information may be aligned either left or right by specifying a
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width, whereas a positive
+ padding will pad on the left. Padding can be useful to aid human
+ readability in log files.
This parameter can only be set in the <filename>postgresql.conf</>
file or on the server command line. The default is an empty string.
diff -u -r b/postgresql/src/backend/utils/error/elog.c a/postgresql/src/backend/utils/error/elog.c
--- b/postgresql/src/backend/utils/error/elog.c 2013-09-09 23:40:55.160371254 +1200
+++ a/postgresql/src/backend/utils/error/elog.c 2013-09-19 21:55:41.024657448 +1200
@@ -167,6 +167,7 @@
} while (0)
+static const char *process_log_prefix_padding(const char *p, int *padding);
static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
@@ -2120,6 +2121,43 @@
}
/*
+ * helper function for processing the format string in
+ * log_line_prefix()
+ * This function returns NULL if it finds something which
+ * it deems invalid for the log_line_prefix string.
+ */
+static const char
+*process_log_prefix_padding(const char *p, int *ppadding)
+{
+ int paddingsign = 1;
+ int padding = 0;
+
+ if (*p == '-')
+ {
+ p++;
+
+ if (*p == '\0') /* Did the buf end in %- ? */
+ return NULL;
+ paddingsign = -1;
+ }
+
+
+ /* generate an int version of the numerical string */
+ while (*p >= '0' && *p <= '9')
+ padding = padding * 10 + (*p++ - '0');
+
+ /* format is invalid if it ends with the padding number */
+ if (*p == '\0')
+ return NULL;
+
+ padding *= paddingsign;
+ *ppadding = padding;
+ return p;
+
+}
+
+
+/*
* Format tag info for log lines; append to the provided buffer.
*/
static void
@@ -2129,10 +2167,9 @@
static long log_line_number = 0;
/* has counter been reset in current process? */
- static int log_my_pid = 0;
-
- int format_len;
- int i;
+ static int log_my_pid = 0;
+ int padding;
+ const char *p;
/*
* This is one of the few places where we'd rather not inherit a static
@@ -2151,23 +2188,43 @@
if (Log_line_prefix == NULL)
return; /* in case guc hasn't run yet */
- format_len = strlen(Log_line_prefix);
-
- for (i = 0; i < format_len; i++)
+ /*
+ * The Log_line_prefix also supports optional space padding similar
+ * to printf(). e.g. %-10u will pad the right side of the username
+ * to make it at least 10 chars wide. %10u would pad the left side.
+ */
+ for (p = Log_line_prefix; *p != '\0'; p++)
{
- if (Log_line_prefix[i] != '%')
+ if (*p != '%')
{
/* literal char, just copy */
- appendStringInfoChar(buf, Log_line_prefix[i]);
+ appendStringInfoChar(buf, *p);
continue;
}
- /* go to char after '%' */
- i++;
- if (i >= format_len)
+
+ /* must be a '%', so skip to the next char */
+ p++;
+ if (*p == '\0')
break; /* format error - ignore it */
+ else if (*p == '%')
+ {
+ /* string contains %% */
+ appendStringInfoChar(buf, '%');
+ continue;
+ }
+
+
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that this moves p past the padding number if it
+ * exists.
+ */
+ if ((p = process_log_prefix_padding(p, &padding)) == NULL)
+ break;
+
/* process the option */
- switch (Log_line_prefix[i])
+ switch (*p)
{
case 'a':
if (MyProcPort)
@@ -2176,8 +2233,13 @@
if (appname == NULL || *appname == '\0')
appname = _("[unknown]");
- appendStringInfoString(buf, appname);
+ appendStringInfo(buf, "%*s", padding, appname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
+
break;
case 'u':
if (MyProcPort)
@@ -2186,7 +2248,11 @@
if (username == NULL || *username == '\0')
username = _("[unknown]");
- appendStringInfoString(buf, username);
+ appendStringInfo(buf, "%*s", padding, username);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'd':
@@ -2196,21 +2262,30 @@
if (dbname == NULL || *dbname == '\0')
dbname = _("[unknown]");
- appendStringInfoString(buf, dbname);
+ appendStringInfo(buf, "%*s", padding, dbname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'c':
- appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%lx.%x",
+ (long) (MyStartTime), MyProcPid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
break;
case 'p':
- appendStringInfo(buf, "%d", MyProcPid);
+ appendStringInfo(buf, "%*d", padding, MyProcPid);
break;
case 'l':
- appendStringInfo(buf, "%ld", log_line_number);
+ appendStringInfo(buf, "%*ld", padding, log_line_number);
break;
case 'm':
setup_formatted_log_time();
- appendStringInfoString(buf, formatted_log_time);
+ appendStringInfo(buf, "%*s", padding, formatted_log_time);
break;
case 't':
{
@@ -2220,13 +2295,13 @@
pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, log_timezone));
- appendStringInfoString(buf, strfbuf);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
}
break;
case 's':
if (formatted_start_time[0] == '\0')
setup_formatted_start_time();
- appendStringInfoString(buf, formatted_start_time);
+ appendStringInfo(buf, "%*s", padding, formatted_start_time);
break;
case 'i':
if (MyProcPort)
@@ -2235,43 +2310,70 @@
int displen;
psdisp = get_ps_display(&displen);
- appendBinaryStringInfo(buf, psdisp, displen);
+ appendStringInfo(buf, "%*s", padding, psdisp);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'r':
if (MyProcPort && MyProcPort->remote_host)
{
- appendStringInfoString(buf, MyProcPort->remote_host);
- if (MyProcPort->remote_port &&
- MyProcPort->remote_port[0] != '\0')
- appendStringInfo(buf, "(%s)",
- MyProcPort->remote_port);
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+ {
+ /*
+ * This option is slightly special as the port number
+ * may be appended onto the end. Here we need to build
+ * 1 string which contains the remote_host and optionally
+ * the remote_port (if set) so we can properly align the
+ * string.
+ */
+
+ char *hostport;
+ int alloclen = strlen(MyProcPort->remote_host) +
+ strlen(MyProcPort->remote_port) + 3;
+ hostport = palloc(alloclen);
+ sprintf(hostport, "%s(%s)", MyProcPort->remote_host, MyProcPort->remote_port);
+ appendStringInfo(buf, "%*s", padding, hostport);
+ pfree(hostport);
+
+ }
+ else
+ {
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ }
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'h':
if (MyProcPort && MyProcPort->remote_host)
- appendStringInfoString(buf, MyProcPort->remote_host);
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
if (MyProcPort == NULL)
- i = format_len;
+ return;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(buf, "%d/%u",
MyProc->backendId, MyProc->lxid);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'x':
- appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
+ appendStringInfo(buf, "%*u", padding, GetTopTransactionIdIfAny());
break;
case 'e':
- appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
- break;
- case '%':
- appendStringInfoChar(buf, '%');
+ appendStringInfo(buf, "%*s", padding, unpack_sql_state(edata->sqlerrcode));
break;
default:
/* format error - ignore it */
Import Notes
Reply to msg id not found: CAApHDvqmy9s6abpd9+NYwmS04yr9034JnAQhjszjbBgTBpkkUw@mail.gmail.com
Something is weird in your latest patch. The header is:
diff -u -r b/postgresql/doc/src/sgml/config.sgml a/postgresql/doc/src/sgml/config.sgml
--- b/postgresql/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/postgresql/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
This doesn't apply with patch -p1 or -p0. (You need -p2.)
Your previous patch in this thread seemed OK. You might want to check what you did there.
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Fri, Sep 20, 2013 at 12:48 AM, Peter Eisentraut <peter_e@gmx.net> wrote:
Something is weird in your latest patch. The header is:
diff -u -r b/postgresql/doc/src/sgml/config.sgml a/postgresql/doc/src/sgml/config.sgml --- b/postgresql/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200 +++ a/postgresql/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200This doesn't apply with patch -p1 or -p0. (You need -p2.)
Your previous patch in this thread seemed OK. You might want to check
what you did there.
I moved the source around and I've patched against it again. New patch
attached.
David
Attachments:
log_line_formatting_v0.3.patchapplication/octet-stream; name=log_line_formatting_v0.3.patchDownload
diff -u -r b/doc/src/sgml/config.sgml a/doc/src/sgml/config.sgml
--- b/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
@@ -3942,7 +3942,13 @@
Unrecognized escapes are ignored. Other
characters are copied straight to the log line. Some escapes are
only recognized by session processes, and are ignored by
- background processes such as the main server process.
+ background processes such as the main server process. Status
+ information may be aligned either left or right by specifying a
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width, whereas a positive
+ padding will pad on the left. Padding can be useful to aid human
+ readability in log files.
This parameter can only be set in the <filename>postgresql.conf</>
file or on the server command line. The default is an empty string.
diff -u -r b/src/backend/utils/error/elog.c a/src/backend/utils/error/elog.c
--- b/src/backend/utils/error/elog.c 2013-09-09 23:40:55.160371254 +1200
+++ a/src/backend/utils/error/elog.c 2013-09-19 21:55:41.024657448 +1200
@@ -167,6 +167,7 @@
} while (0)
+static const char *process_log_prefix_padding(const char *p, int *padding);
static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
@@ -2120,6 +2121,43 @@
}
/*
+ * helper function for processing the format string in
+ * log_line_prefix()
+ * This function returns NULL if it finds something which
+ * it deems invalid for the log_line_prefix string.
+ */
+static const char
+*process_log_prefix_padding(const char *p, int *ppadding)
+{
+ int paddingsign = 1;
+ int padding = 0;
+
+ if (*p == '-')
+ {
+ p++;
+
+ if (*p == '\0') /* Did the buf end in %- ? */
+ return NULL;
+ paddingsign = -1;
+ }
+
+
+ /* generate an int version of the numerical string */
+ while (*p >= '0' && *p <= '9')
+ padding = padding * 10 + (*p++ - '0');
+
+ /* format is invalid if it ends with the padding number */
+ if (*p == '\0')
+ return NULL;
+
+ padding *= paddingsign;
+ *ppadding = padding;
+ return p;
+
+}
+
+
+/*
* Format tag info for log lines; append to the provided buffer.
*/
static void
@@ -2129,10 +2167,9 @@
static long log_line_number = 0;
/* has counter been reset in current process? */
- static int log_my_pid = 0;
-
- int format_len;
- int i;
+ static int log_my_pid = 0;
+ int padding;
+ const char *p;
/*
* This is one of the few places where we'd rather not inherit a static
@@ -2151,23 +2188,43 @@
if (Log_line_prefix == NULL)
return; /* in case guc hasn't run yet */
- format_len = strlen(Log_line_prefix);
-
- for (i = 0; i < format_len; i++)
+ /*
+ * The Log_line_prefix also supports optional space padding similar
+ * to printf(). e.g. %-10u will pad the right side of the username
+ * to make it at least 10 chars wide. %10u would pad the left side.
+ */
+ for (p = Log_line_prefix; *p != '\0'; p++)
{
- if (Log_line_prefix[i] != '%')
+ if (*p != '%')
{
/* literal char, just copy */
- appendStringInfoChar(buf, Log_line_prefix[i]);
+ appendStringInfoChar(buf, *p);
continue;
}
- /* go to char after '%' */
- i++;
- if (i >= format_len)
+
+ /* must be a '%', so skip to the next char */
+ p++;
+ if (*p == '\0')
break; /* format error - ignore it */
+ else if (*p == '%')
+ {
+ /* string contains %% */
+ appendStringInfoChar(buf, '%');
+ continue;
+ }
+
+
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that this moves p past the padding number if it
+ * exists.
+ */
+ if ((p = process_log_prefix_padding(p, &padding)) == NULL)
+ break;
+
/* process the option */
- switch (Log_line_prefix[i])
+ switch (*p)
{
case 'a':
if (MyProcPort)
@@ -2176,8 +2233,13 @@
if (appname == NULL || *appname == '\0')
appname = _("[unknown]");
- appendStringInfoString(buf, appname);
+ appendStringInfo(buf, "%*s", padding, appname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
+
break;
case 'u':
if (MyProcPort)
@@ -2186,7 +2248,11 @@
if (username == NULL || *username == '\0')
username = _("[unknown]");
- appendStringInfoString(buf, username);
+ appendStringInfo(buf, "%*s", padding, username);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'd':
@@ -2196,21 +2262,30 @@
if (dbname == NULL || *dbname == '\0')
dbname = _("[unknown]");
- appendStringInfoString(buf, dbname);
+ appendStringInfo(buf, "%*s", padding, dbname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'c':
- appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%lx.%x",
+ (long) (MyStartTime), MyProcPid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
break;
case 'p':
- appendStringInfo(buf, "%d", MyProcPid);
+ appendStringInfo(buf, "%*d", padding, MyProcPid);
break;
case 'l':
- appendStringInfo(buf, "%ld", log_line_number);
+ appendStringInfo(buf, "%*ld", padding, log_line_number);
break;
case 'm':
setup_formatted_log_time();
- appendStringInfoString(buf, formatted_log_time);
+ appendStringInfo(buf, "%*s", padding, formatted_log_time);
break;
case 't':
{
@@ -2220,13 +2295,13 @@
pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, log_timezone));
- appendStringInfoString(buf, strfbuf);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
}
break;
case 's':
if (formatted_start_time[0] == '\0')
setup_formatted_start_time();
- appendStringInfoString(buf, formatted_start_time);
+ appendStringInfo(buf, "%*s", padding, formatted_start_time);
break;
case 'i':
if (MyProcPort)
@@ -2235,43 +2310,70 @@
int displen;
psdisp = get_ps_display(&displen);
- appendBinaryStringInfo(buf, psdisp, displen);
+ appendStringInfo(buf, "%*s", padding, psdisp);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'r':
if (MyProcPort && MyProcPort->remote_host)
{
- appendStringInfoString(buf, MyProcPort->remote_host);
- if (MyProcPort->remote_port &&
- MyProcPort->remote_port[0] != '\0')
- appendStringInfo(buf, "(%s)",
- MyProcPort->remote_port);
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+ {
+ /*
+ * This option is slightly special as the port number
+ * may be appended onto the end. Here we need to build
+ * 1 string which contains the remote_host and optionally
+ * the remote_port (if set) so we can properly align the
+ * string.
+ */
+
+ char *hostport;
+ int alloclen = strlen(MyProcPort->remote_host) +
+ strlen(MyProcPort->remote_port) + 3;
+ hostport = palloc(alloclen);
+ sprintf(hostport, "%s(%s)", MyProcPort->remote_host, MyProcPort->remote_port);
+ appendStringInfo(buf, "%*s", padding, hostport);
+ pfree(hostport);
+
+ }
+ else
+ {
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ }
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'h':
if (MyProcPort && MyProcPort->remote_host)
- appendStringInfoString(buf, MyProcPort->remote_host);
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
if (MyProcPort == NULL)
- i = format_len;
+ return;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(buf, "%d/%u",
MyProc->backendId, MyProc->lxid);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'x':
- appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
+ appendStringInfo(buf, "%*u", padding, GetTopTransactionIdIfAny());
break;
case 'e':
- appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
- break;
- case '%':
- appendStringInfoChar(buf, '%');
+ appendStringInfo(buf, "%*s", padding, unpack_sql_state(edata->sqlerrcode));
break;
default:
/* format error - ignore it */
David Rowley wrote:
I moved the source around and I've patched against it again. New patch attached.
Thank you, marked as ready for committer.
Yours,
Laurenz Albe
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Fri, Sep 20, 2013 at 3:15 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote:
David Rowley wrote:
I moved the source around and I've patched against it again. New patch attached.
Thank you, marked as ready for committer.
/*
+ * helper function for processing the format string in
+ * log_line_prefix()
+ * This function returns NULL if it finds something which
+ * it deems invalid for the log_line_prefix string.
+ */
Comments should be formatted as a single paragraph. If you want
multiple paragraphs, you need to include a line that's blank except
for the leading " *".
+static const char
+*process_log_prefix_padding(const char *p, int *ppadding)
The asterisk should be on the previous line, separated from "char" by a space.
+ appendStringInfo(buf, "%*ld", padding,
log_line_number);
Is %* supported by all versions of printf() on every platform we support?
Earlier there was some discussion of performance. Was that tested?
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sat, Sep 21, 2013 at 7:18 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Fri, Sep 20, 2013 at 3:15 AM, Albe Laurenz <laurenz.albe@wien.gv.at>
wrote:David Rowley wrote:
I moved the source around and I've patched against it again. New patch
attached.
Thank you, marked as ready for committer.
/* + * helper function for processing the format string in + * log_line_prefix() + * This function returns NULL if it finds something which + * it deems invalid for the log_line_prefix string. + */Comments should be formatted as a single paragraph. If you want
multiple paragraphs, you need to include a line that's blank except
for the leading " *".+static const char +*process_log_prefix_padding(const char *p, int *ppadding)The asterisk should be on the previous line, separated from "char" by a
space.
I've attached another revision of the patch which cleans up the comment for
the process_log_prefix_padding function to be more like the comments
earlier in the same file. I have also moved the asterisk to the previous
line.
+ appendStringInfo(buf, "%*ld", padding,
log_line_number);Is %* supported by all versions of printf() on every platform we support?
Do you specifically mean %*ld, or %* in general? As I can see various other
places where %*s is used in the source by looking at grep -r "%\*" .
But if you do mean specifically %*ld, then we did already use %ld here and
since there are places which use %*s, would it be wrong to assume that %*ld
is ok?
Earlier there was some discussion of performance. Was that tested?
I've done some performance tests now. I assume that the processing of the
log line prefix would be drowned out by any testing of number of
transactions per second, so I put a few lines at the start of
send_message_to_server_log():
Which ended up looking like:
static void
send_message_to_server_log(ErrorData *edata)
{
StringInfoData buf;
int i;
float startTime, endTime;
startTime = (float)clock()/CLOCKS_PER_SEC;
StringInfoData tmpbuf;
for (i = 0; i < 1000000; i++)
{
initStringInfo(&tmpbuf);
log_line_prefix(&tmpbuf, edata);
pfree(tmpbuf.data);
}
endTime = (float)clock()/CLOCKS_PER_SEC;
printf("log_line_prefix (%s) in %f seconds\n", Log_line_prefix, endTime
- startTime);
initStringInfo(&buf);
...
I am seeing a slow down in the processing of the 2 log_line_prefix strings
that I tested with. Here are the results:
Patched (%a %u %d %p %t %m %i %e %c %l %s %v %x )
david@ubuntu64:~/9.4/bin$ ./postgres -D /home/david/9.4/data/
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.930000
seconds
62324 2013-09-20 05:37:30 NZST 2013-09-20 05:37:30.455 NZST 00000
523b3656.f374 1000001 2013-09-20 05:37:26 NZST 0 LOG: database system was
shut down at 2013-09-20 05:36:21 NZST
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.940000
seconds
62329 2013-09-20 05:37:38 NZST 2013-09-20 05:37:38.724 NZST 00000
523b365a.f379 1000001 2013-09-20 05:37:30 NZST 0 LOG: autovacuum launcher
started
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.960000
seconds
62323 2013-09-20 05:37:38 NZST 2013-09-20 05:37:38.756 NZST 00000
523b3656.f373 1000001 2013-09-20 05:37:26 NZST 0 LOG: database system is
ready to accept connections
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 4.820000
seconds
psql david postgres 62331 2013-09-20 05:38:43 NZST 2013-09-20 05:38:43.490
NZST SELECT 22012 523b3688.f37b 1000001 2013-09-20 05:38:16 NZST 2/4 0
ERROR: division by zero
psql david postgres 62331 2013-09-20 05:38:43 NZST 2013-09-20 05:38:43.490
NZST SELECT 22012 523b3688.f37b 1000002 2013-09-20 05:38:16 NZST 2/4 0
STATEMENT: select 1/0;
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 4.690000
seconds
psql david postgres 62331 2013-09-20 05:39:35 NZST 2013-09-20 05:39:35.900
NZST SELECT 22012 523b3688.f37b 2000003 2013-09-20 05:38:16 NZST 2/5 0
ERROR: division by zero
psql david postgres 62331 2013-09-20 05:39:35 NZST 2013-09-20 05:39:35.900
NZST SELECT 22012 523b3688.f37b 2000004 2013-09-20 05:38:16 NZST 2/5 0
STATEMENT: select 1/0;
Unpatched (%a %u %d %p %t %m %i %e %c %l %s %v %x )
david@ubuntu64:~/9.4/bin$ ./postgres -D /home/david/9.4/data/
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.120000
seconds
925 2013-09-20 05:45:48 NZST 2013-09-20 05:45:48.483 NZST 00000
523b3849.39d 1000001 2013-09-20 05:45:45 NZST 0 LOG: database system was
shut down at 2013-09-20 05:40:47 NZST
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.100000
seconds
924 2013-09-20 05:45:54 NZST 2013-09-20 05:45:54.970 NZST 00000
523b3849.39c 1000001 2013-09-20 05:45:45 NZST 0 LOG: database system is
ready to accept connections
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.120000
seconds
931 2013-09-20 05:45:55 NZST 2013-09-20 05:45:55.015 NZST 00000
523b384c.3a3 1000001 2013-09-20 05:45:48 NZST 0 LOG: autovacuum launcher
started
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.490000
seconds
psql david postgres 934 2013-09-20 05:46:31 NZST 2013-09-20 05:46:31.795
NZST SELECT 22012 523b3873.3a6 1000001 2013-09-20 05:46:27 NZST 2/2 0
ERROR: division by zero
psql david postgres 934 2013-09-20 05:46:31 NZST 2013-09-20 05:46:31.795
NZST SELECT 22012 523b3873.3a6 1000002 2013-09-20 05:46:27 NZST 2/2 0
STATEMENT: select 1/0;
log_line_prefix (%a %u %d %p %t %m %i %e %c %l %s %v %x ) in 3.560000
seconds
psql david postgres 934 2013-09-20 05:46:36 NZST 2013-09-20 05:46:36.473
NZST SELECT 22012 523b3873.3a6 2000003 2013-09-20 05:46:27 NZST 2/3 0
ERROR: division by zero
psql david postgres 934 2013-09-20 05:46:36 NZST 2013-09-20 05:46:36.473
NZST SELECT 22012 523b3873.3a6 2000004 2013-09-20 05:46:27 NZST 2/3 0
STATEMENT: select 1/0;
Patched (%a %u %d %p)
david@ubuntu64:~/9.4/bin$ ./postgres -D /home/david/9.4/data/
log_line_prefix (%a %u %d %p ) in 0.210000 seconds
1625 LOG: database system was shut down at 2013-09-20 05:48:50 NZST
log_line_prefix (%a %u %d %p ) in 0.210000 seconds
1624 LOG: database system is ready to accept connections
log_line_prefix (%a %u %d %p ) in 0.220000 seconds
1629 LOG: autovacuum launcher started
log_line_prefix (%a %u %d %p ) in 0.620000 seconds
psql david postgres 1631 ERROR: division by zero
psql david postgres 1631 STATEMENT: select 1/0;
log_line_prefix (%a %u %d %p ) in 0.660000 seconds
psql david postgres 1631 ERROR: division by zero
psql david postgres 1631 STATEMENT: select 1/0;
Unpatched (%a %u %d %p)
david@ubuntu64:~/9.4/bin$ ./postgres -D /home/david/9.4/data/
log_line_prefix (%a %u %d %p ) in 0.180000 seconds
2321 LOG: database system was shut down at 2013-09-20 05:50:35 NZST
log_line_prefix (%a %u %d %p ) in 0.180000 seconds
2320 LOG: database system is ready to accept connections
log_line_prefix (%a %u %d %p ) in 0.180000 seconds
2325 LOG: autovacuum launcher started
log_line_prefix (%a %u %d %p ) in 0.260000 seconds
psql david postgres 2327 ERROR: division by zero
psql david postgres 2327 STATEMENT: select 1/0;
log_line_prefix (%a %u %d %p ) in 0.270000 seconds
psql david postgres 2327 ERROR: division by zero
psql david postgres 2327 STATEMENT: select 1/0;
I put the above results into the attached spreadsheet. On my intel i5
laptop I'm seeing a slow down of about 1 second per million queries for the
longer log_line_prefix and about 1 second per 5 million queries with the
shorter log_line_prefix.
In the attached spreadsheet I've mocked up some very rough estimates on
the performance cost of this change. I think a while ago I read about a
benchmark Robert ran on a 64 core machine which ran around 400k
transactions per second. I've included some workings in the spreadsheet to
show how this change would affect that benchmark, but I have assumed that
the hardware would only be able to execute the log_line_prefix function at
the same speed as my i5 laptop. With this very worst case estimates my
calculations say that the performance hit is 0.6% with the log_line_prefix
which contains all of the variables and 0.11% for the shorter
log_line_prefix. I would imagine that the hardware that performed 400k TPS
would be able to run log_line_prefix faster than my 3 year old i5 laptop,
so this is likely quite a big over estimation of the hit.
I did not run any benchmark tests using any padding as I have nothing to
benchmark against.
David
--
Show quoted text
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Attachments:
log_line_formatting_v0.4.patchapplication/octet-stream; name=log_line_formatting_v0.4.patchDownload
diff -r -u b/doc/src/sgml/config.sgml a/doc/src/sgml/config.sgml
--- b/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
@@ -3942,7 +3942,13 @@
Unrecognized escapes are ignored. Other
characters are copied straight to the log line. Some escapes are
only recognized by session processes, and are ignored by
- background processes such as the main server process.
+ background processes such as the main server process. Status
+ information may be aligned either left or right by specifying a
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width, whereas a positive
+ padding will pad on the left. Padding can be useful to aid human
+ readability in log files.
This parameter can only be set in the <filename>postgresql.conf</>
file or on the server command line. The default is an empty string.
diff -r -u b/src/backend/utils/error/elog.c a/src/backend/utils/error/elog.c
--- b/src/backend/utils/error/elog.c 2013-09-20 05:35:54.433280117 +1200
+++ a/src/backend/utils/error/elog.c 2013-09-20 06:13:01.385330333 +1200
@@ -167,6 +167,7 @@
} while (0)
+static const char *process_log_prefix_padding(const char *p, int *padding);
static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
@@ -2120,6 +2121,44 @@
}
/*
+ * process_log_prefix_padding --- helper function for processing the format
+ * string in log_line_prefix
+ *
+ * Note: This function returns NULL if it finds something which
+ * it deems invalid in the format string.
+ */
+static const char *
+process_log_prefix_padding(const char *p, int *ppadding)
+{
+ int paddingsign = 1;
+ int padding = 0;
+
+ if (*p == '-')
+ {
+ p++;
+
+ if (*p == '\0') /* Did the buf end in %- ? */
+ return NULL;
+ paddingsign = -1;
+ }
+
+
+ /* generate an int version of the numerical string */
+ while (*p >= '0' && *p <= '9')
+ padding = padding * 10 + (*p++ - '0');
+
+ /* format is invalid if it ends with the padding number */
+ if (*p == '\0')
+ return NULL;
+
+ padding *= paddingsign;
+ *ppadding = padding;
+ return p;
+
+}
+
+
+/*
* Format tag info for log lines; append to the provided buffer.
*/
static void
@@ -2129,10 +2168,9 @@
static long log_line_number = 0;
/* has counter been reset in current process? */
- static int log_my_pid = 0;
-
- int format_len;
- int i;
+ static int log_my_pid = 0;
+ int padding;
+ const char *p;
/*
* This is one of the few places where we'd rather not inherit a static
@@ -2151,23 +2189,43 @@
if (Log_line_prefix == NULL)
return; /* in case guc hasn't run yet */
- format_len = strlen(Log_line_prefix);
-
- for (i = 0; i < format_len; i++)
+ /*
+ * The Log_line_prefix also supports optional space padding similar
+ * to printf(). e.g. %-10u will pad the right side of the username
+ * to make it at least 10 chars wide. %10u would pad the left side.
+ */
+ for (p = Log_line_prefix; *p != '\0'; p++)
{
- if (Log_line_prefix[i] != '%')
+ if (*p != '%')
{
/* literal char, just copy */
- appendStringInfoChar(buf, Log_line_prefix[i]);
+ appendStringInfoChar(buf, *p);
continue;
}
- /* go to char after '%' */
- i++;
- if (i >= format_len)
+
+ /* must be a '%', so skip to the next char */
+ p++;
+ if (*p == '\0')
break; /* format error - ignore it */
+ else if (*p == '%')
+ {
+ /* string contains %% */
+ appendStringInfoChar(buf, '%');
+ continue;
+ }
+
+
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that this moves p past the padding number if it
+ * exists.
+ */
+ if ((p = process_log_prefix_padding(p, &padding)) == NULL)
+ break;
+
/* process the option */
- switch (Log_line_prefix[i])
+ switch (*p)
{
case 'a':
if (MyProcPort)
@@ -2176,8 +2234,13 @@
if (appname == NULL || *appname == '\0')
appname = _("[unknown]");
- appendStringInfoString(buf, appname);
+ appendStringInfo(buf, "%*s", padding, appname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
+
break;
case 'u':
if (MyProcPort)
@@ -2186,7 +2249,11 @@
if (username == NULL || *username == '\0')
username = _("[unknown]");
- appendStringInfoString(buf, username);
+ appendStringInfo(buf, "%*s", padding, username);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'd':
@@ -2196,21 +2263,30 @@
if (dbname == NULL || *dbname == '\0')
dbname = _("[unknown]");
- appendStringInfoString(buf, dbname);
+ appendStringInfo(buf, "%*s", padding, dbname);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'c':
- appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%lx.%x",
+ (long) (MyStartTime), MyProcPid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
break;
case 'p':
- appendStringInfo(buf, "%d", MyProcPid);
+ appendStringInfo(buf, "%*d", padding, MyProcPid);
break;
case 'l':
- appendStringInfo(buf, "%ld", log_line_number);
+ appendStringInfo(buf, "%*ld", padding, log_line_number);
break;
case 'm':
setup_formatted_log_time();
- appendStringInfoString(buf, formatted_log_time);
+ appendStringInfo(buf, "%*s", padding, formatted_log_time);
break;
case 't':
{
@@ -2220,13 +2296,13 @@
pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, log_timezone));
- appendStringInfoString(buf, strfbuf);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
}
break;
case 's':
if (formatted_start_time[0] == '\0')
setup_formatted_start_time();
- appendStringInfoString(buf, formatted_start_time);
+ appendStringInfo(buf, "%*s", padding, formatted_start_time);
break;
case 'i':
if (MyProcPort)
@@ -2235,43 +2311,70 @@
int displen;
psdisp = get_ps_display(&displen);
- appendBinaryStringInfo(buf, psdisp, displen);
+ appendStringInfo(buf, "%*s", padding, psdisp);
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'r':
if (MyProcPort && MyProcPort->remote_host)
{
- appendStringInfoString(buf, MyProcPort->remote_host);
- if (MyProcPort->remote_port &&
- MyProcPort->remote_port[0] != '\0')
- appendStringInfo(buf, "(%s)",
- MyProcPort->remote_port);
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+ {
+ /*
+ * This option is slightly special as the port number
+ * may be appended onto the end. Here we need to build
+ * 1 string which contains the remote_host and optionally
+ * the remote_port (if set) so we can properly align the
+ * string.
+ */
+
+ char *hostport;
+ int alloclen = strlen(MyProcPort->remote_host) +
+ strlen(MyProcPort->remote_port) + 3;
+ hostport = palloc(alloclen);
+ sprintf(hostport, "%s(%s)", MyProcPort->remote_host, MyProcPort->remote_port);
+ appendStringInfo(buf, "%*s", padding, hostport);
+ pfree(hostport);
+
+ }
+ else
+ {
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ }
+ }
+ else
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'h':
if (MyProcPort && MyProcPort->remote_host)
- appendStringInfoString(buf, MyProcPort->remote_host);
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
if (MyProcPort == NULL)
- i = format_len;
+ return;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(buf, "%d/%u",
MyProc->backendId, MyProc->lxid);
+ else
+ appendStringInfoSpaces(buf, padding);
break;
case 'x':
- appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
+ appendStringInfo(buf, "%*u", padding, GetTopTransactionIdIfAny());
break;
case 'e':
- appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
- break;
- case '%':
- appendStringInfoChar(buf, '%');
+ appendStringInfo(buf, "%*s", padding, unpack_sql_state(edata->sqlerrcode));
break;
default:
/* format error - ignore it */
On Fri, Sep 20, 2013 at 11:28 PM, David Rowley <dgrowleyml@gmail.com> wrote:\
I put the above results into the attached spreadsheet. On my intel i5 laptop
I'm seeing a slow down of about 1 second per million queries for the longer
log_line_prefix and about 1 second per 5 million queries with the shorter
log_line_prefix.In the attached spreadsheet I've mocked up some very rough estimates on the
performance cost of this change. I think a while ago I read about a
benchmark Robert ran on a 64 core machine which ran around 400k transactions
per second. I've included some workings in the spreadsheet to show how this
change would affect that benchmark, but I have assumed that the hardware
would only be able to execute the log_line_prefix function at the same speed
as my i5 laptop. With this very worst case estimates my calculations say
that the performance hit is 0.6% with the log_line_prefix which contains all
of the variables and 0.11% for the shorter log_line_prefix. I would imagine
that the hardware that performed 400k TPS would be able to run
log_line_prefix faster than my 3 year old i5 laptop, so this is likely quite
a big over estimation of the hit.
Well, on those tests, I was hardly logging anything, so it's hard to
really draw any conclusions that way.
I think the real concern with this patch, performance-wise, is what
happens in environments where there is a lot of logging going on.
We've had previous reports of people who can't even enable the logging
they want because the performance cost is unacceptably high. That's
why we added that logging hook in 9.2 or 9.3, so that people can write
alternative loggers that just throw away messages if the recipient
can't eat them fast enough.
I wouldn't be keen to accept a 25% performance hit on logging overall,
but log_line_prefix() is only a small part of that cost.
So... I guess the question that I'd ask is, if you write a PL/pgsql
function that does RAISE NOTICE in a loop a large number of times, can
you measure any difference in how fast that function executes on the
patch and unpatched code? If so, how much?
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Tue, Sep 24, 2013 at 5:16 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Fri, Sep 20, 2013 at 11:28 PM, David Rowley <dgrowleyml@gmail.com>
wrote:\I put the above results into the attached spreadsheet. On my intel i5
laptop
I'm seeing a slow down of about 1 second per million queries for the
longer
log_line_prefix and about 1 second per 5 million queries with the shorter
log_line_prefix.In the attached spreadsheet I've mocked up some very rough estimates on
the
performance cost of this change. I think a while ago I read about a
benchmark Robert ran on a 64 core machine which ran around 400ktransactions
per second. I've included some workings in the spreadsheet to show how
this
change would affect that benchmark, but I have assumed that the hardware
would only be able to execute the log_line_prefix function at the samespeed
as my i5 laptop. With this very worst case estimates my calculations say
that the performance hit is 0.6% with the log_line_prefix which containsall
of the variables and 0.11% for the shorter log_line_prefix. I would
imagine
that the hardware that performed 400k TPS would be able to run
log_line_prefix faster than my 3 year old i5 laptop, so this is likelyquite
a big over estimation of the hit.
Well, on those tests, I was hardly logging anything, so it's hard to
really draw any conclusions that way.I think the real concern with this patch, performance-wise, is what
happens in environments where there is a lot of logging going on.
We've had previous reports of people who can't even enable the logging
they want because the performance cost is unacceptably high. That's
why we added that logging hook in 9.2 or 9.3, so that people can write
alternative loggers that just throw away messages if the recipient
can't eat them fast enough.I wouldn't be keen to accept a 25% performance hit on logging overall,
but log_line_prefix() is only a small part of that cost.So... I guess the question that I'd ask is, if you write a PL/pgsql
function that does RAISE NOTICE in a loop a large number of times, can
you measure any difference in how fast that function executes on the
patch and unpatched code? If so, how much?
Ok, I've been doing a bit of benchmarking on this. To mock up a really fast
I/O system I created a RAM disk which I will ask Postgres to send the log
files to.
mkdir /tmp/ramdisk; chmod 777 /tmp/ramdisk
mount -t tmpfs -o size=256M tmpfs /tmp/ramdisk/
I created the following function in plpgsql
create function stresslog(n int) returns int as $$
begin
while n > 0 loop
raise notice '%', n;
n := n - 1;
end loop;
return 0;
end;
$$ language plpgsql;
I was running postgreql with
david@ubuntu64:~/9.4/bin$ ./pg_ctl start -D /home/david/9.4/data -l
/tmp/ramdisk/pg.log
I ran the following command 5 times for each version.
client_min_message is set to warning and log_min_message is set to notice
postgres=# select stresslog(100000);
stresslog
-----------
0
(1 row)
I do see a 15-18% slow down with the patched version, so perhaps I'll need
to look to see if I can speed it up a bit, although I do feel this
benchmark is not quite a normal workload.
Please see below the results, or if you want to play about with them a bit,
please use the attached spreadsheet.
------------------------------------
* Round 1
Patched: log_line_prefix = "%a %u %d %r %h %p %t %m %i %e %c %l %s %v %x "
Time: 1822.105 ms
Time: 1762.529 ms
Time: 1839.724 ms
Time: 1837.372 ms
Time: 1813.240 ms
unpatched: log_line_prefix = "%a %u %d %r %h %p %t %m %i %e %c %l %s %v %x "
Time: 1519.032 ms
Time: 1528.760 ms
Time: 1484.074 ms
Time: 1552.786 ms
Time: 1569.410 ms
* Round 2
patched: log_line_prefix = "%a %u %d %e "
Time: 625.969 ms
Time: 668.444 ms
Time: 648.310 ms
Time: 663.655 ms
Time: 715.397 ms
unpatched: log_line_prefix = "%a %u %d %e "
Time: 598.146 ms
Time: 518.827 ms
Time: 532.858 ms
Time: 529.584 ms
Time: 537.276 ms
Regards
David Rowley
Attachments:
Import Notes
Resolved by subject fallback
On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml@gmail.com> wrote:
So... I guess the question that I'd ask is, if you write a PL/pgsql
function that does RAISE NOTICE in a loop a large number of times, can
you measure any difference in how fast that function executes on the
patch and unpatched code? If so, how much?I do see a 15-18% slow down with the patched version, so perhaps I'll need
to look to see if I can speed it up a bit, although I do feel this benchmark
is not quite a normal workload.
Ouch! That's pretty painful. I agree that's not a normal workload,
but I don't think it's an entirely unfair benchmark, either. There
certainly are people who suffer because of the cost of logging as
things are; for example, log_min_duration_statement is commonly used
and can produce massive amounts of output on a busy system.
I wouldn't mind too much if the slowdown you are seeing only occurred
when the feature is actually used, but taking a 15-18% hit on logging
even when the new formatting features aren't being used seems too
expensive to me.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
David Rowley escribi�:
I do see a 15-18% slow down with the patched version, so perhaps I'll need
to look to see if I can speed it up a bit, although I do feel this
benchmark is not quite a normal workload.
Ouch. That's certainly way too much. Is the compiler inlining
process_log_prefix_padding()? If not, does it do it if you add "inline"
to it? That might speed up things a bit. If that's not enough, maybe
you need some way to return to the original coding for the case where no
padding is set in front of each option.
--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote:
David Rowley escribió:
I do see a 15-18% slow down with the patched version, so perhaps I'll need
to look to see if I can speed it up a bit, although I do feel this
benchmark is not quite a normal workload.Ouch. That's certainly way too much. Is the compiler inlining
process_log_prefix_padding()? If not, does it do it if you add "inline"
to it? That might speed up things a bit. If that's not enough, maybe
you need some way to return to the original coding for the case where no
padding is set in front of each option.
From a very short look without actually running it I'd guess the issue
is all the $* things you're now passing to do appendStringInfo (which
passes them off to vsnprintf).
How does it look without that?
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 2013-09-24 19:56:32 +0200, Andres Freund wrote:
On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote:
David Rowley escribió:
I do see a 15-18% slow down with the patched version, so perhaps I'll need
to look to see if I can speed it up a bit, although I do feel this
benchmark is not quite a normal workload.Ouch. That's certainly way too much. Is the compiler inlining
process_log_prefix_padding()? If not, does it do it if you add "inline"
to it? That might speed up things a bit. If that's not enough, maybe
you need some way to return to the original coding for the case where no
padding is set in front of each option.From a very short look without actually running it I'd guess the issue
is all the $* things you're now passing to do appendStringInfo (which
passes them off to vsnprintf).
How does it look without that?
That's maybe misunderstandable, what I mean is to have an if (padding >
0) around the the changed appendStringInfo invocations and use the old
ones otherwise.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Sep 25, 2013 at 6:25 AM, Andres Freund <andres@2ndquadrant.com>wrote:
On 2013-09-24 19:56:32 +0200, Andres Freund wrote:
On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote:
David Rowley escribió:
I do see a 15-18% slow down with the patched version, so perhaps
I'll need
to look to see if I can speed it up a bit, although I do feel this
benchmark is not quite a normal workload.Ouch. That's certainly way too much. Is the compiler inlining
process_log_prefix_padding()? If not, does it do it if you add"inline"
to it? That might speed up things a bit. If that's not enough, maybe
you need some way to return to the original coding for the case whereno
padding is set in front of each option.
From a very short look without actually running it I'd guess the issue
is all the $* things you're now passing to do appendStringInfo (which
passes them off to vsnprintf).
How does it look without that?That's maybe misunderstandable, what I mean is to have an if (padding >
0) around the the changed appendStringInfo invocations and use the old
ones otherwise.
Yeah I had the same idea to try that next. I suspect that's where the slow
down is rather than the processing of the padding. I'm thinking these small
tweaks are going to make the code a bit ugly, but I agree about the 15-18%
slowdown is a no go. The only other thing apart from checking if padding >
0 is to check if the char after the % is > '9', in that case it can't be
formatting as we're only allowing '-' and '0' to '9'. Although I think
that's a bit hackish, but perhaps it is acceptable if it helps narrow the
performance gap.
More benchmarks to follow soon.
David
Show quoted text
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
On Wed, Sep 25, 2013 at 1:20 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml@gmail.com>
wrote:So... I guess the question that I'd ask is, if you write a PL/pgsql
function that does RAISE NOTICE in a loop a large number of times, can
you measure any difference in how fast that function executes on the
patch and unpatched code? If so, how much?I do see a 15-18% slow down with the patched version, so perhaps I'll
need
to look to see if I can speed it up a bit, although I do feel this
benchmark
is not quite a normal workload.
Ouch! That's pretty painful. I agree that's not a normal workload,
but I don't think it's an entirely unfair benchmark, either. There
certainly are people who suffer because of the cost of logging as
things are; for example, log_min_duration_statement is commonly used
and can produce massive amounts of output on a busy system.I wouldn't mind too much if the slowdown you are seeing only occurred
when the feature is actually used, but taking a 15-18% hit on logging
even when the new formatting features aren't being used seems too
expensive to me.
Ok, I think I've managed to narrow the performance gap to just about
nothing but noise, though to do this the code is now a bit bigger. I've
added a series of tests to see if the padding is > 0 and if it's not then
I'm doing things the old way.
I've also added a some code which does a fast test to see if it is worth
while calling the padding processing function. This is just a simple if (*p
<= '9'), I'm not completely happy with that as it does look a bit weird,
but to compensate I've added a good comment to explain what it is doing.
Please find attached the new patch ... version v0.5 and also updated
benchmark results.
Regards
David
--
Show quoted text
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Attachments:
log_line_formatting_v0.5.patchapplication/octet-stream; name=log_line_formatting_v0.5.patchDownload
diff -r -u b/doc/src/sgml/config.sgml a/doc/src/sgml/config.sgml
--- b/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
@@ -3942,7 +3942,13 @@
Unrecognized escapes are ignored. Other
characters are copied straight to the log line. Some escapes are
only recognized by session processes, and are ignored by
- background processes such as the main server process.
+ background processes such as the main server process. Status
+ information may be aligned either left or right by specifying a
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width, whereas a positive
+ padding will pad on the left. Padding can be useful to aid human
+ readability in log files.
This parameter can only be set in the <filename>postgresql.conf</>
file or on the server command line. The default is an empty string.
diff -r -u b/src/backend/utils/error/elog.c a/src/backend/utils/error/elog.c
--- b/src/backend/utils/error/elog.c 2013-09-20 09:03:59.477561648 +1200
+++ a/src/backend/utils/error/elog.c 2013-09-24 22:24:22.326977716 +1200
@@ -167,6 +167,7 @@
} while (0)
+static const char *process_log_prefix_padding(const char *p, int *padding);
static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
@@ -2120,6 +2121,44 @@
}
/*
+ * process_log_prefix_padding --- helper function for processing the format
+ * string in log_line_prefix
+ *
+ * Note: This function returns NULL if it finds something which
+ * it deems invalid in the format string.
+ */
+static const char *
+process_log_prefix_padding(const char *p, int *ppadding)
+{
+ int paddingsign = 1;
+ int padding = 0;
+
+ if (*p == '-')
+ {
+ p++;
+
+ if (*p == '\0') /* Did the buf end in %- ? */
+ return NULL;
+ paddingsign = -1;
+ }
+
+
+ /* generate an int version of the numerical string */
+ while (*p >= '0' && *p <= '9')
+ padding = padding * 10 + (*p++ - '0');
+
+ /* format is invalid if it ends with the padding number */
+ if (*p == '\0')
+ return NULL;
+
+ padding *= paddingsign;
+ *ppadding = padding;
+ return p;
+
+}
+
+
+/*
* Format tag info for log lines; append to the provided buffer.
*/
static void
@@ -2129,10 +2168,9 @@
static long log_line_number = 0;
/* has counter been reset in current process? */
- static int log_my_pid = 0;
-
- int format_len;
- int i;
+ static int log_my_pid = 0;
+ int padding;
+ const char *p;
/*
* This is one of the few places where we'd rather not inherit a static
@@ -2151,23 +2189,49 @@
if (Log_line_prefix == NULL)
return; /* in case guc hasn't run yet */
- format_len = strlen(Log_line_prefix);
-
- for (i = 0; i < format_len; i++)
+ /*
+ * The Log_line_prefix also supports optional space padding similar
+ * to printf(). e.g. %-10u will pad the right side of the username
+ * to make it at least 10 chars wide. %10u would pad the left side.
+ */
+ for (p = Log_line_prefix; *p != '\0'; p++)
{
- if (Log_line_prefix[i] != '%')
+ if (*p != '%')
{
/* literal char, just copy */
- appendStringInfoChar(buf, Log_line_prefix[i]);
+ appendStringInfoChar(buf, *p);
continue;
}
- /* go to char after '%' */
- i++;
- if (i >= format_len)
+
+ /* must be a '%', so skip to the next char */
+ p++;
+ if (*p == '\0')
break; /* format error - ignore it */
+ else if (*p == '%')
+ {
+ /* string contains %% */
+ appendStringInfoChar(buf, '%');
+ continue;
+ }
+
+
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that process_log_prefix_padding moves p past
+ * the padding number if it exists.
+ *
+ * Note: Since only '-', '0' to '9' are valid formatting
+ * characters we can do a quick check here to pre-check
+ * for formatting. If the char is not formatting then we
+ * can skip a useless function call.
+ */
+ if (*p <= '9')
+ if ((p = process_log_prefix_padding(p, &padding)) == NULL)
+ break;
+
/* process the option */
- switch (Log_line_prefix[i])
+ switch (*p)
{
case 'a':
if (MyProcPort)
@@ -2176,8 +2240,14 @@
if (appname == NULL || *appname == '\0')
appname = _("[unknown]");
- appendStringInfoString(buf, appname);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, appname);
+ else
+ appendStringInfoString(buf, appname);
}
+ else
+ appendStringInfoSpaces(buf, padding);
+
break;
case 'u':
if (MyProcPort)
@@ -2186,8 +2256,13 @@
if (username == NULL || *username == '\0')
username = _("[unknown]");
- appendStringInfoString(buf, username);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, username);
+ else
+ appendStringInfoString(buf, username);
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'd':
if (MyProcPort)
@@ -2196,21 +2271,44 @@
if (dbname == NULL || *dbname == '\0')
dbname = _("[unknown]");
- appendStringInfoString(buf, dbname);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, dbname);
+ else
+ appendStringInfoString(buf, dbname);
+
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'c':
- appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
+ if (padding > 0)
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%lx.%x",
+ (long) (MyStartTime), MyProcPid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
+ else
+ appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
break;
case 'p':
- appendStringInfo(buf, "%d", MyProcPid);
+ if (padding > 0)
+ appendStringInfo(buf, "%*d", padding, MyProcPid);
+ else
+ appendStringInfo(buf, "%d", MyProcPid);
break;
case 'l':
- appendStringInfo(buf, "%ld", log_line_number);
+ if (padding > 0)
+ appendStringInfo(buf, "%*ld", padding, log_line_number);
+ else
+ appendStringInfo(buf, "%ld", log_line_number);
break;
case 'm':
setup_formatted_log_time();
- appendStringInfoString(buf, formatted_log_time);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, formatted_log_time);
+ else
+ appendStringInfoString(buf, formatted_log_time);
break;
case 't':
{
@@ -2220,13 +2318,19 @@
pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, log_timezone));
- appendStringInfoString(buf, strfbuf);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ else
+ appendStringInfoString(buf, strfbuf);
}
break;
case 's':
if (formatted_start_time[0] == '\0')
setup_formatted_start_time();
- appendStringInfoString(buf, formatted_start_time);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, formatted_start_time);
+ else
+ appendStringInfoString(buf, formatted_start_time);
break;
case 'i':
if (MyProcPort)
@@ -2235,43 +2339,103 @@
int displen;
psdisp = get_ps_display(&displen);
- appendBinaryStringInfo(buf, psdisp, displen);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, psdisp);
+ else
+ appendBinaryStringInfo(buf, psdisp, displen);
+
+ }
+ else if (padding > 0)
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'r':
if (MyProcPort && MyProcPort->remote_host)
{
- appendStringInfoString(buf, MyProcPort->remote_host);
- if (MyProcPort->remote_port &&
- MyProcPort->remote_port[0] != '\0')
- appendStringInfo(buf, "(%s)",
- MyProcPort->remote_port);
+ if (padding > 0)
+ {
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+ {
+ /*
+ * This option is slightly special as the port number
+ * may be appended onto the end. Here we need to build
+ * 1 string which contains the remote_host and optionally
+ * the remote_port (if set) so we can properly align the
+ * string.
+ */
+
+ char *hostport;
+ int alloclen = strlen(MyProcPort->remote_host) +
+ strlen(MyProcPort->remote_port) + 3;
+ hostport = palloc(alloclen);
+ sprintf(hostport, "%s(%s)", MyProcPort->remote_host, MyProcPort->remote_port);
+ appendStringInfo(buf, "%*s", padding, hostport);
+ pfree(hostport);
+ }
+ else
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+
+ }
+ else
+ {
+ /* padding is 0, so we don't need a temp buffer */
+ appendStringInfoString(buf, MyProcPort->remote_host);
+ if (MyProcPort->remote_port &&
+ MyProcPort->remote_port[0] != '\0')
+ appendStringInfo(buf, "(%s)",
+ MyProcPort->remote_port);
+ }
+
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'h':
- if (MyProcPort && MyProcPort->remote_host)
- appendStringInfoString(buf, MyProcPort->remote_host);
+ if (MyProcPort && MyProcPort->remote_host)
+ {
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ else
+ appendStringInfoString(buf, MyProcPort->remote_host);
+ }
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
if (MyProcPort == NULL)
- i = format_len;
+ return;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
- appendStringInfo(buf, "%d/%u",
- MyProc->backendId, MyProc->lxid);
+ {
+ if (padding > 0)
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%d/%u",
+ MyProc->backendId, MyProc->lxid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
+ else
+ appendStringInfo(buf, "%d/%u", MyProc->backendId, MyProc->lxid);
+ }
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'x':
- appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
+ if (padding > 0)
+ appendStringInfo(buf, "%*u", padding, GetTopTransactionIdIfAny());
+ else
+ appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
break;
case 'e':
- appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
- break;
- case '%':
- appendStringInfoChar(buf, '%');
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, unpack_sql_state(edata->sqlerrcode));
+ else
+ appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
break;
default:
/* format error - ignore it */
On 9/25/13 4:46 AM, David Rowley wrote:
Please find attached the new patch ... version v0.5 and also updated
benchmark results.
Please fix compiler warnings:
elog.c: In function �log_line_prefix.isra.3�:
elog.c:2436:22: warning: �padding� may be used uninitialized in this function [-Wmaybe-uninitialized]
elog.c:2172:6: note: �padding� was declared here
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Sep 26, 2013 at 4:57 AM, Peter Eisentraut <peter_e@gmx.net> wrote:
On 9/25/13 4:46 AM, David Rowley wrote:
Please find attached the new patch ... version v0.5 and also updated
benchmark results.Please fix compiler warnings:
elog.c: In function ‘log_line_prefix.isra.3’:
elog.c:2436:22: warning: ‘padding’ may be used uninitialized in this
function [-Wmaybe-uninitialized]
elog.c:2172:6: note: ‘padding’ was declared here
Fixed in attached version.
Regards
David Rowley
Attachments:
log_line_formatting_v0.6.patchapplication/octet-stream; name=log_line_formatting_v0.6.patchDownload
diff -r -u b/doc/src/sgml/config.sgml a/doc/src/sgml/config.sgml
--- b/doc/src/sgml/config.sgml 2013-09-09 23:40:52.356371191 +1200
+++ a/doc/src/sgml/config.sgml 2013-09-19 22:13:26.236681468 +1200
@@ -3942,7 +3942,13 @@
Unrecognized escapes are ignored. Other
characters are copied straight to the log line. Some escapes are
only recognized by session processes, and are ignored by
- background processes such as the main server process.
+ background processes such as the main server process. Status
+ information may be aligned either left or right by specifying a
+ numeric literal after the % and before the option. A negative
+ padding will cause the status information to be padded on the
+ right with spaces to give it a minimum width, whereas a positive
+ padding will pad on the left. Padding can be useful to aid human
+ readability in log files.
This parameter can only be set in the <filename>postgresql.conf</>
file or on the server command line. The default is an empty string.
Only in a/doc/src/sgml: config.sgml~
Only in a: log_line_formatting_v0.1.patch
Binary files b/src/backend/postgres and a/src/backend/postgres differ
diff -r -u b/src/backend/utils/error/elog.c a/src/backend/utils/error/elog.c
--- b/src/backend/utils/error/elog.c 2013-09-20 09:03:59.477561648 +1200
+++ a/src/backend/utils/error/elog.c 2013-09-24 22:55:35.095019946 +1200
@@ -167,6 +167,7 @@
} while (0)
+static const char *process_log_prefix_padding(const char *p, int *padding);
static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
@@ -2120,6 +2121,44 @@
}
/*
+ * process_log_prefix_padding --- helper function for processing the format
+ * string in log_line_prefix
+ *
+ * Note: This function returns NULL if it finds something which
+ * it deems invalid in the format string.
+ */
+static const char *
+process_log_prefix_padding(const char *p, int *ppadding)
+{
+ int paddingsign = 1;
+ int padding = 0;
+
+ if (*p == '-')
+ {
+ p++;
+
+ if (*p == '\0') /* Did the buf end in %- ? */
+ return NULL;
+ paddingsign = -1;
+ }
+
+
+ /* generate an int version of the numerical string */
+ while (*p >= '0' && *p <= '9')
+ padding = padding * 10 + (*p++ - '0');
+
+ /* format is invalid if it ends with the padding number */
+ if (*p == '\0')
+ return NULL;
+
+ padding *= paddingsign;
+ *ppadding = padding;
+ return p;
+
+}
+
+
+/*
* Format tag info for log lines; append to the provided buffer.
*/
static void
@@ -2129,10 +2168,9 @@
static long log_line_number = 0;
/* has counter been reset in current process? */
- static int log_my_pid = 0;
-
- int format_len;
- int i;
+ static int log_my_pid = 0;
+ int padding;
+ const char *p;
/*
* This is one of the few places where we'd rather not inherit a static
@@ -2151,23 +2189,54 @@
if (Log_line_prefix == NULL)
return; /* in case guc hasn't run yet */
- format_len = strlen(Log_line_prefix);
-
- for (i = 0; i < format_len; i++)
+ /*
+ * The Log_line_prefix also supports optional space padding similar
+ * to printf(). e.g. %-10u will pad the right side of the username
+ * to make it at least 10 chars wide. %10u would pad the left side.
+ */
+ for (p = Log_line_prefix; *p != '\0'; p++)
{
- if (Log_line_prefix[i] != '%')
+ if (*p != '%')
{
/* literal char, just copy */
- appendStringInfoChar(buf, Log_line_prefix[i]);
+ appendStringInfoChar(buf, *p);
continue;
}
- /* go to char after '%' */
- i++;
- if (i >= format_len)
+
+ /* must be a '%', so skip to the next char */
+ p++;
+ if (*p == '\0')
break; /* format error - ignore it */
+ else if (*p == '%')
+ {
+ /* string contains %% */
+ appendStringInfoChar(buf, '%');
+ continue;
+ }
+
+
+ /*
+ * Process any formatting which may exist after the '%'.
+ * Note that process_log_prefix_padding moves p past
+ * the padding number if it exists.
+ *
+ * Note: Since only '-', '0' to '9' are valid formatting
+ * characters we can do a quick check here to pre-check
+ * for formatting. If the char is not formatting then we
+ * can skip a useless function call.
+ */
+ if (*p <= '9')
+ {
+ if ((p = process_log_prefix_padding(p, &padding)) == NULL)
+ {
+ break;
+ }
+ }
+ else
+ padding = 0;
/* process the option */
- switch (Log_line_prefix[i])
+ switch (*p)
{
case 'a':
if (MyProcPort)
@@ -2176,8 +2245,14 @@
if (appname == NULL || *appname == '\0')
appname = _("[unknown]");
- appendStringInfoString(buf, appname);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, appname);
+ else
+ appendStringInfoString(buf, appname);
}
+ else
+ appendStringInfoSpaces(buf, padding);
+
break;
case 'u':
if (MyProcPort)
@@ -2186,8 +2261,13 @@
if (username == NULL || *username == '\0')
username = _("[unknown]");
- appendStringInfoString(buf, username);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, username);
+ else
+ appendStringInfoString(buf, username);
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'd':
if (MyProcPort)
@@ -2196,21 +2276,44 @@
if (dbname == NULL || *dbname == '\0')
dbname = _("[unknown]");
- appendStringInfoString(buf, dbname);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, dbname);
+ else
+ appendStringInfoString(buf, dbname);
+
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'c':
- appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
+ if (padding > 0)
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%lx.%x",
+ (long) (MyStartTime), MyProcPid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
+ else
+ appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
break;
case 'p':
- appendStringInfo(buf, "%d", MyProcPid);
+ if (padding > 0)
+ appendStringInfo(buf, "%*d", padding, MyProcPid);
+ else
+ appendStringInfo(buf, "%d", MyProcPid);
break;
case 'l':
- appendStringInfo(buf, "%ld", log_line_number);
+ if (padding > 0)
+ appendStringInfo(buf, "%*ld", padding, log_line_number);
+ else
+ appendStringInfo(buf, "%ld", log_line_number);
break;
case 'm':
setup_formatted_log_time();
- appendStringInfoString(buf, formatted_log_time);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, formatted_log_time);
+ else
+ appendStringInfoString(buf, formatted_log_time);
break;
case 't':
{
@@ -2220,13 +2323,19 @@
pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, log_timezone));
- appendStringInfoString(buf, strfbuf);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ else
+ appendStringInfoString(buf, strfbuf);
}
break;
case 's':
if (formatted_start_time[0] == '\0')
setup_formatted_start_time();
- appendStringInfoString(buf, formatted_start_time);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, formatted_start_time);
+ else
+ appendStringInfoString(buf, formatted_start_time);
break;
case 'i':
if (MyProcPort)
@@ -2235,43 +2344,103 @@
int displen;
psdisp = get_ps_display(&displen);
- appendBinaryStringInfo(buf, psdisp, displen);
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, psdisp);
+ else
+ appendBinaryStringInfo(buf, psdisp, displen);
+
+ }
+ else if (padding > 0)
+ {
+ appendStringInfoSpaces(buf, padding);
}
break;
case 'r':
if (MyProcPort && MyProcPort->remote_host)
{
- appendStringInfoString(buf, MyProcPort->remote_host);
- if (MyProcPort->remote_port &&
- MyProcPort->remote_port[0] != '\0')
- appendStringInfo(buf, "(%s)",
- MyProcPort->remote_port);
+ if (padding > 0)
+ {
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+ {
+ /*
+ * This option is slightly special as the port number
+ * may be appended onto the end. Here we need to build
+ * 1 string which contains the remote_host and optionally
+ * the remote_port (if set) so we can properly align the
+ * string.
+ */
+
+ char *hostport;
+ int alloclen = strlen(MyProcPort->remote_host) +
+ strlen(MyProcPort->remote_port) + 3;
+ hostport = palloc(alloclen);
+ sprintf(hostport, "%s(%s)", MyProcPort->remote_host, MyProcPort->remote_port);
+ appendStringInfo(buf, "%*s", padding, hostport);
+ pfree(hostport);
+ }
+ else
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+
+ }
+ else
+ {
+ /* padding is 0, so we don't need a temp buffer */
+ appendStringInfoString(buf, MyProcPort->remote_host);
+ if (MyProcPort->remote_port &&
+ MyProcPort->remote_port[0] != '\0')
+ appendStringInfo(buf, "(%s)",
+ MyProcPort->remote_port);
+ }
+
}
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'h':
- if (MyProcPort && MyProcPort->remote_host)
- appendStringInfoString(buf, MyProcPort->remote_host);
+ if (MyProcPort && MyProcPort->remote_host)
+ {
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, MyProcPort->remote_host);
+ else
+ appendStringInfoString(buf, MyProcPort->remote_host);
+ }
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
if (MyProcPort == NULL)
- i = format_len;
+ return;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
- appendStringInfo(buf, "%d/%u",
- MyProc->backendId, MyProc->lxid);
+ {
+ if (padding > 0)
+ {
+ char strfbuf[128];
+ snprintf(strfbuf, sizeof(strfbuf) - 1, "%d/%u",
+ MyProc->backendId, MyProc->lxid);
+ appendStringInfo(buf, "%*s", padding, strfbuf);
+ }
+ else
+ appendStringInfo(buf, "%d/%u", MyProc->backendId, MyProc->lxid);
+ }
+ else if (padding > 0)
+ appendStringInfoSpaces(buf, padding);
break;
case 'x':
- appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
+ if (padding > 0)
+ appendStringInfo(buf, "%*u", padding, GetTopTransactionIdIfAny());
+ else
+ appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
break;
case 'e':
- appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
- break;
- case '%':
- appendStringInfoChar(buf, '%');
+ if (padding > 0)
+ appendStringInfo(buf, "%*s", padding, unpack_sql_state(edata->sqlerrcode));
+ else
+ appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
break;
default:
/* format error - ignore it */
On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml@gmail.com> wrote:
Ok, I think I've managed to narrow the performance gap to just about nothing
but noise, though to do this the code is now a bit bigger. I've added a
series of tests to see if the padding is > 0 and if it's not then I'm doing
things the old way.I've also added a some code which does a fast test to see if it is worth
while calling the padding processing function. This is just a simple if (*p
<= '9'), I'm not completely happy with that as it does look a bit weird, but
to compensate I've added a good comment to explain what it is doing.Please find attached the new patch ... version v0.5 and also updated
benchmark results.
Are you sure this is the right set of benchmark results? This still
reflects a 15-18% slowdown AFAICS.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Fri, Sep 27, 2013 at 4:44 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml@gmail.com>
wrote:Ok, I think I've managed to narrow the performance gap to just about
nothing
but noise, though to do this the code is now a bit bigger. I've added a
series of tests to see if the padding is > 0 and if it's not then I'mdoing
things the old way.
I've also added a some code which does a fast test to see if it is worth
while calling the padding processing function. This is just a simple if(*p
<= '9'), I'm not completely happy with that as it does look a bit weird,
but
to compensate I've added a good comment to explain what it is doing.
Please find attached the new patch ... version v0.5 and also updated
benchmark results.Are you sure this is the right set of benchmark results? This still
reflects a 15-18% slowdown AFAICS.
I think I must have forgot to save it before I emailed it...
Here's the correct version.
Show quoted text
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Attachments:
On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com> wrote:
I think I must have forgot to save it before I emailed it...
Here's the correct version.
Ah ha. Looks better.
I'm working on getting this committed now. Aside from some stylistic
things, I've found one serious functional bug, which is that you need
to test padding != 0, not padding > 0, when deciding which path to
take. No need to send a new patch, I've already fixed it in my local
copy...
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Sep 26, 2013 at 5:18 PM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com> wrote:
I think I must have forgot to save it before I emailed it...
Here's the correct version.
Ah ha. Looks better.
I'm working on getting this committed now. Aside from some stylistic
things, I've found one serious functional bug, which is that you need
to test padding != 0, not padding > 0, when deciding which path to
take. No need to send a new patch, I've already fixed it in my local
copy...
Committed now. Let me know if I broke anything.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Fri, Sep 27, 2013 at 10:28 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Sep 26, 2013 at 5:18 PM, Robert Haas <robertmhaas@gmail.com>
wrote:On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com>
wrote:
I think I must have forgot to save it before I emailed it...
Here's the correct version.
Ah ha. Looks better.
I'm working on getting this committed now. Aside from some stylistic
things, I've found one serious functional bug, which is that you need
to test padding != 0, not padding > 0, when deciding which path to
take. No need to send a new patch, I've already fixed it in my local
copy...
Oops, negative padding. My bad. I was focusing too much on the benchmarks I
think.
Committed now. Let me know if I broke anything.
Great, thanks for commiting!
Thank you Albe for your review too!
Regards
David.
Show quoted text
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company