Re: FW: REVIEW: Allow formatting in log_line_prefix

On Sat, Sep 21, 2013 at 7:18 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> On Fri, Sep 20, 2013 at 3:15 AM, Albe Laurenz <laurenz(dot)albe(at)wien(dot)gv(dot)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(at)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(at)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(at)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(at)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

--
> Robert Haas
> EnterpriseDB: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company
>