Using ProcSignal to get memory context stats from a running backend

From: Craig Ringer [mailto:craig@2ndquadrant.com]

TL;DR: Lets add a ProcSignalReason that makes a backend call
MemoryContextStats when it sees it and a C func that users can use to set
it on a proc. Sane?

So how about borrowing a ProcSignalReason entry for "dump a memory context
summary at your earliest convenience" ? We could name it a more generic
"dump debug data" in case we want to add things later.

Then a new pg_log_debug_backend(int) function or something like that could
signal the proc and let CHECK_FOR_INTERRUPTS handle calling
MemoryContextStats next time it's called.

+1
That's one of things I wanted to do. It will be more useful on Windows. Would it work for autovac processes and background workers, etc. that connect to shared memory?

I have also wanted to dump stack traces. Linux (glibc) has backtrace_symbols(), and Windows has StackWalk()/StackWalk64(). Is it sane to make the function a hook?

Regards
Takayuki Tsunakawa

Hi,

On 2017-12-12 11:57:41 +0800, Craig Ringer wrote:

TL;DR: Lets add a ProcSignalReason that makes a backend
call MemoryContextStats when it sees it and a C func that users can use to
set it on a proc. Sane?

It's not unproblematic. procsignal_sigusr1_handler() runs in a signal
handler, so you can't really rely on a lot of stuff being legal to
do.

It'd be easy to set a flag in the handler and then have
CHECK_FOR_INTERRUPTS() do the MemoryContextStats() call. But that'd have
the disadvanatage that it possibly would take a while till the
MemoryContextStats() is executed. Not sure if that's still good enough
for you?

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

Greetings,

Andres Freund

On 12 December 2017 at 12:25, Tsunakawa, Takayuki <
tsunakawa.takay@jp.fujitsu.com> wrote:

From: Craig Ringer [mailto:craig@2ndquadrant.com]

TL;DR: Lets add a ProcSignalReason that makes a backend call
MemoryContextStats when it sees it and a C func that users can use to set
it on a proc. Sane?

So how about borrowing a ProcSignalReason entry for "dump a memory

context

summary at your earliest convenience" ? We could name it a more generic
"dump debug data" in case we want to add things later.

Then a new pg_log_debug_backend(int) function or something like that

could

signal the proc and let CHECK_FOR_INTERRUPTS handle calling
MemoryContextStats next time it's called.

+1
That's one of things I wanted to do. It will be more useful on Windows.
Would it work for autovac processes and background workers, etc. that
connect to shared memory?

Anything that uses CHECK_FOR_INTERRUPTS() and is attached to PGXACT. So
yeah, pretty much anything attached to shmem.

I have also wanted to dump stack traces. Linux (glibc) has
backtrace_symbols(), and Windows has StackWalk()/StackWalk64(). Is it sane
to make the function a hook?

In-proc stack traces are immensely useful, and IMO relatively safe in a
proc that's already in a reasonable state. If your stack is mangled, making
it worse with an in-proc stack trace is rarely your biggest concern. I'd
LOVE to be able to do this.

However, I'd want to address anything like that quite separately to the
change I proposed to expose an existing facility.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Andres Freund <andres@anarazel.de> writes:

On 2017-12-12 11:57:41 +0800, Craig Ringer wrote:

TL;DR: Lets add a ProcSignalReason that makes a backend
call MemoryContextStats when it sees it and a C func that users can use to
set it on a proc. Sane?

It's not unproblematic. procsignal_sigusr1_handler() runs in a signal
handler, so you can't really rely on a lot of stuff being legal to do.

Indeed, calling MemoryContextStats in a signal handler would be a damfool
idea, but Craig didn't propose that AFAICS.

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

Yeah, this is an issue. MemoryContextStats is designed to print
to stderr in the (possibly vain) hope that it will work even when
we are up against an OOM failure. That's not a property I much
want to give up, but you're right that it's not very desirable
if a user is trying to capture state during normal running.

regards, tom lane

On 12 December 2017 at 12:43, Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2017-12-12 11:57:41 +0800, Craig Ringer wrote:

TL;DR: Lets add a ProcSignalReason that makes a backend
call MemoryContextStats when it sees it and a C func that users can use

to

set it on a proc. Sane?

It's not unproblematic. procsignal_sigusr1_handler() runs in a signal
handler, so you can't really rely on a lot of stuff being legal to
do.

It'd be easy to set a flag in the handler and then have
CHECK_FOR_INTERRUPTS() do the MemoryContextStats() call.

Yes, definitely. That was my intention. Trying to write to stderr, mess
with memory contexts, etc from a signal handler context seems awfully hairy
and definitely not something I'd want to risk on a live system.

But that'd have
the disadvanatage that it possibly would take a while till the
MemoryContextStats() is executed. Not sure if that's still good enough
for you?

Definitely. Sure, it won't be perfect, but it'd be a big improvement on
what we have.

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

I think the reason it prints to stderr now is that it's intended to run in
OOM situations.

Arguably that's not such a concern when being triggered by a procsignal. So
elog(...) in that context could make sense. I'd probably add a
print-wrapper callback arg to MemoryContextStatsDetail that you can use to
write to a stringinfo / elog / fprintf(stderr), as desired.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

On 12 December 2017 at 14:06, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

Yeah, this is an issue. MemoryContextStats is designed to print
to stderr in the (possibly vain) hope that it will work even when
we are up against an OOM failure. That's not a property I much
want to give up, but you're right that it's not very desirable
if a user is trying to capture state during normal running.

If we were willing to wrap variadic calls in a callback and rely on
vfprintf, we could:

typedef void (*printwrapper)(void *extra, const char *fmt,...)
pg_attribute_printf(2, 3);

...

static void
printwrapper_stderr(void *extra, const char *fmt, ...)
{
vfprintf(stderr, fmt, va_list);
}

void
MemoryContextStats(MemoryContext context)
{
MemoryContextStatsDetail(context, 100, printwrapper_stderr, NULL);
}

void
MemoryContextStatsDetail(MemoryContext context, int max_children,
printwrapper outfunc, void *printwrapper_extra)
{
...
printwrapper(extra, "Grand total: ...", ...);
}

and let the ProcSignal based caller pass an elog wrapper instead, or form a
StringInfo with appendStringInfoVA then elog it in one go after the
MemoryContextStatsDetail call returns.

I was worried about relying on vfprintf, but we already use it widely in
the codebase so it shouldn't be an issue with elderly buildfarm critters.

Letting it go to stderr isn't too bad, but it'd certainly make it that bit
nicer if it didn't so I'm not opposed to adding the needed indirection.
I'll give it a try in a bit.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

On 2017-12-12 14:25:48 +0800, Craig Ringer wrote:

If we were willing to wrap variadic calls in a callback and rely on
vfprintf, we could:

I don't think there's problems with relying on variadic calls, we do
that in plenty places.

and let the ProcSignal based caller pass an elog wrapper instead, or form a
StringInfo with appendStringInfoVA then elog it in one go after the
MemoryContextStatsDetail call returns.

I don't think we want a simple elog wrapper - outputting the context
stats as hundreds of log messages doesn't seem right. So at the least it
seems we should bunch it up in stringinfo - which seems to at least
require expanding the API to pass around a void *callback_data or such.

I do wonder if the right thing here wouldn't be to put the result into a
dsm segment, and then return that to the UDF on the requesting
side. Logging to the server log and then have the requestor dig that out
doesn't seem particularly user friendly.

Greetings,

Andres Freund

On Tue, Dec 12, 2017 at 1:50 PM, Andres Freund <andres@anarazel.de> wrote:

I do wonder if the right thing here wouldn't be to put the result into a
dsm segment, and then return that to the UDF on the requesting
side. Logging to the server log and then have the requestor dig that out
doesn't seem particularly user friendly.

I think that dumping it to the server log will be fine for most
people, and it's *significantly* safer. Creating a DSM segment could
fail, and the last thing we want is for interrogating a long-running
backend to make it crap out.

+1 for this whole concept, just BTW. As I've said before, I grow
weary of asking customers to run gdb.

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

On 2017-12-12 14:04:55 -0500, Robert Haas wrote:

On Tue, Dec 12, 2017 at 1:50 PM, Andres Freund <andres@anarazel.de> wrote:

I do wonder if the right thing here wouldn't be to put the result into a
dsm segment, and then return that to the UDF on the requesting
side. Logging to the server log and then have the requestor dig that out
doesn't seem particularly user friendly.

I think that dumping it to the server log will be fine for most
people, and it's *significantly* safer.

I agree that it's more reliable - I hope there's no meaningful safety
difference. I think you overestimate users a bit however - far from
most of them are going to be able to extract a very long log entry from
a busy log file. There's no generally available easy way to copy a few
pages of text from a logfile that's a few gigabytes large...

I'd suggest adding two functions.

Creating a DSM segment could fail, and the last thing we want is for
interrogating a long-running backend to make it crap out.

It'd need to handle memory alloc failures gracefully, I agree. That
doesn't seem impossible. Also don't think that's meaningfully different
in the non-dsm case, it'd be good to handle malloc failures gracefully
in that case as well.

The requesting side should create the dsm segment and preallocate a
reasonable amount of memory, if we go for it.

+1 for this whole concept, just BTW. As I've said before, I grow
weary of asking customers to run gdb.

Indeed.

Greetings,

Andres Freund

On Tue, Dec 12, 2017 at 2:12 PM, Andres Freund <andres@anarazel.de> wrote:

I agree that it's more reliable - I hope there's no meaningful safety
difference. I think you overestimate users a bit however - far from
most of them are going to be able to extract a very long log entry from
a busy log file. There's no generally available easy way to copy a few
pages of text from a logfile that's a few gigabytes large...

Well, a lot of users will send us the whole logfile rather than just
the relevant bits, but that doesn't bother me.

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

On 2017-12-12 14:16:59 -0500, Robert Haas wrote:

On Tue, Dec 12, 2017 at 2:12 PM, Andres Freund <andres@anarazel.de> wrote:

I agree that it's more reliable - I hope there's no meaningful safety
difference. I think you overestimate users a bit however - far from
most of them are going to be able to extract a very long log entry from
a busy log file. There's no generally available easy way to copy a few
pages of text from a logfile that's a few gigabytes large...

Well, a lot of users will send us the whole logfile rather than just
the relevant bits, but that doesn't bother me.

That doesn't really work on some busy servers, and also often in cases
where the log potentially contains sensitive (e.g. HIPPA) data.

I think a function returning the dump would be great, a function "just"
dumping to the server log still pretty good.

Greetings,

Andres Freund

On Mon, Dec 11, 2017 at 10:07 PM, Craig Ringer <craig@2ndquadrant.com> wrote:

On 12 December 2017 at 12:43, Andres Freund <andres@anarazel.de> wrote:

On 2017-12-12 11:57:41 +0800, Craig Ringer wrote:
But that'd have
the disadvanatage that it possibly would take a while till the
MemoryContextStats() is executed. Not sure if that's still good enough
for you?

Definitely. Sure, it won't be perfect, but it'd be a big improvement on what
we have.

If this would be fine enough, why not giving a shot then? Having to
use gdb now on production systems is something sometimes hard to
justify to customers. There are also the Windows problems...

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

I think the reason it prints to stderr now is that it's intended to run in
OOM situations.

Yep. I am on board with Tom here that this property should not be thrown away.
--
Michael

On 13 December 2017 at 12:10, Michael Paquier <michael.paquier@gmail.com>
wrote:

On Mon, Dec 11, 2017 at 10:07 PM, Craig Ringer <craig@2ndquadrant.com>
wrote:

On 12 December 2017 at 12:43, Andres Freund <andres@anarazel.de> wrote:

On 2017-12-12 11:57:41 +0800, Craig Ringer wrote:
But that'd have
the disadvanatage that it possibly would take a while till the
MemoryContextStats() is executed. Not sure if that's still good enough
for you?

Definitely. Sure, it won't be perfect, but it'd be a big improvement on

what

we have.

If this would be fine enough, why not giving a shot then? Having to
use gdb now on production systems is something sometimes hard to
justify to customers. There are also the Windows problems...

Another question is whether printing to stderr, bypassing proper
logging!, is good enough for something like this.

I think the reason it prints to stderr now is that it's intended to run

in

OOM situations.

Yep. I am on board with Tom here that this property should not be thrown
away.

OK, so I think I'll do pretty much what I outlined above, using stringinfo
for the !OOM case and fprintf for the OOM case, via callback, roughly as
outlined upthread. I won't bother with elog, it's easy enough if someone
cares.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Another simpler option would be to open up a new file in the log
directory something like "debug_dump.<pid>.txt" and print whatever you
want there. Then print out a reasonable size log entry saying "Debug
dump output to file 'debug_dump.<pid>.txt'". You could provide a
function that reads such files out of the log directory or just
document how to access them using the pg_read_file().

It's not perfect but it's got most of the advantages of communicating
with the requesting process without the complexities of a DSM segment
and it's a bit more flexible too. Users can have automated monitoring
tools watch for dumps for example. And regular tools can be used to
back up and clean out old files.

On 15 December 2017 at 09:24, Greg Stark <stark@mit.edu> wrote:

Another simpler option would be to open up a new file in the log
directory

... if we have one.

We might be logging to syslog, or whatever else.

I'd rather keep it simple(ish).

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

On Thu, Dec 14, 2017 at 9:34 PM, Craig Ringer <craig@2ndquadrant.com> wrote:

On 15 December 2017 at 09:24, Greg Stark <stark@mit.edu> wrote:

Another simpler option would be to open up a new file in the log
directory

... if we have one.

We might be logging to syslog, or whatever else.

I'd rather keep it simple(ish).

+1. I still think just printing it to the log is fine.

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

On 18 December 2017 at 10:05, Robert Haas <robertmhaas@gmail.com> wrote:

On Thu, Dec 14, 2017 at 9:34 PM, Craig Ringer <craig@2ndquadrant.com>
wrote:

On 15 December 2017 at 09:24, Greg Stark <stark@mit.edu> wrote:

Another simpler option would be to open up a new file in the log
directory

... if we have one.

We might be logging to syslog, or whatever else.

I'd rather keep it simple(ish).

+1. I still think just printing it to the log is fine.

Here we go. Implemented pretty much as outlined above. A new
pg_diag_backend(pid) function sends a new
ProcSignalReason PROCSIG_DIAG_REQUEST. It's handled by
CHECK_FOR_INTERRUPTS() and logs MemoryContextStats() output to elog(...).

I didn't want to mess with the MemoryContextMethods and expose a
printf-wrapper style typedef in memnodes.h, so I went with a hook global.
It's a diagnostic routine so I don't think that's going to be a great
bother. By default it's set to write_stderr. That just writes to vfprintf
on unix so the outcome's the same as our direct use of fprintf now.

On Windows, though, using write_stderr will make Pg attempt to write memory
context dumps to the eventlog with ERROR level if running as a service with
no console. That means we vsnprintf the string into a static buffer first.
I'm not 100% convinced of the wisdom of that because it could flood the
event log, which is usually size limited by # of events and recycled. It'd
be better to write one event than write one per memory context line, but
it's not safe to do that when OOM. I lean toward this being a win: at least
Windows users should have some hope of finding out why Pg OOM'd, which
currently they don't when it runs as a service. If we don't, we should look
at using SetStdHandle to write stderr to a secondary logfile instead.

I'm happy to just add a trivial vfprintf wrapper so we preserve exactly the
same behaviour instead, but I figured I'd start with reusing write_stderr.

I'd really like to preserve the writing to elog(...) not fprintf, because
on some systems simply finding where stderr is written can be a challenge,
if it's not going to /dev/null via some detached session. Is it in
journald? In some separate log? Being captured by the logging collector
(and probably silently eaten)? Who knows!

Using elog(...) provides a log_line_prefix and other useful info to
associate the dump with the process of interest and what it's doing at the
time.

Also, an astonishing number of deployed systems I've worked with actually
don't put the pid or anything useful in log_line_prefix to make grouping up
multi-line output practical. Which is insane. But it's only PGC_SIGHUP so
fixing it is easy enough.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Hi

2017-12-19 14:44 GMT+01:00 Craig Ringer <craig@2ndquadrant.com>:

On 18 December 2017 at 10:05, Robert Haas <robertmhaas@gmail.com> wrote:

On Thu, Dec 14, 2017 at 9:34 PM, Craig Ringer <craig@2ndquadrant.com>
wrote:

On 15 December 2017 at 09:24, Greg Stark <stark@mit.edu> wrote:

Another simpler option would be to open up a new file in the log
directory

... if we have one.

We might be logging to syslog, or whatever else.

I'd rather keep it simple(ish).

+1. I still think just printing it to the log is fine.

Here we go. Implemented pretty much as outlined above. A new
pg_diag_backend(pid) function sends a new ProcSignalReason PROCSIG_DIAG_REQUEST.
It's handled by CHECK_FOR_INTERRUPTS() and logs MemoryContextStats() output
to elog(...).

I didn't want to mess with the MemoryContextMethods and expose a
printf-wrapper style typedef in memnodes.h, so I went with a hook global.
It's a diagnostic routine so I don't think that's going to be a great
bother. By default it's set to write_stderr. That just writes to vfprintf
on unix so the outcome's the same as our direct use of fprintf now.

On Windows, though, using write_stderr will make Pg attempt to write
memory context dumps to the eventlog with ERROR level if running as a
service with no console. That means we vsnprintf the string into a static
buffer first. I'm not 100% convinced of the wisdom of that because it could
flood the event log, which is usually size limited by # of events and
recycled. It'd be better to write one event than write one per memory
context line, but it's not safe to do that when OOM. I lean toward this
being a win: at least Windows users should have some hope of finding out
why Pg OOM'd, which currently they don't when it runs as a service. If we
don't, we should look at using SetStdHandle to write stderr to a secondary
logfile instead.

I'm happy to just add a trivial vfprintf wrapper so we preserve exactly
the same behaviour instead, but I figured I'd start with reusing
write_stderr.

I'd really like to preserve the writing to elog(...) not fprintf, because
on some systems simply finding where stderr is written can be a challenge,
if it's not going to /dev/null via some detached session. Is it in
journald? In some separate log? Being captured by the logging collector
(and probably silently eaten)? Who knows!

Using elog(...) provides a log_line_prefix and other useful info to
associate the dump with the process of interest and what it's doing at the
time.

Also, an astonishing number of deployed systems I've worked with actually
don't put the pid or anything useful in log_line_prefix to make grouping up
multi-line output practical. Which is insane. But it's only PGC_SIGHUP so
fixing it is easy enough.

sorry for small offtopic. Can be used this mechanism for log of executed
plan or full query?

Regards

Pavel

On Tue, Dec 19, 2017 at 8:44 AM, Craig Ringer <craig@2ndquadrant.com> wrote:

I didn't want to mess with the MemoryContextMethods and expose a
printf-wrapper style typedef in memnodes.h, so I went with a hook global.

That looks pretty grotty to me. I think if you want to elog/ereport
this, you need to pass another argument to MemoryContextStats() or add
another memory context method. This is pretty much a textbook example
of the wrong way to use a global variable, IMHO.

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