Re: Printing backtrace of postgres processes

On Mon, Apr 18, 2022 at 9:10 AM vignesh C <vignesh21(at)gmail(dot)com> wrote:
>
> The attached v21 patch has the changes for the same.

Thanks for the patch. Here are some comments:

1. I think there's a fundamental problem with this patch, that is, it
prints the backtrace when the interrupt is processed but not when
interrupt is received. This way, the backends/aux processes will
always have backtraces in their main loops or some processing loops
wherever CHECK_FOR_INTERRUPTS() is called [1]. What we need is
something more useful. What I think is the better way is to capture
the backtrace, call set_backtrace(), when the interrupt arrives and
then if we don't want to print it in the interrupt handler, perhaps
save it and print it in the next CFI() cycle. See some realistic and
useful backtrace [2] when I emitted the backtrace in the interrupt
handler.

2.
+ specified process ID. This function can send the request to
+ backends and auxiliary processes except the logger and statistics
+ collector. The backtraces will be logged at <literal>LOG</literal>
There's no statistics collector process any more. Please remove it.
Also remove 'the' before 'logger' to be in sync with
pg_log_backend_memory_contexts docs.

3.
+ configuration set (See <xref linkend="runtime-config-logging"/> for
Lowercase 'see' to be in sync with pg_log_backend_memory_contexts docs.

4.
+ You can obtain the file name and line number from the logged
details by using
How about 'One can obtain'?

5.
+postgres=# select pg_log_backtrace(pg_backend_pid());
+For example:
+<screen>
+2021-01-27 11:33:50.247 IST [111735] LOG: current backtrace:
A more realistic example would be better here, say walwriter or
checkpointer or some other process backtrace will be good instead of a
backend logging its pg_log_backtrace()'s call stack?

6.
Don't we need the backtrace of walreceiver? I think it'll be good to
have in ProcessWalRcvInterrupts().

7.
+ errmsg_internal("logging backtrace of PID %d", MyProcPid));
+ elog(LOG_SERVER_ONLY, "current backtrace:%s", errtrace);
Can we get rid of "current backtrace:%s" and have something similar to
ProcessLogMemoryContextInterrupt() like below?

errmsg("logging backtrace of PID %d", MyProcPid)));
errmsg("%s", errtrace);

[1]
2022-11-10 09:55:44.691 UTC [1346443] LOG: logging backtrace of PID 1346443
2022-11-10 09:55:44.691 UTC [1346443] LOG: current backtrace:
postgres: checkpointer (set_backtrace+0x46) [0x5640df9849c6]
postgres: checkpointer (ProcessLogBacktraceInterrupt+0x16)
[0x5640df7fd326]
postgres: checkpointer (CheckpointerMain+0x1a3) [0x5640df77f553]
postgres: checkpointer (AuxiliaryProcessMain+0xc9) [0x5640df77d5e9]
postgres: checkpointer (+0x436a9a) [0x5640df783a9a]
postgres: checkpointer (PostmasterMain+0xd57) [0x5640df7877e7]
postgres: checkpointer (main+0x20f) [0x5640df4a6f1f]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f4b9fe9dd90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f4b9fe9de40]
postgres: checkpointer (_start+0x25) [0x5640df4a7265]
2022-11-10 09:56:05.032 UTC [1346448] LOG: logging backtrace of PID 1346448
2022-11-10 09:56:05.032 UTC [1346448] LOG: current backtrace:
postgres: logical replication launcher (set_backtrace+0x46)
[0x5640df9849c6]
postgres: logical replication launcher
(ProcessLogBacktraceInterrupt+0x16) [0x5640df7fd326]
postgres: logical replication launcher
(ApplyLauncherMain+0x11b) [0x5640df7a253b]
postgres: logical replication launcher
(StartBackgroundWorker+0x220) [0x5640df77e270]
postgres: logical replication launcher (+0x4369f4) [0x5640df7839f4]
postgres: logical replication launcher (+0x43771d) [0x5640df78471d]
/lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f4b9feb6520]
/lib/x86_64-linux-gnu/libc.so.6(__select+0xbd) [0x7f4b9ff8f74d]
postgres: logical replication launcher (+0x43894d) [0x5640df78594d]
postgres: logical replication launcher (PostmasterMain+0xcb5)
[0x5640df787745]
postgres: logical replication launcher (main+0x20f) [0x5640df4a6f1f]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f4b9fe9dd90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f4b9fe9de40]
postgres: logical replication launcher (_start+0x25) [0x5640df4a7265]

[2]
2022-11-10 10:25:20.021 UTC [1351953] LOG: current backtrace:
postgres: ubuntu postgres [local] INSERT(set_backtrace+0x46)
[0x55c60ae069b6]
postgres: ubuntu postgres [local]
INSERT(procsignal_sigusr1_handler+0x1d8) [0x55c60ac7f4f8]
/lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f75a395c520]
/lib/x86_64-linux-gnu/libc.so.6(+0x91104) [0x7f75a39ab104]
/lib/x86_64-linux-gnu/libc.so.6(+0x9ccf8) [0x7f75a39b6cf8]
postgres: ubuntu postgres [local] INSERT(PGSemaphoreLock+0x22)
[0x55c60abfb1f2]
postgres: ubuntu postgres [local] INSERT(LWLockAcquire+0x174)
[0x55c60ac8f384]
postgres: ubuntu postgres [local] INSERT(+0x1fb778) [0x55c60a9ca778]
postgres: ubuntu postgres [local] INSERT(+0x1fb8d3) [0x55c60a9ca8d3]
postgres: ubuntu postgres [local]
INSERT(XLogInsertRecord+0x4e4) [0x55c60a9cb0c4]
postgres: ubuntu postgres [local] INSERT(XLogInsert+0xcf)
[0x55c60a9d167f]
postgres: ubuntu postgres [local] INSERT(heap_insert+0x2ca)
[0x55c60a97168a]
postgres: ubuntu postgres [local] INSERT(+0x1ab14a) [0x55c60a97a14a]
postgres: ubuntu postgres [local] INSERT(+0x33dcab) [0x55c60ab0ccab]
postgres: ubuntu postgres [local] INSERT(+0x33f10d) [0x55c60ab0e10d]
postgres: ubuntu postgres [local]
INSERT(standard_ExecutorRun+0x102) [0x55c60aadfdb2]
postgres: ubuntu postgres [local] INSERT(+0x4d48d4) [0x55c60aca38d4]
postgres: ubuntu postgres [local] INSERT(PortalRun+0x27d)
[0x55c60aca47ed]
postgres: ubuntu postgres [local] INSERT(+0x4d180f) [0x55c60aca080f]
postgres: ubuntu postgres [local] INSERT(PostgresMain+0x1eb4)
[0x55c60aca2b94]
postgres: ubuntu postgres [local] INSERT(+0x4396f8) [0x55c60ac086f8]
postgres: ubuntu postgres [local] INSERT(PostmasterMain+0xcb5)
[0x55c60ac09745]
postgres: ubuntu postgres [local] INSERT(main+0x20f) [0x55c60a928f1f]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f75a3943d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f75a3943e40]
postgres: ubuntu postgres [local] INSERT(_start+0x25) [0x55c60a929265]
2022-11-10 10:25:20.021 UTC [1351953] STATEMENT: insert into foo
select * from generate_series(1, 1000000000);
2022-11-10 10:25:20.521 UTC [1351953] LOG: logging backtrace of PID 1351953
2022-11-10 10:25:20.521 UTC [1351953] LOG: current backtrace:
postgres: ubuntu postgres [local] INSERT(set_backtrace+0x46)
[0x55c60ae069b6]
postgres: ubuntu postgres [local]
INSERT(procsignal_sigusr1_handler+0x1d8) [0x55c60ac7f4f8]
/lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f75a395c520]
postgres: ubuntu postgres [local]
INSERT(XLogInsertRecord+0x976) [0x55c60a9cb556]
postgres: ubuntu postgres [local] INSERT(XLogInsert+0xcf)
[0x55c60a9d167f]
postgres: ubuntu postgres [local] INSERT(heap_insert+0x2ca)
[0x55c60a97168a]
postgres: ubuntu postgres [local] INSERT(+0x1ab14a) [0x55c60a97a14a]
postgres: ubuntu postgres [local] INSERT(+0x33dcab) [0x55c60ab0ccab]
postgres: ubuntu postgres [local] INSERT(+0x33f10d) [0x55c60ab0e10d]
postgres: ubuntu postgres [local]
INSERT(standard_ExecutorRun+0x102) [0x55c60aadfdb2]
postgres: ubuntu postgres [local] INSERT(+0x4d48d4) [0x55c60aca38d4]
postgres: ubuntu postgres [local] INSERT(PortalRun+0x27d)
[0x55c60aca47ed]
postgres: ubuntu postgres [local] INSERT(+0x4d180f) [0x55c60aca080f]
postgres: ubuntu postgres [local] INSERT(PostgresMain+0x1eb4)
[0x55c60aca2b94]
postgres: ubuntu postgres [local] INSERT(+0x4396f8) [0x55c60ac086f8]
postgres: ubuntu postgres [local] INSERT(PostmasterMain+0xcb5)
[0x55c60ac09745]
postgres: ubuntu postgres [local] INSERT(main+0x20f) [0x55c60a928f1f]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f75a3943d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f75a3943e40]
postgres: ubuntu postgres [local] INSERT(_start+0x25) [0x55c60a929265]
2022-11-10 10:25:20.521 UTC [1351953] STATEMENT: insert into foo
select * from generate_series(1, 1000000000);
2022-11-10 10:25:21.050 UTC [1351953] LOG: logging backtrace of PID 1351953
2022-11-10 10:25:21.050 UTC [1351953] LOG: current backtrace:
postgres: ubuntu postgres [local] INSERT(set_backtrace+0x46)
[0x55c60ae069b6]
postgres: ubuntu postgres [local]
INSERT(procsignal_sigusr1_handler+0x1d8) [0x55c60ac7f4f8]
/lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f75a395c520]
/lib/x86_64-linux-gnu/libc.so.6(fdatasync+0x17) [0x7f75a3a35af7]
postgres: ubuntu postgres [local] INSERT(+0x1fb384) [0x55c60a9ca384]
postgres: ubuntu postgres [local] INSERT(+0x1fb7ef) [0x55c60a9ca7ef]
postgres: ubuntu postgres [local] INSERT(+0x1fb8d3) [0x55c60a9ca8d3]
postgres: ubuntu postgres [local]
INSERT(XLogInsertRecord+0x4e4) [0x55c60a9cb0c4]
postgres: ubuntu postgres [local] INSERT(XLogInsert+0xcf)
[0x55c60a9d167f]
postgres: ubuntu postgres [local] INSERT(heap_insert+0x2ca)
[0x55c60a97168a]
postgres: ubuntu postgres [local] INSERT(+0x1ab14a) [0x55c60a97a14a]
postgres: ubuntu postgres [local] INSERT(+0x33dcab) [0x55c60ab0ccab]
postgres: ubuntu postgres [local] INSERT(+0x33f10d) [0x55c60ab0e10d]
postgres: ubuntu postgres [local]
INSERT(standard_ExecutorRun+0x102) [0x55c60aadfdb2]
postgres: ubuntu postgres [local] INSERT(+0x4d48d4) [0x55c60aca38d4]
postgres: ubuntu postgres [local] INSERT(PortalRun+0x27d)
[0x55c60aca47ed]
postgres: ubuntu postgres [local] INSERT(+0x4d180f) [0x55c60aca080f]
postgres: ubuntu postgres [local] INSERT(PostgresMain+0x1eb4)
[0x55c60aca2b94]
postgres: ubuntu postgres [local] INSERT(+0x4396f8) [0x55c60ac086f8]
postgres: ubuntu postgres [local] INSERT(PostmasterMain+0xcb5)
[0x55c60ac09745]
postgres: ubuntu postgres [local] INSERT(main+0x20f) [0x55c60a928f1f]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f75a3943d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f75a3943e40]
postgres: ubuntu postgres [local] INSERT(_start+0x25) [0x55c60a929265]

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com