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