Re: FW: REVIEW: Allow formatting in log_line_prefix

Поиск
Список
Период
Сортировка
От David Rowley
Тема Re: FW: REVIEW: Allow formatting in log_line_prefix
Дата
Msg-id CAApHDvqJUgcHAdSPAFYy=tDW94bD2AbjwXudar4QuwBx5Za8mg@mail.gmail.com
обсуждение исходный текст
Ответ на Re: FW: REVIEW: Allow formatting in log_line_prefix  (Robert Haas <robertmhaas@gmail.com>)
Ответы Re: FW: REVIEW: Allow formatting in log_line_prefix  (Robert Haas <robertmhaas@gmail.com>)
Список 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

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

Вложения

В списке pgsql-hackers по дате отправления:

Предыдущее
От: Stephen Frost
Дата:
Сообщение: Re: INSERT...ON DUPLICATE KEY LOCK FOR UPDATE
Следующее
От: Noah Misch
Дата:
Сообщение: Re: pgbench progress report improvements