On Wed, Jul 21, 2021 at 10:56 PM vignesh C <vignes...@gmail.com> wrote:
>
> On Wed, Jul 21, 2021 at 3:52 PM Bharath Rupireddy
> <bharath.rupireddyforpostg...@gmail.com> wrote:
> >
> > On Tue, Jul 13, 2021 at 9:03 PM vignesh C <vignes...@gmail.com> wrote:
> > >
> > > On Wed, May 12, 2021 at 2:27 AM Robert Haas <robertmh...@gmail.com> wrote:
> > > >
> > > > Maybe we should have a role that is specifically for server debugging
> > > > type things. This kind of overlaps with Mark Dilger's proposal to try
> > > > to allow SET for security-sensitive GUCs to be delegated via
> > > > predefined roles. The exact way to divide that up is open to question,
> > > > but it wouldn't seem crazy to me if the same role controlled the
> > > > ability to do this plus the ability to set the GUCs
> > > > backtrace_functions, debug_invalidate_system_caches_always,
> > > > wal_consistency_checking, and maybe a few other things.
> > >
> > > +1 for the idea of having a new role for this. Currently I have
> > > implemented this feature to be supported only for the superuser. If we
> > > are ok with having a new role to handle debugging features, I will
> > > make a 002 patch to handle this.
> >
> > I see that there are a good number of user functions that are
> > accessible only by superuser (I searched for "if (!superuser())" in
> > the code base). I agree with the intention to not overload the
> > superuser anymore and have a few other special roles to delegate the
> > existing superuser-only functions to them. In that case, are we going
> > to revisit and reassign all the existing superuser-only functions?
>
> As Robert pointed out, this idea is based on Mark Dilger's proposal. Mark
> Dilger is already handling many of them at [1]. I'm proposing this patch only
> for server debugging functionalities based on Robert's suggestions at [2].
> [1] - https://commitfest.postgresql.org/33/3223/
> [2] -
> https://www.postgresql.org/message-id/CA%2BTgmoZz%3DK1bQRp0Ug%3D6uMGFWg-6kaxdHe6VSWaxq0U-YkppYQ%40mail.gmail.com
The previous patch was failing because of the recent test changes made
by commit 201a76183e2 which unified new and get_new_node, attached
patch has the changes to handle the changes accordingly.
Regards,
Vignesh
From e99c97e9a8356976e556fc0cc061d6c98d6b58da Mon Sep 17 00:00:00 2001
From: Vigneshwaran C <vignesh21@gmail.com>
Date: Thu, 26 Aug 2021 17:41:02 +0530
Subject: [PATCH v8] Print backtrace of specified postgres process.
The idea here is to implement & expose pg_print_backtrace function, internally
what this function does is, the connected backend will send SIGUSR1 signal by
setting PROCSIG_PRINT_BACKTRACE to postgres backend whose pid matches the
specified process id. Once the backend process receives this signal it will
print the backtrace of the process to the log file based on the logging
configuration, if logging is disabled backtrace will be printed to the
console where postmaster was started.
---
doc/src/sgml/func.sgml | 76 +++++++++++++++++++
src/backend/postmaster/autovacuum.c | 7 ++
src/backend/postmaster/interrupt.c | 8 ++
src/backend/storage/ipc/procsignal.c | 18 +++++
src/backend/storage/ipc/signalfuncs.c | 46 +++++++++++
src/backend/tcop/postgres.c | 9 +++
src/backend/utils/error/elog.c | 20 ++++-
src/backend/utils/init/globals.c | 1 +
src/include/catalog/pg_proc.dat | 5 ++
src/include/miscadmin.h | 2 +
src/include/storage/procsignal.h | 2 +
src/include/utils/elog.h | 2 +
.../t/002_print_backtrace_validation.pl | 73 ++++++++++++++++++
13 files changed, 265 insertions(+), 4 deletions(-)
create mode 100644 src/test/modules/test_misc/t/002_print_backtrace_validation.pl
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 78812b2dbe..de7d341ee0 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -24832,6 +24832,32 @@ SELECT collation for ('foo' COLLATE "de_DE");
</para></entry>
</row>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>pg_print_backtrace</primary>
+ </indexterm>
+ <function>pg_print_backtrace</function> ( <parameter>pid</parameter> <type>integer</type> )
+ <returnvalue>boolean</returnvalue>
+ </para>
+ <para>
+ Send a request to the backend with the specified process ID to log its
+ backtrace. The backtrace will be logged at message level
+ <literal>LOG</literal>. It will appear in the server log based on the
+ log configuration set (See <xref linkend="runtime-config-logging"/> for
+ more information), but will not be sent to the client regardless of
+ <xref linkend="guc-client-min-messages"/>. A backtrace will identify
+ where exactly the backend process is currently executing. This may be
+ useful to developers to diagnose stuck processes and other problems.
+ This feature is not supported for the postmaster, logger, checkpointer,
+ walwriter, background writer or statistics collector process. This
+ feature will be available if PostgreSQL was built with the ability to
+ capture backtrace. If not available, the function will return false
+ and show a WARNING. Only superusers can request backends to log their
+ backtrace.
+ </para></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -25394,6 +25420,56 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_print_backtrace</function> can be used to print backtrace of
+ a backend process. For example:
+<programlisting>
+postgres=# select pg_print_backtrace(pg_backend_pid());
+ pg_print_backtrace
+--------------------
+ t
+(1 row)
+
+The backtrace will be logged to the log file if logging is enabled, if logging
+is disabled backtrace will be logged to the console where the postmaster was
+started. For example:
+2021-01-27 11:33:50.247 IST [111735] LOG: current backtrace:
+ postgres: postgresdba postgres [local] SELECT(set_backtrace+0x38) [0xae06c5]
+ postgres: postgresdba postgres [local] SELECT(ProcessInterrupts+0x788) [0x950c34]
+ postgres: postgresdba postgres [local] SELECT() [0x761e89]
+ postgres: postgresdba postgres [local] SELECT() [0x71bbda]
+ postgres: postgresdba postgres [local] SELECT() [0x71e380]
+ postgres: postgresdba postgres [local] SELECT(standard_ExecutorRun+0x1d6) [0x71c1fe]
+ postgres: postgresdba postgres [local] SELECT(ExecutorRun+0x55) [0x71c026]
+ postgres: postgresdba postgres [local] SELECT() [0x953fc5]
+ postgres: postgresdba postgres [local] SELECT(PortalRun+0x262) [0x953c7e]
+ postgres: postgresdba postgres [local] SELECT() [0x94db78]
+ postgres: postgresdba postgres [local] SELECT(PostgresMain+0x7d7) [0x951e72]
+ postgres: postgresdba postgres [local] SELECT() [0x896b2f]
+ postgres: postgresdba postgres [local] SELECT() [0x8964b5]
+ postgres: postgresdba postgres [local] SELECT() [0x892a79]
+ postgres: postgresdba postgres [local] SELECT(PostmasterMain+0x116b) [0x892350]
+ postgres: postgresdba postgres [local] SELECT() [0x795f72]
+ /lib64/libc.so.6(__libc_start_main+0xf5) [0x7f2107bbd505]
+ postgres: postgresdba postgres [local] SELECT() [0x4842a9]
+
+</programlisting>
+ You can get the file name and line number by using gdb/addr2line in
+ linux platforms, as a prerequisite users must ensure gdb/addr2line is
+ already installed:
+<programlisting>
+1) "info line *address" from gdb on postgres executable. For example:
+gdb ./postgres
+(gdb) info line *0x71c25d
+Line 378 of "execMain.c" starts at address 0x71c25d <literal><</literal>standard_ExecutorRun+470<literal>></literal> and ends at 0x71c263 <literal><</literal>standard_ExecutorRun+476<literal>></literal>.
+OR
+2) Using "addr2line -e postgres address", For example:
+addr2line -e ./postgres 0x71c25d
+/home/postgresdba/src/backend/executor/execMain.c:378
+</programlisting>
+</para>
+
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/postmaster/autovacuum.c b/src/backend/postmaster/autovacuum.c
index 3b3df8fa8c..ce43459708 100644
--- a/src/backend/postmaster/autovacuum.c
+++ b/src/backend/postmaster/autovacuum.c
@@ -836,6 +836,13 @@ HandleAutoVacLauncherInterrupts(void)
if (ProcSignalBarrierPending)
ProcessProcSignalBarrier();
+ /* Process printing backtrace */
+ if (PrintBacktracePending)
+ {
+ PrintBacktracePending = false;
+ set_backtrace(NULL, 0);
+ }
+
/* Process sinval catchup interrupts that happened while sleeping */
ProcessCatchupInterrupt();
}
diff --git a/src/backend/postmaster/interrupt.c b/src/backend/postmaster/interrupt.c
index dd9136a942..59aff6ca02 100644
--- a/src/backend/postmaster/interrupt.c
+++ b/src/backend/postmaster/interrupt.c
@@ -21,6 +21,7 @@
#include "storage/ipc.h"
#include "storage/latch.h"
#include "storage/procsignal.h"
+#include "tcop/tcopprot.h"
#include "utils/guc.h"
volatile sig_atomic_t ConfigReloadPending = false;
@@ -41,6 +42,13 @@ HandleMainLoopInterrupts(void)
ProcessConfigFile(PGC_SIGHUP);
}
+ /* Process printing backtrace */
+ if (PrintBacktracePending)
+ {
+ PrintBacktracePending = false;
+ set_backtrace(NULL, 0);
+ }
+
if (ShutdownRequestPending)
proc_exit(0);
}
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index defb75aa26..a2863e7e8b 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -441,6 +441,21 @@ HandleProcSignalBarrierInterrupt(void)
/* latch will be set by procsignal_sigusr1_handler */
}
+/*
+ * Handle receipt of an interrupt indicating a print backtrace.
+ *
+ * Note: this is called within a signal handler! All we can do is set
+ * a flag that will cause the next CHECK_FOR_INTERRUPTS to invoke
+ * set_backtrace function which will log the backtrace.
+ */
+static void
+HandlePrintBacktraceInterrupt(void)
+{
+ InterruptPending = true;
+ PrintBacktracePending = true;
+ /* latch will be set by procsignal_sigusr1_handler */
+}
+
/*
* Perform global barrier related interrupt checking.
*
@@ -679,6 +694,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN))
RecoveryConflictInterrupt(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
+ if (CheckProcSignal(PROCSIG_PRINT_BACKTRACE))
+ HandlePrintBacktraceInterrupt();
+
SetLatch(MyLatch);
errno = save_errno;
diff --git a/src/backend/storage/ipc/signalfuncs.c b/src/backend/storage/ipc/signalfuncs.c
index de69d60e79..12df551502 100644
--- a/src/backend/storage/ipc/signalfuncs.c
+++ b/src/backend/storage/ipc/signalfuncs.c
@@ -23,6 +23,7 @@
#include "storage/pmsignal.h"
#include "storage/proc.h"
#include "storage/procarray.h"
+#include "tcop/tcopprot.h"
#include "utils/acl.h"
#include "utils/builtins.h"
@@ -298,3 +299,48 @@ pg_rotate_logfile_v2(PG_FUNCTION_ARGS)
SendPostmasterSignal(PMSIGNAL_ROTATE_LOGFILE);
PG_RETURN_BOOL(true);
}
+
+/*
+ * pg_print_backtrace - print backtrace of backend process.
+ *
+ * Only superusers can print backtrace.
+ */
+Datum
+pg_print_backtrace(PG_FUNCTION_ARGS)
+{
+#ifdef HAVE_BACKTRACE_SYMBOLS
+ int pid = PG_GETARG_INT32(0);
+ PGPROC *proc;
+
+ /* Only superusers can print back trace. */
+ if (!superuser())
+ ereport(ERROR,
+ (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+ errmsg("must be a superuser to print backtrace")));
+
+ /* BackendPidGetProc returns NULL if the pid isn't valid. */
+ proc = BackendPidGetProc(pid);
+ if (proc == NULL)
+ {
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL server process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ /*
+ * Send SIGUSR1 to postgres backend whose pid matches pid by
+ * setting PROCSIG_PRINT_BACKTRACE, the backend process will print
+ * the backtrace once the signal is received.
+ */
+ if (!SendProcSignal(pid, PROCSIG_PRINT_BACKTRACE, InvalidBackendId))
+ PG_RETURN_BOOL(true);
+ else
+ ereport(WARNING,
+ (errmsg("could not send signal to process %d: %m", pid))); /* return false below */
+#else
+ ereport(WARNING,
+ (errmsg("backtrace generation is not supported by this installation")));
+#endif
+
+ PG_RETURN_BOOL(false);
+}
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 58b5960e27..f35c42629e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3366,6 +3366,15 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+
+ /* Process printing backtrace */
+ if (PrintBacktracePending)
+ {
+ PrintBacktracePending = false;
+ ereport(LOG,
+ (errmsg("logging backtrace of PID %d", MyProcPid)));
+ set_backtrace(NULL, 0);
+ }
}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index a3e1c59a82..046ce3920b 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -172,7 +172,6 @@ static char formatted_log_time[FORMATTED_TS_LEN];
static const char *err_gettext(const char *str) pg_attribute_format_arg(1);
-static pg_noinline void set_backtrace(ErrorData *edata, int num_skip);
static void set_errdata_field(MemoryContextData *cxt, char **ptr, const char *str);
static void write_console(const char *line, int len);
static void setup_formatted_log_time(void);
@@ -949,9 +948,10 @@ errbacktrace(void)
* Compute backtrace data and add it to the supplied ErrorData. num_skip
* specifies how many inner frames to skip. Use this to avoid showing the
* internal backtrace support functions in the backtrace. This requires that
- * this and related functions are not inlined.
+ * this and related functions are not inlined. If edata pointer is valid
+ * backtrace information will be set in edata.
*/
-static void
+void
set_backtrace(ErrorData *edata, int num_skip)
{
StringInfoData errtrace;
@@ -978,7 +978,19 @@ set_backtrace(ErrorData *edata, int num_skip)
"backtrace generation is not supported by this installation");
#endif
- edata->backtrace = errtrace.data;
+ if (edata)
+ edata->backtrace = errtrace.data;
+ else
+ {
+ /*
+ * LOG_SERVER_ONLY is used intentionally to make sure this information
+ * is not sent to client based on client_min_messages. We don't want
+ * to mess up a different session as pg_print_backtrace will be
+ * sending SIGNAL to a different backend.
+ */
+ elog(LOG_SERVER_ONLY, "current backtrace:%s", errtrace.data);
+ pfree(errtrace.data);
+ }
}
/*
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 381d9e548d..bd869ebf8c 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -39,6 +39,7 @@ volatile sig_atomic_t LogMemoryContextPending = false;
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+volatile sig_atomic_t PrintBacktracePending = false;
int MyProcPid;
pg_time_t MyStartTime;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index b603700ed9..1bc679a0b5 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -11689,4 +11689,9 @@
prorettype => 'bytea', proargtypes => 'pg_brin_minmax_multi_summary',
prosrc => 'brin_minmax_multi_summary_send' },
+# function to get the backtrace of server process
+{ oid => '6105', descr => 'print backtrace of process',
+ proname => 'pg_print_backtrace', provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_print_backtrace' },
+
]
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 2e2e9a364a..011127b6c9 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -103,6 +103,8 @@ extern PGDLLIMPORT volatile uint32 InterruptHoldoffCount;
extern PGDLLIMPORT volatile uint32 QueryCancelHoldoffCount;
extern PGDLLIMPORT volatile uint32 CritSectionCount;
+extern PGDLLIMPORT volatile sig_atomic_t PrintBacktracePending;
+
/* in tcop/postgres.c */
extern void ProcessInterrupts(void);
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index eec186be2e..089b15993b 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -44,6 +44,8 @@ typedef enum
PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK,
+ PROCSIG_PRINT_BACKTRACE, /* ask backend to print the current backtrace */
+
NUM_PROCSIGNALS /* Must be last! */
} ProcSignalReason;
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index f53607e12e..c63d25716a 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -453,4 +453,6 @@ extern void set_syslog_parameters(const char *ident, int facility);
*/
extern void write_stderr(const char *fmt,...) pg_attribute_printf(1, 2);
+extern pg_noinline void set_backtrace(ErrorData *edata, int num_skip);
+
#endif /* ELOG_H */
diff --git a/src/test/modules/test_misc/t/002_print_backtrace_validation.pl b/src/test/modules/test_misc/t/002_print_backtrace_validation.pl
new file mode 100644
index 0000000000..5a5b0dc564
--- /dev/null
+++ b/src/test/modules/test_misc/t/002_print_backtrace_validation.pl
@@ -0,0 +1,73 @@
+use strict;
+use warnings;
+
+use PostgresNode;
+use TestLib;
+use Test::More tests => 2;
+use Time::HiRes qw(usleep);
+
+# Set up node with logging collector
+my $node = PostgresNode->new('primary');
+$node->init();
+$node->append_conf(
+ 'postgresql.conf', qq(
+logging_collector = on
+lc_messages = 'C'
+));
+
+$node->start();
+
+# Verify that log output gets to the file
+$node->psql('postgres', 'select pg_print_backtrace(pg_backend_pid())');
+
+# might need to retry if logging collector process is slow...
+my $max_attempts = 180 * 10;
+
+my $current_logfiles;
+for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+{
+ eval {
+ $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+ };
+ last unless $@;
+ usleep(100_000);
+}
+die $@ if $@;
+
+note "current_logfiles = $current_logfiles";
+
+like(
+ $current_logfiles,
+ qr|^stderr log/postgresql-.*log$|,
+ 'current_logfiles is sane');
+
+my $lfname = $current_logfiles;
+$lfname =~ s/^stderr //;
+chomp $lfname;
+
+my $first_logfile;
+my $bt_occurence_count;
+
+# Verify that the backtraces of the processes are logged into logfile.
+for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+{
+ $first_logfile = $node->data_dir . '/' . $lfname;
+ chomp $first_logfile;
+ print "file is $first_logfile";
+ open my $fh, '<', $first_logfile
+ or die "Could not open '$first_logfile' $!";
+ while (my $line = <$fh>)
+ {
+ chomp $line;
+ if ($line =~ m/current backtrace/)
+ {
+ $bt_occurence_count++;
+ }
+ }
+ last if $bt_occurence_count == 1;
+ usleep(100_000);
+}
+
+is($bt_occurence_count, 1, 'found expected backtrace in the log file');
+
+$node->stop();
--
2.30.2
