From e44351d85f6415c0649c18e00dc92368be0bc1d6 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Wed, 7 Feb 2024 07:46:05 +0000 Subject: [PATCH v27] Add function to log backtrace of a backend --- doc/src/sgml/func.sgml | 53 +++++++ src/backend/catalog/system_functions.sql | 2 + src/backend/storage/ipc/Makefile | 1 + src/backend/storage/ipc/meson.build | 1 + src/backend/storage/ipc/procbacktrace.c | 143 +++++++++++++++++++ src/backend/storage/ipc/procsignal.c | 4 + src/backend/storage/lmgr/proc.c | 3 + src/include/catalog/pg_proc.dat | 4 + src/include/storage/procbacktrace.h | 20 +++ src/include/storage/procsignal.h | 1 + src/test/regress/expected/misc_functions.out | 51 +++++++ src/test/regress/sql/misc_functions.sql | 41 ++++++ 12 files changed, 324 insertions(+) create mode 100644 src/backend/storage/ipc/procbacktrace.c create mode 100644 src/include/storage/procbacktrace.h diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml index 6788ba8ef4..4d5a31b113 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -27186,6 +27186,24 @@ SELECT collation for ('foo' COLLATE "de_DE"); + + + + pg_log_backtrace + + pg_log_backtrace ( pid integer ) + boolean + + + Requests to log the backtrace of a backend with the specified process + ID. The backtraces will be logged to stderr. + Typically, a backtrace identifies which function a process is currently + executing, and is useful for developers to diagnose stuck processes. + This function is supported only if PostgreSQL was built with the ability + to capture backtraces, otherwise it will emit a warning. + + + @@ -27300,6 +27318,41 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560 because it may generate a large number of log messages. + + pg_log_backtrace can be used to log the backtrace of + a backend process. For example: + +postgres=# select pg_log_backtrace(pg_backend_pid()); + pg_log_backtrace +------------------ + t +(1 row) + +The backtrace will be logged as specified by the logging configuration. +For example: + +logging current backtrace of process with PID 174542: +postgres: myuser mydb [local] ALTER TABLE(HandleLogBacktraceInterrupt+0x3c)[0x55fb151249ce] +postgres: myuser postgres [local] ALTER TABLE(procsignal_sigusr1_handler+0x9e)[0x55fb15125cbc] +/lib/x86_64-linux-gnu/libc.so.6(+0x42520)[0x7fd572842520] +/lib/x86_64-linux-gnu/libc.so.6(fsync+0x17)[0x7fd57291b887] +postgres: myuser mydb [local] ALTER TABLE(pg_fsync_no_writethrough+0x2f)[0x55fb1510d18b] +postgres: myuser mydb [local] ALTER TABLE(pg_fsync+0xe0)[0x55fb1510d146] +postgres: myuser mydb [local] ALTER TABLE(FileSync+0xb2)[0x55fb1510fad6] +postgres: myuser mydb [local] ALTER TABLE(mdimmedsync+0x9e)[0x55fb1515040a] +postgres: myuser mydb [local] ALTER TABLE(smgrimmedsync+0x2b)[0x55fb1515218d] +postgres: myuser mydb [local] ALTER TABLE(+0x183d09)[0x55fb14c4ed09] +postgres: myuser mydb [local] ALTER TABLE(+0x18243a)[0x55fb14c4d43a] +postgres: myuser mydb [local] ALTER TABLE(btbuild+0x112)[0x55fb14c4ce69] +postgres: myuser mydb [local] ALTER TABLE(index_build+0x331)[0x55fb14cef750] +postgres: myuser mydb [local] ALTER TABLE(index_create+0x1212)[0x55fb14cec1ea] +postgres: myuser mydb [local] ALTER TABLE(DefineIndex+0x1a73)[0x55fb14df8f7e] +... + + One can obtain the file name and line number from the logged details by + using GDB or + addr2line in most Linux systems. + diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql index 346cfb98a0..3d8ea385fb 100644 --- a/src/backend/catalog/system_functions.sql +++ b/src/backend/catalog/system_functions.sql @@ -757,6 +757,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC; REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC; +REVOKE EXECUTE ON FUNCTION pg_log_backtrace(integer) FROM PUBLIC; + -- -- We also set up some things as accessible to standard roles. -- diff --git a/src/backend/storage/ipc/Makefile b/src/backend/storage/ipc/Makefile index d8a1653eb6..4647916ea6 100644 --- a/src/backend/storage/ipc/Makefile +++ b/src/backend/storage/ipc/Makefile @@ -18,6 +18,7 @@ OBJS = \ latch.o \ pmsignal.o \ procarray.o \ + procbacktrace.o \ procsignal.o \ shm_mq.o \ shm_toc.o \ diff --git a/src/backend/storage/ipc/meson.build b/src/backend/storage/ipc/meson.build index 5a936171f7..7b38cdd3f0 100644 --- a/src/backend/storage/ipc/meson.build +++ b/src/backend/storage/ipc/meson.build @@ -10,6 +10,7 @@ backend_sources += files( 'latch.c', 'pmsignal.c', 'procarray.c', + 'procbacktrace.c', 'procsignal.c', 'shm_mq.c', 'shm_toc.c', diff --git a/src/backend/storage/ipc/procbacktrace.c b/src/backend/storage/ipc/procbacktrace.c new file mode 100644 index 0000000000..ffb93756c9 --- /dev/null +++ b/src/backend/storage/ipc/procbacktrace.c @@ -0,0 +1,143 @@ +/*------------------------------------------------------------------------- + * + * procbacktrace.c + * Backtrace-related routines + * + * Portions Copyright (c) 1996-2024, PostgreSQL Global Development Group + * Portions Copyright (c) 1994, Regents of the University of California + * + * IDENTIFICATION + * src/backend/storage/ipc/procbacktrace.c + * + *------------------------------------------------------------------------- + */ + +#include "postgres.h" + +#ifdef HAVE_EXECINFO_H +#include +#endif + +#include "funcapi.h" +#include "miscadmin.h" +#include "storage/proc.h" +#include "storage/procarray.h" +#include "storage/procbacktrace.h" +#include "storage/procsignal.h" +#include "utils/fmgrprotos.h" + +static volatile sig_atomic_t backtrace_functions_loaded = false; + +/* + * Handle receipt of an interrupt indicating logging of current backtrace. + * + * We capture the backtrace within this signal handler itself in a safe manner. + * It is ensured that no memory allocations happen here. This function emits + * backtrace to stderr as writing to server log allocates memory, making the + * signal halder unsafe. Also, the shared library implementing the + * backtrace-related functions is preloaded to avoid memory allocations upon + * first-time loading, see LoadBacktraceFunctions. + */ +void +HandleLogBacktraceInterrupt(void) +{ + void *buf[100]; + int nframes; + +#ifndef HAVE_BACKTRACE_SYMBOLS + return; +#endif + + if (!backtrace_functions_loaded) + return; + + nframes = backtrace(buf, lengthof(buf)); + + write_stderr("logging current backtrace of process with PID %d:\n", + MyProcPid); + backtrace_symbols_fd(buf, nframes, fileno(stderr)); +} + +/* + * Load backtrace shared library. + * + * Any backtrace-related functions when called for the first time dynamically + * loads the shared library, which usually triggers a call to malloc, making + * them unsafe to use in signal handlers. This function makes backtrace-related + * functions signal-safe. + * + * Note that this function is supposed to be called in the early life of a + * process, preferably after signal handlers are setup; but not from within a + * signal handler. + */ +void +LoadBacktraceFunctions(void) +{ + void *buf[2]; + +#ifndef HAVE_BACKTRACE_SYMBOLS + return; +#endif + + if (backtrace_functions_loaded) + return; + + /* + * It is enough to call any one backtrace-related function to ensure that + * the corresponding shared library is dynamically loaded. We just load + * two most recent function calls, as we don't use the backtrace anyway. + */ + backtrace(buf, lengthof(buf)); + + backtrace_functions_loaded = true; +} + +/* + * Signal a backend to log its current backtrace. + */ +Datum +pg_log_backtrace(PG_FUNCTION_ARGS) +{ + int pid = PG_GETARG_INT32(0); + PGPROC *proc; + +#ifndef HAVE_BACKTRACE_SYMBOLS + ereport(WARNING, + errmsg("backtrace generation is not supported by this installation"), + errhint("You need to rebuild PostgreSQL using a library containing backtrace_symbols.")); + PG_RETURN_BOOL(false); +#endif + + proc = BackendPidGetProc(pid); + + /* + * BackendPidGetProc returns NULL if the pid isn't valid. + * + * Note that the proc will also be NULL if the pid refers to an auxiliary + * process or the postmaster (neither of which can be signaled via + * pg_log_backtrace() to get backtrace). + * + * XXX: It might be worth implementing it for auxiliary processes. + */ + if (proc == NULL) + { + /* + * This is just a warning so a loop-through-resultset will not abort + * if one backend terminated on its own during the run. + */ + ereport(WARNING, + (errmsg("PID %d is not a PostgreSQL backend process", pid))); + + PG_RETURN_BOOL(false); + } + + if (SendProcSignal(pid, PROCSIG_LOG_BACKTRACE, proc->backendId) < 0) + { + /* Again, just a warning to allow loops */ + ereport(WARNING, + (errmsg("could not send signal to process %d: %m", pid))); + PG_RETURN_BOOL(false); + } + + PG_RETURN_BOOL(true); +} diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c index e84619e5a5..3f1ce745af 100644 --- a/src/backend/storage/ipc/procsignal.c +++ b/src/backend/storage/ipc/procsignal.c @@ -28,6 +28,7 @@ #include "storage/ipc.h" #include "storage/latch.h" #include "storage/proc.h" +#include "storage/procbacktrace.h" #include "storage/shmem.h" #include "storage/smgr.h" #include "storage/sinval.h" @@ -658,6 +659,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS) if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT)) HandleLogMemoryContextInterrupt(); + if (CheckProcSignal(PROCSIG_LOG_BACKTRACE)) + HandleLogBacktraceInterrupt(); + if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE)) HandleParallelApplyMessageInterrupt(); diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index e5977548fe..73e0368c29 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -48,6 +48,7 @@ #include "storage/pmsignal.h" #include "storage/proc.h" #include "storage/procarray.h" +#include "storage/procbacktrace.h" #include "storage/procsignal.h" #include "storage/spin.h" #include "storage/standby.h" @@ -462,6 +463,8 @@ InitProcess(void) InitLWLockAccess(); InitDeadLockChecking(); + LoadBacktraceFunctions(); + #ifdef EXEC_BACKEND /* diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 29af4ce65d..17b95f3f35 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -12170,4 +12170,8 @@ proargtypes => 'int2', prosrc => 'gist_stratnum_identity' }, +# function to get the backtrace of server process +{ oid => '9661', descr => 'log backtrace of server process', + proname => 'pg_log_backtrace', provolatile => 'v', prorettype => 'bool', + proargtypes => 'int4', prosrc => 'pg_log_backtrace' }, ] diff --git a/src/include/storage/procbacktrace.h b/src/include/storage/procbacktrace.h new file mode 100644 index 0000000000..884bdb34ad --- /dev/null +++ b/src/include/storage/procbacktrace.h @@ -0,0 +1,20 @@ +/*------------------------------------------------------------------------- + * + * procsignal.h + * Backtrace-related routines + * + * + * Portions Copyright (c) 1996-2024, PostgreSQL Global Development Group + * Portions Copyright (c) 1994, Regents of the University of California + * + * src/include/storage/procbacktrace.h + * + *------------------------------------------------------------------------- + */ +#ifndef PROCBACKTRACE_H +#define PROCBACKTRACE_H + +extern void HandleLogBacktraceInterrupt(void); +extern void LoadBacktraceFunctions(void); + +#endif /* PROCBACKTRACE_H */ diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h index 52dcb4c2ad..a387da8379 100644 --- a/src/include/storage/procsignal.h +++ b/src/include/storage/procsignal.h @@ -36,6 +36,7 @@ typedef enum PROCSIG_BARRIER, /* global barrier interrupt */ PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */ PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */ + PROCSIG_LOG_BACKTRACE, /* ask backend to log the current backtrace */ /* Recovery conflict reasons */ PROCSIG_RECOVERY_CONFLICT_FIRST, diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out index 7c15477104..92328a4f21 100644 --- a/src/test/regress/expected/misc_functions.out +++ b/src/test/regress/expected/misc_functions.out @@ -326,6 +326,57 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) FROM regress_log_memory; DROP ROLE regress_log_memory; -- +-- pg_log_backtrace() +-- +-- Backtraces are logged to stderr and not returned to the function. +-- Furthermore, their contents can vary depending on the timing. However, +-- we can verify that the code doesn't fail, and that the permissions are +-- set properly. +CREATE ROLE regress_log_backtrace; +SELECT has_function_privilege('regress_log_backtrace', + 'pg_log_backtrace(integer)', 'EXECUTE'); -- no + has_function_privilege +------------------------ + f +(1 row) + +GRANT EXECUTE ON FUNCTION pg_log_backtrace(integer) + TO regress_log_backtrace; +SELECT has_function_privilege('regress_log_backtrace', + 'pg_log_backtrace(integer)', 'EXECUTE'); -- yes + has_function_privilege +------------------------ + t +(1 row) + +-- Suppress warnings that depend on dynamic content i.e. PID or backtrace +-- generation support. +SET client_min_messages = 'ERROR'; +SET ROLE regress_log_backtrace; +-- Backtrace is logged only for backends +SELECT pg_log_backtrace(pg_backend_pid()); + pg_log_backtrace +------------------ + t +(1 row) + +RESET ROLE; +-- Backtrace is not logged for auxiliary processes +SELECT backend_type, pg_log_backtrace(pid) FROM pg_stat_activity + WHERE backend_type IN ('checkpointer', 'walwriter', 'background writer') + ORDER BY backend_type; + backend_type | pg_log_backtrace +-------------------+------------------ + background writer | f + checkpointer | f + walwriter | f +(3 rows) + +RESET client_min_messages; +REVOKE EXECUTE ON FUNCTION pg_log_backtrace(integer) + FROM regress_log_backtrace; +DROP ROLE regress_log_backtrace; +-- -- Test some built-in SRFs -- -- The outputs of these are variable, so we can't just print their results diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql index 851dad90f4..9931c384a6 100644 --- a/src/test/regress/sql/misc_functions.sql +++ b/src/test/regress/sql/misc_functions.sql @@ -102,6 +102,47 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) DROP ROLE regress_log_memory; +-- +-- pg_log_backtrace() +-- +-- Backtraces are logged to stderr and not returned to the function. +-- Furthermore, their contents can vary depending on the timing. However, +-- we can verify that the code doesn't fail, and that the permissions are +-- set properly. +CREATE ROLE regress_log_backtrace; + +SELECT has_function_privilege('regress_log_backtrace', + 'pg_log_backtrace(integer)', 'EXECUTE'); -- no + +GRANT EXECUTE ON FUNCTION pg_log_backtrace(integer) + TO regress_log_backtrace; + +SELECT has_function_privilege('regress_log_backtrace', + 'pg_log_backtrace(integer)', 'EXECUTE'); -- yes + +-- Suppress warnings that depend on dynamic content i.e. PID or backtrace +-- generation support. +SET client_min_messages = 'ERROR'; + +SET ROLE regress_log_backtrace; + +-- Backtrace is logged only for backends +SELECT pg_log_backtrace(pg_backend_pid()); + +RESET ROLE; + +-- Backtrace is not logged for auxiliary processes +SELECT backend_type, pg_log_backtrace(pid) FROM pg_stat_activity + WHERE backend_type IN ('checkpointer', 'walwriter', 'background writer') + ORDER BY backend_type; + +RESET client_min_messages; + +REVOKE EXECUTE ON FUNCTION pg_log_backtrace(integer) + FROM regress_log_backtrace; + +DROP ROLE regress_log_backtrace; + -- -- Test some built-in SRFs -- -- 2.34.1