Re: FW: REVIEW: Allow formatting in log_line_prefix

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?