Hi, here's version 4 of the patch.
On Wed, Oct 19, 2011 at 19:34, Robert Haas <robertmh...@gmail.com> wrote:
> I think it would be safer to write this so that
> pgstat_get_crashed_backend_activity writes its answer into a
> statically allocated buffer and returns a pointer to that buffer,
> rather than using palloc. I think the current coding might lead to a
> memory leak in the postmaster
Good catch about the memory leak; I always assumed that the caller
takes care of cleaning the memory context. But looking at the code,
that doesn't seem to happen in postmaster.
Using a global buffer would waste memory in every backend, but this is
needed rarely only in postmaster. So instead I'm allocating the buffer
on stack in LogChildExit(), and pass that to
pgstat_get_crashed_backend_activity() in arguments.
I use a character array of 1024 bytes in LogChildExit() since
'track_activity_query_size' is unknown at compile time (1024 is the
default). I could have used alloca(), but doesn't seem portable or
robust with arbitrary inputs coming from GUC.
> Also, how about having CreateSharedBackendStatus store the length of
> the backend activity buffer in a global somewhere, instead of
> repeating the calculation here?
Sure, I added a BackendActivityBufferSize global to pgstat.c
> return "<command string not enabled>";
> I'd suggest that we instead return <command string not found>, and
> avoid making judgements about how things got that way.
Originally I wanted to use exact same messages as
pg_stat_get_backend_activity; but you're right, we should be as
accurate as possible. I think "<command string empty>" is better,
since it means the PID was found, but it had a zero-length activity
string.
> It's almost making me cry
> thinking about how much time this would have saved me
Thanks for your review and the generous words. :)
Regards,
Marti
From bce8e81ea4811a823ec7c3a0ad15ff63b5cd1be4 Mon Sep 17 00:00:00 2001
From: Marti Raudsepp <ma...@juffo.org>
Date: Fri, 21 Oct 2011 18:36:50 +0300
Subject: [PATCH] Log crashed backend's query (activity string)
The crashing query is often a good starting point in debugging the
cause, and much more easily accessible than core dumps.
We're extra-paranoid in reading the activity buffer since it might be
corrupt. All non-ASCII characters are replaced with '?'
Example output:
LOG: server process (PID 31451) was terminated by signal 9: Killed
DETAIL: Running query: DO LANGUAGE plpythonu 'import os;os.kill(os.getpid(),9)'
---
src/backend/postmaster/pgstat.c | 73 ++++++++++++++++++++++++++++++++++-
src/backend/postmaster/postmaster.c | 22 ++++++++--
src/backend/utils/adt/ascii.c | 34 ++++++++++++++++
src/include/pgstat.h | 2 +
src/include/utils/ascii.h | 1 +
5 files changed, 125 insertions(+), 7 deletions(-)
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index 44956c1..ba64f23 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -58,6 +58,7 @@
#include "storage/pg_shmem.h"
#include "storage/pmsignal.h"
#include "storage/procsignal.h"
+#include "utils/ascii.h"
#include "utils/guc.h"
#include "utils/memutils.h"
#include "utils/ps_status.h"
@@ -2228,6 +2229,7 @@ static PgBackendStatus *MyBEEntry = NULL;
static char *BackendClientHostnameBuffer = NULL;
static char *BackendAppnameBuffer = NULL;
static char *BackendActivityBuffer = NULL;
+static Size BackendActivityBufferSize = 0;
/*
@@ -2310,9 +2312,12 @@ CreateSharedBackendStatus(void)
}
/* Create or attach to the shared activity buffer */
- size = mul_size(pgstat_track_activity_query_size, MaxBackends);
+ BackendActivityBufferSize = mul_size(pgstat_track_activity_query_size,
+ MaxBackends);
BackendActivityBuffer = (char *)
- ShmemInitStruct("Backend Activity Buffer", size, &found);
+ ShmemInitStruct("Backend Activity Buffer",
+ BackendActivityBufferSize,
+ &found);
if (!found)
{
@@ -2751,6 +2756,70 @@ pgstat_get_backend_current_activity(int pid, bool checkUser)
return "<backend information not available>";
}
+/* ----------
+ * pgstat_get_crashed_backend_activity() -
+ *
+ * Return a string representing the current activity of the backend with
+ * the specified PID. Like the function above, but reads shared memory with
+ * the expectation that it may be corrupt. Returns either a pointer to a
+ * constant string, or writes into the 'buffer' argument and returns it.
+ *
+ * This function is only intended to be used by postmaster to report the
+ * query that crashed the backend. In particular, no attempt is made to
+ * follow the correct concurrency protocol when accessing the
+ * BackendStatusArray. But that's OK, in the worst case we'll return a
+ * corrupted message. We also must take care not to trip on ereport(ERROR).
+ *
+ * Note: return strings for special cases match pg_stat_get_backend_activity.
+ * ----------
+ */
+const char *
+pgstat_get_crashed_backend_activity(int pid, char *buffer,
+ int len)
+{
+ volatile PgBackendStatus *beentry;
+ int i;
+
+ beentry = BackendStatusArray;
+ for (i = 1; i <= MaxBackends; i++)
+ {
+ if (beentry->st_procpid == pid)
+ {
+ /* Read pointer just once, so it can't change after validation */
+ const char *activity = beentry->st_activity;
+ const char *activity_last;
+
+ /*
+ * We can't access activity pointer before we verify that it
+ * falls into BackendActivityBuffer. To make sure that the entire
+ * string including its ending is contained within the buffer,
+ * we subtract one activity length from it.
+ */
+ activity_last = BackendActivityBuffer + BackendActivityBufferSize
+ - pgstat_track_activity_query_size;
+
+ if (activity < BackendActivityBuffer ||
+ activity > activity_last)
+ return "<command string corrupt>";
+
+ if (*(activity) == '\0')
+ return "<command string empty>";
+
+ /*
+ * Copy only ASCII-safe characters so we don't run into encoding
+ * problems when reporting the message.
+ */
+ ascii_safe_strncpy(buffer, activity, len);
+
+ return buffer;
+ }
+
+ beentry++;
+ }
+
+ /* PID not found */
+ return "<backend information not available>";
+}
/* ------------------------------------------------------------
* Local support functions follow
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index dd7493c..5476975 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -2777,6 +2777,13 @@ HandleChildCrash(int pid, int exitstatus, const char *procname)
static void
LogChildExit(int lev, const char *procname, int pid, int exitstatus)
{
+ char activity_buffer[1024]; /* default track_activity_query_size */
+ const char *activity;
+
+ activity = pgstat_get_crashed_backend_activity(pid,
+ activity_buffer,
+ sizeof(activity_buffer));
+
if (WIFEXITED(exitstatus))
ereport(lev,
@@ -2784,7 +2791,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus)
translator: %s is a noun phrase describing a child process, such as
"server process" */
(errmsg("%s (PID %d) exited with exit code %d",
- procname, pid, WEXITSTATUS(exitstatus))));
+ procname, pid, WEXITSTATUS(exitstatus)),
+ errdetail("Running query: %s", activity)));
else if (WIFSIGNALED(exitstatus))
#if defined(WIN32)
ereport(lev,
@@ -2794,7 +2802,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus)
"server process" */
(errmsg("%s (PID %d) was terminated by exception 0x%X",
procname, pid, WTERMSIG(exitstatus)),
- errhint("See C include file \"ntstatus.h\" for a description of the hexadecimal value.")));
+ errhint("See C include file \"ntstatus.h\" for a description of the hexadecimal value."),
+ errdetail("Running query: %s", activity)));
#elif defined(HAVE_DECL_SYS_SIGLIST) && HAVE_DECL_SYS_SIGLIST
ereport(lev,
@@ -2804,7 +2813,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus)
(errmsg("%s (PID %d) was terminated by signal %d: %s",
procname, pid, WTERMSIG(exitstatus),
WTERMSIG(exitstatus) < NSIG ?
- sys_siglist[WTERMSIG(exitstatus)] : "(unknown)")));
+ sys_siglist[WTERMSIG(exitstatus)] : "(unknown)"),
+ errdetail("Running query: %s", activity)));
#else
ereport(lev,
@@ -2812,7 +2822,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus)
translator: %s is a noun phrase describing a child process, such as
"server process" */
(errmsg("%s (PID %d) was terminated by signal %d",
- procname, pid, WTERMSIG(exitstatus))));
+ procname, pid, WTERMSIG(exitstatus)),
+ errdetail("Running query: %s", activity)));
#endif
else
ereport(lev,
@@ -2821,7 +2832,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus)
translator: %s is a noun phrase describing a child process, such as
"server process" */
(errmsg("%s (PID %d) exited with unrecognized status %d",
- procname, pid, exitstatus)));
+ procname, pid, exitstatus),
+ errdetail("Running query: %s", activity)));
}
/*
diff --git a/src/backend/utils/adt/ascii.c b/src/backend/utils/adt/ascii.c
index 7ecf494..fda79c8 100644
--- a/src/backend/utils/adt/ascii.c
+++ b/src/backend/utils/adt/ascii.c
@@ -158,3 +158,37 @@ to_ascii_default(PG_FUNCTION_ARGS)
PG_RETURN_TEXT_P(encode_to_ascii(data, enc));
}
+
+/* ----------
+ * "Escape" a string in unknown encoding to a valid ASCII string.
+ * Replace non-ASCII bytes with '?'
+ * This must not trigger ereport(ERROR), as it is called from postmaster.
+ *
+ * Unlike C strncpy(), the result is always terminated with exactly one null
+ * byte.
+ * ----------
+ */
+void
+ascii_safe_strncpy(char *dest, const char *src, int len)
+{
+ int i;
+
+ for (i = 0; i < (len - 1); i++)
+ {
+ char ch = src[i];
+
+ if (ch == '\0')
+ break;
+ /* Keep printable ASCII characters */
+ if (32 <= ch && ch <= 127)
+ dest[i] = ch;
+ /* White-space is also OK */
+ else if (ch == '\n' || ch == '\r' || ch == '\t')
+ dest[i] = ch;
+ /* Everything else is replaced with '?' */
+ else
+ dest[i] = '?';
+ }
+
+ dest[i] = '\0';
+}
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 20c4d43..d0f1927 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -720,6 +720,8 @@ extern void pgstat_report_appname(const char *appname);
extern void pgstat_report_xact_timestamp(TimestampTz tstamp);
extern void pgstat_report_waiting(bool waiting);
extern const char *pgstat_get_backend_current_activity(int pid, bool checkUser);
+extern const char *pgstat_get_crashed_backend_activity(int pid, char *buffer,
+ int len);
extern PgStat_TableStatus *find_tabstat_entry(Oid rel_id);
extern PgStat_BackendFunctionEntry *find_funcstat_entry(Oid func_id);
diff --git a/src/include/utils/ascii.h b/src/include/utils/ascii.h
index ad70e03..adeddb5 100644
--- a/src/include/utils/ascii.h
+++ b/src/include/utils/ascii.h
@@ -16,5 +16,6 @@
extern Datum to_ascii_encname(PG_FUNCTION_ARGS);
extern Datum to_ascii_enc(PG_FUNCTION_ARGS);
extern Datum to_ascii_default(PG_FUNCTION_ARGS);
+extern void ascii_safe_strncpy(char *dest, const char *src, int len);
#endif /* _ASCII_H_ */
--
1.7.7
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
