Thread: Re: FW: REVIEW: Allow formatting in log_line_prefix
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
On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml@gmail.com> wrote: >> 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? > 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. Ouch! That's pretty painful. I agree that's not a normal workload, but I don't think it's an entirely unfair benchmark, either. There certainly are people who suffer because of the cost of logging as things are; for example, log_min_duration_statement is commonly used and can produce massive amounts of output on a busy system. I wouldn't mind too much if the slowdown you are seeing only occurred when the feature is actually used, but taking a 15-18% hit on logging even when the new formatting features aren't being used seems too expensive to me. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
David Rowley escribió: > 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. Ouch. That's certainly way too much. Is the compiler inlining process_log_prefix_padding()? If not, does it do it if you add "inline" to it? That might speed up things a bit. If that's not enough, maybe you need some way to return to the original coding for the case where no padding is set in front of each option. -- Álvaro Herrera http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote: > David Rowley escribió: > > > 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. > > Ouch. That's certainly way too much. Is the compiler inlining > process_log_prefix_padding()? If not, does it do it if you add "inline" > to it? That might speed up things a bit. If that's not enough, maybe > you need some way to return to the original coding for the case where no > padding is set in front of each option. From a very short look without actually running it I'd guess the issue is all the $* things you're now passing to do appendStringInfo (which passes them off to vsnprintf). How does it look without that? Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services
On 2013-09-24 19:56:32 +0200, Andres Freund wrote: > On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote: > > David Rowley escribió: > > > > > 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. > > > > Ouch. That's certainly way too much. Is the compiler inlining > > process_log_prefix_padding()? If not, does it do it if you add "inline" > > to it? That might speed up things a bit. If that's not enough, maybe > > you need some way to return to the original coding for the case where no > > padding is set in front of each option. > > From a very short look without actually running it I'd guess the issue > is all the $* things you're now passing to do appendStringInfo (which > passes them off to vsnprintf). > How does it look without that? That's maybe misunderstandable, what I mean is to have an if (padding > 0) around the the changed appendStringInfo invocations and use the old ones otherwise. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services
On Wed, Sep 25, 2013 at 6:25 AM, Andres Freund <andres@2ndquadrant.com> wrote:
On 2013-09-24 19:56:32 +0200, Andres Freund wrote:That's maybe misunderstandable, what I mean is to have an if (padding >
> On 2013-09-24 13:51:04 -0300, Alvaro Herrera wrote:
> > David Rowley escribió:
> >
> > > 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.
> >
> > Ouch. That's certainly way too much. Is the compiler inlining
> > process_log_prefix_padding()? If not, does it do it if you add "inline"
> > to it? That might speed up things a bit. If that's not enough, maybe
> > you need some way to return to the original coding for the case where no
> > padding is set in front of each option.
>
> From a very short look without actually running it I'd guess the issue
> is all the $* things you're now passing to do appendStringInfo (which
> passes them off to vsnprintf).
> How does it look without that?
0) around the the changed appendStringInfo invocations and use the old
ones otherwise.
Yeah I had the same idea to try that next. I suspect that's where the slow down is rather than the processing of the padding. I'm thinking these small tweaks are going to make the code a bit ugly, but I agree about the 15-18% slowdown is a no go. The only other thing apart from checking if padding > 0 is to check if the char after the % is > '9', in that case it can't be formatting as we're only allowing '-' and '0' to '9'. Although I think that's a bit hackish, but perhaps it is acceptable if it helps narrow the performance gap.
More benchmarks to follow soon.
David
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
On Wed, Sep 25, 2013 at 1:20 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml@gmail.com> wrote:
>> 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?> I do see a 15-18% slow down with the patched version, so perhaps I'll needOuch! That's pretty painful. I agree that's not a normal workload,
> to look to see if I can speed it up a bit, although I do feel this benchmark
> is not quite a normal workload.
but I don't think it's an entirely unfair benchmark, either. There
certainly are people who suffer because of the cost of logging as
things are; for example, log_min_duration_statement is commonly used
and can produce massive amounts of output on a busy system.
I wouldn't mind too much if the slowdown you are seeing only occurred
when the feature is actually used, but taking a 15-18% hit on logging
even when the new formatting features aren't being used seems too
expensive to me.
Ok, I think I've managed to narrow the performance gap to just about nothing but noise, though to do this the code is now a bit bigger. I've added a series of tests to see if the padding is > 0 and if it's not then I'm doing things the old way.
I've also added a some code which does a fast test to see if it is worth while calling the padding processing function. This is just a simple if (*p <= '9'), I'm not completely happy with that as it does look a bit weird, but to compensate I've added a good comment to explain what it is doing.
Please find attached the new patch ... version v0.5 and also updated benchmark results.
Regards
David
David
Attachment
On 9/25/13 4:46 AM, David Rowley wrote: > Please find attached the new patch ... version v0.5 and also updated > benchmark results. Please fix compiler warnings: elog.c: In function ‘log_line_prefix.isra.3’: elog.c:2436:22: warning: ‘padding’ may be used uninitialized in this function [-Wmaybe-uninitialized] elog.c:2172:6: note: ‘padding’ was declared here
On Thu, Sep 26, 2013 at 4:57 AM, Peter Eisentraut <peter_e@gmx.net> wrote:
On 9/25/13 4:46 AM, David Rowley wrote:Please fix compiler warnings:
> Please find attached the new patch ... version v0.5 and also updated
> benchmark results.
elog.c: In function ‘log_line_prefix.isra.3’:
elog.c:2436:22: warning: ‘padding’ may be used uninitialized in this function [-Wmaybe-uninitialized]
elog.c:2172:6: note: ‘padding’ was declared here
Fixed in attached version.
Regards
David Rowley
Attachment
On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml@gmail.com> wrote: > Ok, I think I've managed to narrow the performance gap to just about nothing > but noise, though to do this the code is now a bit bigger. I've added a > series of tests to see if the padding is > 0 and if it's not then I'm doing > things the old way. > > I've also added a some code which does a fast test to see if it is worth > while calling the padding processing function. This is just a simple if (*p > <= '9'), I'm not completely happy with that as it does look a bit weird, but > to compensate I've added a good comment to explain what it is doing. > > Please find attached the new patch ... version v0.5 and also updated > benchmark results. Are you sure this is the right set of benchmark results? This still reflects a 15-18% slowdown AFAICS. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Fri, Sep 27, 2013 at 4:44 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml@gmail.com> wrote:Are you sure this is the right set of benchmark results? This still
> Ok, I think I've managed to narrow the performance gap to just about nothing
> but noise, though to do this the code is now a bit bigger. I've added a
> series of tests to see if the padding is > 0 and if it's not then I'm doing
> things the old way.
>
> I've also added a some code which does a fast test to see if it is worth
> while calling the padding processing function. This is just a simple if (*p
> <= '9'), I'm not completely happy with that as it does look a bit weird, but
> to compensate I've added a good comment to explain what it is doing.
>
> Please find attached the new patch ... version v0.5 and also updated
> benchmark results.
reflects a 15-18% slowdown AFAICS.
I think I must have forgot to save it before I emailed it...
Here's the correct version.
Here's the correct version.
Attachment
On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com> wrote: > I think I must have forgot to save it before I emailed it... > > Here's the correct version. Ah ha. Looks better. I'm working on getting this committed now. Aside from some stylistic things, I've found one serious functional bug, which is that you need to test padding != 0, not padding > 0, when deciding which path to take. No need to send a new patch, I've already fixed it in my local copy... -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Thu, Sep 26, 2013 at 5:18 PM, Robert Haas <robertmhaas@gmail.com> wrote: > On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com> wrote: >> I think I must have forgot to save it before I emailed it... >> >> Here's the correct version. > > Ah ha. Looks better. > > I'm working on getting this committed now. Aside from some stylistic > things, I've found one serious functional bug, which is that you need > to test padding != 0, not padding > 0, when deciding which path to > take. No need to send a new patch, I've already fixed it in my local > copy... Committed now. Let me know if I broke anything. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Fri, Sep 27, 2013 at 10:28 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Sep 26, 2013 at 5:18 PM, Robert Haas <robertmhaas@gmail.com> wrote:
> On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml@gmail.com> wrote:
>> I think I must have forgot to save it before I emailed it...
>>
>> Here's the correct version.
>
> Ah ha. Looks better.
>
> I'm working on getting this committed now. Aside from some stylistic
> things, I've found one serious functional bug, which is that you need
> to test padding != 0, not padding > 0, when deciding which path to
> take. No need to send a new patch, I've already fixed it in my local
> copy...
Oops, negative padding. My bad. I was focusing too much on the benchmarks I think.
Committed now. Let me know if I broke anything.
Great, thanks for commiting!
Thank you Albe for your review too!
Regards
David.