Thread: REVIEW: Allow formatting in log_line_prefix

REVIEW: Allow formatting in log_line_prefix

From
Albe Laurenz
Date:
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
informationto be padded on the +         right with spaces to give it a minimum width. Whereas a positive +
paddingwill 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
encountersbad 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
thatthis 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

FW: REVIEW: Allow formatting in log_line_prefix

From
"David Rowley"
Date:

(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> wrote:

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".

 

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

 

Attachment

Re: FW: REVIEW: Allow formatting in log_line_prefix

From
Peter Eisentraut
Date:
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.



Re: FW: REVIEW: Allow formatting in log_line_prefix

From
David Rowley
Date:



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 +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.

I moved the source around and I've patched against it again. New patch attached.


David
Attachment

Re: FW: REVIEW: Allow formatting in log_line_prefix

From
Albe Laurenz
Date:
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

Re: FW: REVIEW: Allow formatting in log_line_prefix

From
Robert Haas
Date:
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



Re: FW: REVIEW: Allow formatting in log_line_prefix

From
David Rowley
Date:
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

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

Attachment

Re: FW: REVIEW: Allow formatting in log_line_prefix

From
Robert Haas
Date:
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