Re: FW: REVIEW: Allow formatting in log_line_prefix - Mailing list pgsql-hackers
| From | David Rowley |
|---|---|
| Subject | Re: FW: REVIEW: Allow formatting in log_line_prefix |
| Date | |
| Msg-id | CAApHDvreSGYvtXJvqHcXZL8_tXiKKiFXhQyXgqtnQ5Yo=MEfMg@mail.gmail.com Whole thread Raw |
| In response to | FW: REVIEW: Allow formatting in log_line_prefix ("David Rowley" <dgrowleyml@gmail.com>) |
| Responses |
Re: FW: REVIEW: Allow formatting in log_line_prefix
Re: FW: REVIEW: Allow formatting in log_line_prefix |
| List | 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 laptopWell, on those tests, I was hardly logging anything, so it's hard to
> 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.
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/
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;
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)
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
David Rowley
Attachment
pgsql-hackers by date: