Re: logging in high performance systems.

We have a need for logging in systems where it isn't feasible to log
to disk as it negatively impacts performance.

I'd like to be able to creatively solve this problem without modifying
the core, but today I cannot.

So... here's my first whack at solving this with some flexibility.

The first thing I did was add hook points where immediate statement
logging happens "pre_exec" and those that present duration
"post_exec". These should, with optimization turned on, have only a
few instructions of impact when no hooks are registered (we could
hoist the branch outside the function call if that were identified as
an issue).

https://github.com/postwait/postgres/commit/62bb9dfa2d373618f10e46678612720a3a01599a

The second thing I did was write a sample use of those hooks to
implement a completely non-blocking fifo logger. (if it would block,
it drops the log line). The concept is that we could run this without
risk of negative performance impact due to slow log reading (choosing
to drop logs in lieu of pausing). And a simple process could be
written to consume from the fifo. We use this method in other systems
to log many 10s of thousands of log lines per second with negligible
impact on performance.

https://github.com/postwait/postgres/commit/c8f5a346c7b2c3eba9f72ea49077dc72f03a2679

Thoughts? Feedback?

As can be seen, the patch is pretty tiny.

--
Theo Schlossnagle

http://omniti.com/is/theo-schlossnagle

On 11/23/2011 09:28 PM, Theo Schlossnagle wrote:
> The second thing I did was write a sample use of those hooks to
> implement a completely non-blocking fifo logger. (if it would block,
> it drops the log line). The concept is that we could run this without
> risk of negative performance impact due to slow log reading (choosing
> to drop logs in lieu of pausing). And a simple process could be
> written to consume from the fifo.

This was one of the topics at the last developer's meeting you might not
have seen go by:
http://wiki.postgresql.org/wiki/PgCon_2011_Developer_Meeting#Improving_Logging
There was a reference to a pipe-based implementation from Magnus that I
haven't gotten a chance to track down yet. I think this area is going
to start hitting a lot more people in the upcoming couple of years,
since I'm seeing it increasingly at two customers I consider "canary in
a cole mine" sentinels for performance issues.

I'm now roughly considering three types of users here:

-Don't care about the overhead of logging, but are sick of parsing text
files. Would prefer the data be in a table instead.
-Concerned enough about overhead that statement-level logging is
impractical to log or table, but can cope with logging for other things.
-Logging rate can burst high enough that messages must start being
dropped instead no matter where they go. Before making a big change,
log file vs. table needs to be carefully explored to figure which of the
two approaches has more reasonable behavior/performance trade-offs.

I've been trying to attack this starting at the middle, with the
pg_stat_statements rework Peter here did for the current CommitFest. If
you've already worked out a way to simulate heavy logging as part of
what you've done here, I'd be quite interested to hear how capable you
feel it is for the class of problem you're seeing. I've always assumed
that pushing the most common queries into shared memory and only showing
them on demand, rather than logging them line at a time, could be a big
win for some places. We're still a bit light on benchmarks proving that
is the case so far though.

My assumption has been that eventually a lossy logger was going to be
necessary for busier sites, I just haven't been suffering from one
enough to hack on it yet. If it's possible to work this out in enough
detail to figure out where the hooks go, and to prove they work with at
least one consumer of them, I'd consider that a really useful thing to
try and squeeze into 9.2. The processing parts can always be further
improved later based on production feedback, going along with my recent
them of letting extensions that poke and probe existing hooks be one
place to brew next version features at.

--
Greg Smith 2ndQuadrant US greg(at)2ndQuadrant(dot)com Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support www.2ndQuadrant.us

On Wed, Nov 23, 2011 at 11:45 PM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> My assumption has been that eventually a lossy logger was going to be
> necessary for busier sites, I just haven't been suffering from one enough to
> hack on it yet.  If it's possible to work this out in enough detail to
> figure out where the hooks go, and to prove they work with at least one
> consumer of them, I'd consider that a really useful thing to try and squeeze
> into 9.2.

I think it's possible. I did both in my patches 1) placed hooks where
logging exists today and 2) provided a useful consumer of them. and I
tested it (only on a single system) under high simulated load.

I see the next steps being:
1) agreeing that a problem exists (I know one does, but I suppose
consensus is req'd)
2) agreeing that "hooks" are the right approach, if not propose a
different approach. (fwiw, it's incredible common)
3) reworking the implementation to fit in the project; I assume the
implementation I proposed will, at best, vaguely resemble anything
that gets integrated. It was just a PoC.

Also, I put the sample consumer in contrib in a separate commit, just
to make it easy to review -- while I'm not against it, I am not
proposing that a fifo logger be in contrib.

> The processing parts can always be further improved later based
> on production feedback, going along with my recent them of letting
> extensions that poke and probe existing hooks be one place to brew next
> version features at.

I think that a generalized hook framework (like that offered by
apr-utils) would be generally useful in cases like these. It makes it
simple to add them and auto document them. But, I'm not proposing
that here. I'm trying to keep the patch to logging so I can solve a
critical production issue we seem to be running into more and more.

Thanks for you time.
--
Theo Schlossnagle

http://omniti.com/is/theo-schlossnagle

On Wed, Nov 23, 2011 at 9:28 PM, Theo Schlossnagle <jesus(at)omniti(dot)com> wrote:
> Thoughts? Feedback?

Can you add it to the next CommitFest?

https://commitfest.postgresql.org/action/commitfest_view/open

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

* Theo Schlossnagle (jesus(at)omniti(dot)com) wrote:
> I'd like to be able to creatively solve this problem without modifying
> the core, but today I cannot.

I thought a hook already existed for this (there's already a module
which uses a hook to log commands done as a superuser, for example)..
Perhaps it wasn't in the right place, however.

> So... here's my first whack at solving this with some flexibility.

I was hoping to work on something similar (and have discussed it with
Magnus a few times) but with much more flexibility. Basically, have a
structure where there's a lot of meta-data available that can easily be
used to direct where a log message goes (or if it's logged at all), all
without having to actually parse the log message (which is painful..).

To be honest, I was consdiering something like what syslog-ng provides,
but PG specific, not needing regexp's (though perhaps supporting them)
and with multiple different destination types and locations.

Independent of all that, if we don't have hooks already that can be used
for this, I certainly think it makes sense to add some, even if we do
something more later.

Thanks,

Stephen

On 11/24/2011 06:33 PM, Theo Schlossnagle wrote:
> I see the next steps being:
> 1) agreeing that a problem exists (I know one does, but I suppose
> consensus is req'd)

+1, high volume logging is also a huge problem here at Skype. Some of
the issues that immediately come to mind:

- extracting usage statistics from logs
- extracting error messages from logs
- pushing the logs to remote log server (and no, syslog is not actually
usable for that ;)

> 2) agreeing that "hooks" are the right approach, if not propose a
> different approach. (fwiw, it's incredible common)

+1 for hook based approach. While the whole logging system could
possibly use an overhaul, this is not likely going to happen for 9.2.
Meanwhile hooks provide the flexibility to implement custom log
collectors for those who really need it.

> 3) reworking the implementation to fit in the project; I assume the
> implementation I proposed will, at best, vaguely resemble anything
> that gets integrated. It was just a PoC.
>

I'd vote for a hook to be added to EmitErrorReport. That way all logged
messages pass through the hook, which could then decide whether to
actually write the message to server log or to discard it. As an added
bonus, the message is broken down into pieces so there is no need to
parse the messages for severity, context, etc.

Patch attached.

regards,
Martin

On 11/24/2011 11:33 AM, Theo Schlossnagle wrote:
> I see the next steps being:
> 1) agreeing that a problem exists (I know one does, but I suppose
> consensus is req'd)
> 2) agreeing that "hooks" are the right approach, if not propose a
> different approach. (fwiw, it's incredible common)
> 3) reworking the implementation to fit in the project; I assume the
> implementation I proposed will, at best, vaguely resemble anything
> that gets integrated. It was just a PoC.
>

With this idea still being pretty new, and several of the people popping
out opinions in this thread being local--Theo, Stephen, myself--we've
decided to make our local Baltimore/Washington PUG meeting this month be
an excuse to hash some of this early stuff out a bit more in person, try
to speed things up . See
http://www.meetup.com/Baltimore-Washington-PostgreSQL-Users-Group/events/44335672/
if any other locals would like to attend, it's a week from today. (Note
that the NYC PUG is also having its meeting at the same time this month)

--
Greg Smith 2ndQuadrant US greg(at)2ndQuadrant(dot)com Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support www.2ndQuadrant.us

On Dec 13, 2011, at 13:57, Greg Smith wrote:

> With this idea still being pretty new, and several of the people popping out opinions in this thread being local--Theo, Stephen, myself--we've decided to make our local Baltimore/Washington PUG meeting this month be an excuse to hash some of this early stuff out a bit more in person, try to speed things up . See http://www.meetup.com/Baltimore-Washington-PostgreSQL-Users-Group/events/44335672/ if any other locals would like to attend, it's a week from today. (Note that the NYC PUG is also having its meeting at the same time this month)

What time? I'd potentially like to attend. Philadelphia, represent!

Michael Glaesemann
grzm seespotcode net

On 11/23/2011 09:28 PM, Theo Schlossnagle wrote:
> The first thing I did was add hook points where immediate statement
> logging happens "pre_exec" and those that present duration
> "post_exec". These should, with optimization turned on, have only a
> few instructions of impact when no hooks are registered (we could
> hoist the branch outside the function call if that were identified as
> an issue).
>
> https://github.com/postwait/postgres/commit/62bb9dfa2d373618f10e46678612720a3a01599a

Theo: could you e-mail the current "pre-flight and post-flight logging
hooks" code as a patch to the list? I put it into the CF app so we
don't forget to take a look at this, but from a policy point of view an
official patch submission to the list is needed here. I've looked at
the code on github enough to know we probably want the sort of
registration scheme you've proposed no matter what ends up getting logged.

The majority of Theo's patch is worrying about how to register and
manage multiple hook consumers around statements that are being
executed. The other one we got from Martin is hooking all log output
and not worrying about the multiple consumer problems.

There is an important distinction to make here. Statement logging is
one of the largest producers of logging data you want to worry about
optimizing for on a high performance system. The decision about whether
to log or not may need to be made by the hook. Something that hooks
EmitErrorReport has already lost an important opportunity to make a
decision about whether the system is perhaps too busy to worry about
logging right now at all; you've already paid a chunk of the logging
overhead getting the log message to it. I think both areas are going to
be important to hook eventually.

The meeting to discuss this area at our last BWPUG group happened, and
we made some good progress mapping out what various people would like to
see here. I'm holding the token for the job of summarizing all that
usefully for the community. I'll get back to that as soon as I can now
once the January CF is rolling along, hopefully later this week.

--
Greg Smith 2ndQuadrant US greg(at)2ndQuadrant(dot)com Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support www.2ndQuadrant.com

On Thu, Nov 24, 2011 at 04:28, Theo Schlossnagle <jesus(at)omniti(dot)com> wrote:
> So... here's my first whack at solving this with some flexibility.
>
> The first thing I did was add hook points where immediate statement
> logging happens "pre_exec" and those that present duration
> "post_exec".  These should, with optimization turned on, have only a
> few instructions of impact when no hooks are registered (we could
> hoist the branch outside the function call if that were identified as
> an issue).

Note that the hook mechanism you've built is a departure from how
other hooks are managed in Postgres. Traditionally hooks are just
global function pointers, and each consumer is responsible for storing
the previous value of the hook and chain-calling it in the handler. If
you want to change this pattern, I think you should start another
discussion.

E.g. hook registration looks like:

next_object_access_hook = object_access_hook;
object_access_hook = sepgsql_object_access;

static void
sepgsql_object_access(ObjectAccessType access, Oid classId, Oid
objectId, int subId)
{
if (next_object_access_hook)
(*next_object_access_hook) (access, classId, objectId, subId);

Regards,
Marti

Excerpts from Marti Raudsepp's message of mar ene 17 12:12:50 -0300 2012:
> On Thu, Nov 24, 2011 at 04:28, Theo Schlossnagle <jesus(at)omniti(dot)com> wrote:
> > So... here's my first whack at solving this with some flexibility.
> >
> > The first thing I did was add hook points where immediate statement
> > logging happens "pre_exec" and those that present duration
> > "post_exec".  These should, with optimization turned on, have only a
> > few instructions of impact when no hooks are registered (we could
> > hoist the branch outside the function call if that were identified as
> > an issue).
>
> Note that the hook mechanism you've built is a departure from how
> other hooks are managed in Postgres. Traditionally hooks are just
> global function pointers, and each consumer is responsible for storing
> the previous value of the hook and chain-calling it in the handler. If
> you want to change this pattern, I think you should start another
> discussion.

Hm. We already have places doing the other thing, for example
see XactCallback and ExprContextCallback. Not sure we have an actual
criteria for deciding when to use which.

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Mon, Jan 16, 2012 at 3:51 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> There is an important distinction to make here.  Statement logging is one of
> the largest producers of logging data you want to worry about optimizing for
> on a high performance system.  The decision about whether to log or not may
> need to be made by the hook.  Something that hooks EmitErrorReport has
> already lost an important opportunity to make a decision about whether the
> system is perhaps too busy to worry about logging right now at all; you've
> already paid a chunk of the logging overhead getting the log message to it.
>  I think both areas are going to be important to hook eventually.

I would dismissed this out of hand at this if you said it a year ago,
but I'm older and wiser now. At some point this cycle, I did some
benchmarking of the subtransaction abort path, since the slowness of
things like EXCEPTION blocks in PL/pgsql is a known sore point. I
don't remember the exact numbers anymore, but I do remember the
general picture, which is that constructing the error message is
shockingly expensive compared to anything else that we do in that
path. I dropped it at that point for lack of good ideas: it would be
awfully nice to postpone the error message construction until we know
that it's actually needed, but I don't see any clean (or even messy)
way of doing that.

I'm not sure if the effect is quite as significant for toplevel
transaction abort, because sending the message to the client is going
to cost something, so the relative cost of generating the error
message on a busy system will be less. But I still wouldn't like to
bet against it being significant if you're really hammering the
server.

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

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> I would dismissed this out of hand at this if you said it a year ago,
> but I'm older and wiser now. At some point this cycle, I did some
> benchmarking of the subtransaction abort path, since the slowness of
> things like EXCEPTION blocks in PL/pgsql is a known sore point. I
> don't remember the exact numbers anymore, but I do remember the
> general picture, which is that constructing the error message is
> shockingly expensive compared to anything else that we do in that
> path. I dropped it at that point for lack of good ideas: it would be
> awfully nice to postpone the error message construction until we know
> that it's actually needed, but I don't see any clean (or even messy)
> way of doing that.

I came across this thread while looking back to see if there was
anything relevant to Martin Pihlak's logging patch. It doesn't
seem to be a reason not to commit his patch, but I was a bit struck
by your comment about the cost of generating error messages. We
already knew that was expensive, which is why elog.c has provisions
to not do it if the message isn't going to be printed. I am wondering
exactly what case you were looking at in the above testing --- was it
plpgsql exception blocks? If so, I wonder if there'd be any mileage in
trying to postpone error message processing until we see if the user
actually asks for the text of the message. The SQLERRM variable would
have to become even more magic than it is now for that to work, but
since it's a wart already, maybe that's not a big objection.

regards, tom lane

On Tue, Mar 6, 2012 at 2:11 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> I would dismissed this out of hand at this if you said it a year ago,
>> but I'm older and wiser now.  At some point this cycle, I did some
>> benchmarking of the subtransaction abort path, since the slowness of
>> things like EXCEPTION blocks in PL/pgsql is a known sore point.  I
>> don't remember the exact numbers anymore, but I do remember the
>> general picture, which is that constructing the error message is
>> shockingly expensive compared to anything else that we do in that
>> path.  I dropped it at that point for lack of good ideas: it would be
>> awfully nice to postpone the error message construction until we know
>> that it's actually needed, but I don't see any clean (or even messy)
>> way of doing that.
>
> I came across this thread while looking back to see if there was
> anything relevant to Martin Pihlak's logging patch.  It doesn't
> seem to be a reason not to commit his patch, but I was a bit struck
> by your comment about the cost of generating error messages.  We
> already knew that was expensive, which is why elog.c has provisions
> to not do it if the message isn't going to be printed.  I am wondering
> exactly what case you were looking at in the above testing --- was it
> plpgsql exception blocks?  If so, I wonder if there'd be any mileage in
> trying to postpone error message processing until we see if the user
> actually asks for the text of the message.  The SQLERRM variable would
> have to become even more magic than it is now for that to work, but
> since it's a wart already, maybe that's not a big objection.

/me looks to see if he still has the test case.

Yep, I do. Attached.

A patch I was noodling around with, but ultimately was somewhat
underwhelmed by, also attached. IIRC it helps, but not a lot.

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

On Wed, Nov 23, 2011 at 9:28 PM, Theo Schlossnagle <jesus(at)omniti(dot)com> wrote:
> We have a need for logging in systems where it isn't feasible to log
> to disk as it negatively impacts performance.
>
> I'd like to be able to creatively solve this problem without modifying
> the core, but today I cannot.
>
> So... here's my first whack at solving this with some flexibility.
>
> The first thing I did was add hook points where immediate statement
> logging happens "pre_exec" and those that present duration
> "post_exec".  These should, with optimization turned on, have only a
> few instructions of impact when no hooks are registered (we could
> hoist the branch outside the function call if that were identified as
> an issue).
>
> https://github.com/postwait/postgres/commit/62bb9dfa2d373618f10e46678612720a3a01599a
>
> The second thing I did was write a sample use of those hooks to
> implement a completely non-blocking fifo logger. (if it would block,
> it drops the log line).  The concept is that we could run this without
> risk of negative performance impact due to slow log reading (choosing
> to drop logs in lieu of pausing).  And a simple process could be
> written to consume from the fifo.  We use this method in other systems
> to log many 10s of thousands of log lines per second with negligible
> impact on performance.
>
> https://github.com/postwait/postgres/commit/c8f5a346c7b2c3eba9f72ea49077dc72f03a2679
>
> Thoughts? Feedback?
>
> As can be seen, the patch is pretty tiny.

Theo,

Tom recently committed something by another author that is along
similar lines to what you have here (I think). Can you comment on
whether you think more is still needed and what the differences are
between that approach and yours?

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

On Fri, Mar 9, 2012 at 9:53 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> Tom recently committed something by another author that is along
> similar lines to what you have here (I think).  Can you comment on
> whether you think more is still needed and what the differences are
> between that approach and yours?

Hearing no response, I am marking this Returned with Feedback.

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