On Sat, Sep 21, 2013 at 7:18 AM, Robert Haas <robertmh...@gmail.com> wrote:
> On Fri, Sep 20, 2013 at 3:15 AM, Albe Laurenz <laurenz.a...@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 >
log_line_formatting_v0.4.patch
Description: Binary data
log_line_prefix_benchmark_results_v0.4.xls
Description: MS-Excel spreadsheet
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers