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 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@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


Attachment

pgsql-hackers by date:

Previous
From: Andres Freund
Date:
Subject: Re: record identical operator
Next
From: Andres Freund
Date:
Subject: Re: INSERT...ON DUPLICATE KEY LOCK FOR UPDATE - visibility semantics