Re: FW: REVIEW: Allow formatting in log_line_prefix

On Tue, Sep 24, 2013 at 5:16 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> On Fri, Sep 20, 2013 at 11:28 PM, David Rowley <dgrowleyml(at)gmail(dot)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?
>
>

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/

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;

I was running postgreql with
david(at)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)

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

Regards

David Rowley

On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml(at)gmail(dot)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(at)2ndquadrant(dot)com>wrote:

> 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.
>
>
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(at)gmail(dot)com> wrote:

> On Tue, Sep 24, 2013 at 5:04 AM, David Rowley <dgrowleyml(at)gmail(dot)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.
>
>
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

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

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(at)gmx(dot)net> wrote:

> 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
>
>
Fixed in attached version.

Regards

David Rowley

On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml(at)gmail(dot)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(at)gmail(dot)com> wrote:

> On Wed, Sep 25, 2013 at 4:46 AM, David Rowley <dgrowleyml(at)gmail(dot)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.
>
>
I think I must have forgot to save it before I emailed it...

Here's the correct version.

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

On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml(at)gmail(dot)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(at)gmail(dot)com> wrote:
> On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml(at)gmail(dot)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(at)gmail(dot)com> wrote:

> On Thu, Sep 26, 2013 at 5:18 PM, Robert Haas <robertmhaas(at)gmail(dot)com>
> wrote:
> > On Thu, Sep 26, 2013 at 3:55 PM, David Rowley <dgrowleyml(at)gmail(dot)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.

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