====== Postgres Stack Traces ====== See also [[database:database|Database Engines]], [[database:postgresql]] Reference Matt Smiley's email Dated: 23 Jan 2013 Attached are annotated examples of: * how to capture stack traces using the helper script * a few tips on finding useful facts in the stack traces ===== How to Capture ===== # Capture stack traces for all non-idle postgres processes. # Must run as user "postgres". May run from a couple seconds to a couple minutes depending on system load. [postgres@db04.prd ~]$ ~/bin/capture_stack_traces_from_nonidle_postgres_pids.sh > /db/scratch/stack_traces.$(date '+%Y%m%d_%H%M%S').out ===== How to Analyze ===== * For reference, the output files are usually ~100-1000 KB. [postgres@db04.prd ~]$ ls -l /db/scratch/stack_traces.20130116_165754.out -rw-r--r--. 1 postgres postgres 123111 Jan 16 16:58 /db/scratch/stack_traces.20130116_165754.out [postgres@db04.prd ~]$ wc -l /db/scratch/stack_traces.20130116_165754.out 2365 /db/scratch/stack_traces.20130116_165754.out [postgres@db04.prd ~]$ less /db/scratch/stack_traces.20130116_165754.out ---------------------------------------------------------------------------------- Start time: 2013-01-16 16:57:54 16:57:54 up 32 days, 14:38, 6 users, load average: 19.64, 21.55, 25.68 Stack trace for PID: 8239 [Thread debugging using libthread_db enabled] 0x00007fac158d3360 in __read_nocancel () from /lib64/libc.so.6 Thread 1 (Thread 0x7fac171f97c0 (LWP 8239)): #0 0x00007fac158d3360 in __read_nocancel () from /lib64/libc.so.6 No symbol table info available. #1 0x00000000006157dd in read (file=, buffer=0x7fab76fae740 "\313\022", amount=8192) at /usr/include/bits/unistd.h:45 No locals. #2 FileRead (file=, buffer=0x7fab76fae740 "\313\022", amount=8192) at fd.c:1191 returnCode = 0 #3 0x000000000062d622 in mdread (reln=, forknum=, blocknum=11213365, buffer=0x7fab76fae740 "\313\022") at md.c:640 seekpos = nbytes = v = 0x1568f00 __func__ = "mdread" #4 0x0000000000612591 in ReadBuffer_common (smgr=, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=11213365, mode=RBM_NORMAL, strategy=0x1665290, hit=0x7fff72cb703f "") at bufmgr.c:438 ... * There are currently 2 helper scripts to simplify and filter the stacks. * ''stack\_trace\_filter.simplify\_frames.pl'' * Strips out all arguments from the function. Does not remove other lines. Intended as input for other filter script. * Will consolidate at some point in the future. * ''stack\_trace\_filter.regexp\_match\_on\_whole\_stack.pl'' * Show whole stack if any frame matches the given perl regexp. Outputs 1 line per frame. * Currently must receive input from simplify\_frames script. Must give 1 argument: a regexp (which can be empty string to match all frames). [postgres@db04.prd ~]$ ls -l ~/bin/stack_trace_filter.* -rwxr-xr-x. 1 postgres postgres 347 Jan 10 18:24 /var/lib/pgsql/bin/stack_trace_filter.regexp_match_on_whole_stack.pl -rwxr-xr-x. 1 postgres postgres 117 Jan 10 22:27 /var/lib/pgsql/bin/stack_trace_filter.simplify_frames.pl * Examples: * Review each stack individually, but without the noise of the full stack trace output. [postgres@db04.prd ~]$ cat /db/scratch/stack_traces.20130116_165754.out | /bin/stack_trace_filter.simplify_frames.pl | ~/bin/stack_trace_filter.regexp_match_on_whole_stack.pl '' | less ------------------------------------------------------------------------------ Frame 0 __read_nocancel from /lib64/libc.so.6 Frame 1 read at /usr/include/bits/unistd.h:45 Frame 2 FileRead at fd.c:1191 Frame 3 mdread at md.c:640 Frame 4 ReadBuffer_common at bufmgr.c:438 Frame 5 ReadBufferExtended at bufmgr.c:246 Frame 6 heapgetpage at heapam.c:230 Frame 7 heapgettup_pagemode at heapam.c:824 Frame 8 heap_getnext at heapam.c:1349 Frame 9 SeqNext at nodeSeqscan.c:66 Frame 10 ExecScanFetch at execScan.c:82 Frame 11 ExecScan at execScan.c:167 Frame 12 ExecProcNode at execProcnode.c:394 Frame 13 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 14 ExecHashJoin at nodeHashjoin.c:209 Frame 15 ExecProcNode at execProcnode.c:447 Frame 16 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 17 ExecHashJoin at nodeHashjoin.c:209 Frame 18 ExecProcNode at execProcnode.c:447 Frame 19 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 20 ExecHashJoin at nodeHashjoin.c:209 Frame 21 ExecProcNode at execProcnode.c:447 Frame 22 ExecSort at nodeSort.c:103 Frame 23 ExecProcNode at execProcnode.c:458 Frame 24 ExecLimit at nodeLimit.c:91 Frame 25 ExecProcNode at execProcnode.c:490 Frame 26 ExecutePlan at execMain.c:1440 Frame 27 standard_ExecutorRun at execMain.c:314 Frame 28 explain_ExecutorRun at auto_explain.c:214 Frame 29 pgss_ExecutorRun at pg_stat_statements.c:564 Frame 30 PortalRunSelect at pquery.c:943 Frame 31 PortalRun at pquery.c:787 Frame 32 exec_execute_message at postgres.c:1965 Frame 33 PostgresMain at postgres.c:4025 Frame 34 BackendRun at postmaster.c:3611 Frame 35 BackendStartup at postmaster.c:3296 Frame 36 ServerLoop at postmaster.c:1460 Frame 37 PostmasterMain at postmaster.c:1121 Frame 38 main at main.c:199 Frame 0 slot_deform_tuple at heaptuple.c:1085 Frame 1 slot_getattr at heaptuple.c:1213 Frame 2 ExecMakeFunctionResultNoSets at execQual.c:1864 Frame 3 ExecQual at execQual.c:5006 Frame 4 ExecScan at execScan.c:195 Frame 5 ExecProcNode at execProcnode.c:394 Frame 6 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 7 ExecHashJoin at nodeHashjoin.c:209 Frame 8 ExecProcNode at execProcnode.c:447 Frame 9 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 10 ExecHashJoin at nodeHashjoin.c:209 Frame 11 ExecProcNode at execProcnode.c:447 Frame 12 ExecHashJoinOuterGetTuple at nodeHashjoin.c:656 Frame 13 ExecHashJoin at nodeHashjoin.c:209 Frame 14 ExecProcNode at execProcnode.c:447 Frame 15 ExecSort at nodeSort.c:103 Frame 16 ExecProcNode at execProcnode.c:458 Frame 17 ExecLimit at nodeLimit.c:91 Frame 18 ExecProcNode at execProcnode.c:490 Frame 19 ExecutePlan at execMain.c:1440 Frame 20 standard_ExecutorRun at execMain.c:314 Frame 21 explain_ExecutorRun at auto_explain.c:214 Frame 22 pgss_ExecutorRun at pg_stat_statements.c:564 Frame 23 PortalRunSelect at pquery.c:943 Frame 24 PortalRun at pquery.c:787 Frame 25 exec_execute_message at postgres.c:1965 Frame 26 PostgresMain at postgres.c:4025 Frame 27 BackendRun at postmaster.c:3611 Frame 28 BackendStartup at postmaster.c:3296 Frame 29 ServerLoop at postmaster.c:1460 Frame 30 PostmasterMain at postmaster.c:1121 Frame 31 main at main.c:199 ... Find all stacks that contain a particular function call anywhere in the stack. If you need to see the context in which a function was called, you need more than just "grep". This gives you the whole stack, regardless of how many frames are above/below the function call you're profiling. [postgres@db04.prd ~]$ cat /db/scratch/stack_traces.20130116_165754.out | ~/bin/stack_trace_filter.simplify_frames.pl | ~/bin/stack_trace_filter.regexp_match_on_whole_stack.pl 'XLogWrite' ------------------------------------------------------------------------------ Frame 0 __fdatasync_nocancel from /lib64/libc.so.6 Frame 1 issue_xlog_fsync at xlog.c:8831 Frame 2 XLogWrite at xlog.c:1908 Frame 3 XLogFlush at xlog.c:2116 Frame 4 RecordTransactionCommit at xact.c:1086 Frame 5 CommitTransaction at xact.c:1844 Frame 6 CommitTransactionCommand at xact.c:2562 Frame 7 finish_xact_command at postgres.c:2452 Frame 8 exec_execute_message at postgres.c:1982 Frame 9 PostgresMain at postgres.c:4025 Frame 10 BackendRun at postmaster.c:3611 Frame 11 BackendStartup at postmaster.c:3296 Frame 12 ServerLoop at postmaster.c:1460 Frame 13 PostmasterMain at postmaster.c:1121 Frame 14 main at main.c:199 * Aggregate frames from all stacks. Sort by frame number. * This is helpful for seeing what are the most common frames among all the stacks. Very helpful for performance profiling. * Particularly helpful for: * Finding where a single process is spending most of its time, by capturing its stack multiple times during a single query or session, and aggregating the stack traces. Frequently occurring frames or functions indicate common places where time is spent. * Note that a function may appear in different frame numbers, depending on when the process was interrupted. * The same trick can be used on many processes if they are doing the same thing (e.g. all testtaker sessions behave similarly). * Interpreting system-call traces (strace). Strace shows how often and how long postgres is making system calls, but the next question is why are those calls prevalent. To answer that question, capture a series of stack traces and look for ones where one of the top few frames is a system call (read, recv, semop, etc.). [postgres@db04.prd ~]$ cat /db/scratch/stack_traces.20130116_165754.out | ~/bin/stack_trace_filter.simplify_frames.pl | ~/bin/stack_trace_filter.regexp_match_on_whole_stack.pl '' | sort -k2 -n | uniq -c | less ------------------------------------------------------------------------------ 22 1 Frame 0 calc_bucket at dynahash.c:755 1 Frame 0 CleanUpLock at lock.c:1092 1 Frame 0 __fdatasync_nocancel from /lib64/libc.so.6 4 Frame 0 __read_nocancel from /lib64/libc.so.6 13 Frame 0 recv from /lib64/libc.so.6 1 Frame 0 slot_deform_tuple at heaptuple.c:1065 1 Frame 0 slot_deform_tuple at heaptuple.c:1085 1 Frame 1 expand_table at dynahash.c:1252 1 Frame 1 issue_xlog_fsync at xlog.c:8831 1 Frame 1 LockReleaseAll at lock.c:1650 4 Frame 1 read at /usr/include/bits/unistd.h:45 13 Frame 1 recv at /usr/include/bits/socket2.h:45 2 Frame 1 slot_getattr at heaptuple.c:1213 2 Frame 2 ExecMakeFunctionResultNoSets at execQual.c:1864 4 Frame 2 FileRead at fd.c:1191 1 Frame 2 hash_search_with_hash_value at dynahash.c:959 1 Frame 2 ProcReleaseLocks at proc.c:665 13 Frame 2 secure_read at be-secure.c:304 1 Frame 2 XLogWrite at xlog.c:1908 2 Frame 3 ExecQual at execQual.c:5006 1 Frame 3 LookupTupleHashEntry at execGrouping.c:376 4 Frame 3 mdread at md.c:640 13 Frame 3 pq_recvbuf at pqcomm.c:816 1 Frame 3 ResourceOwnerReleaseInternal at resowner.c:266 1 Frame 3 XLogFlush at xlog.c:2116 1 Frame 4 buildSubPlanHash at nodeSubplan.c:539 2 Frame 4 ExecScan at execScan.c:195 13 Frame 4 pq_getbyte at pqcomm.c:857 4 Frame 4 ReadBuffer_common at bufmgr.c:438 1 Frame 4 RecordTransactionCommit at xact.c:1086 1 Frame 4 ResourceOwnerRelease at resowner.c:186 ... * Optionally, omit the rare frames (those occurring less than, say, 3 times). * This may make it easier to see the dominant paths, but it may also hide important details. [postgres@db04.prd ~]$ cat /db/scratch/stack_traces.20130116_165754.out | ~/bin/stack_trace_filter.simplify_frames.pl | ~/bin/stack_trace_filter.regexp_match_on_whole_stack.pl '' | sort -k2 -n | uniq -c | awk '$1 >= 3' ------------------------------------------------------------------------------ 22 4 Frame 0 __read_nocancel from /lib64/libc.so.6 13 Frame 0 recv from /lib64/libc.so.6 4 Frame 1 read at /usr/include/bits/unistd.h:45 13 Frame 1 recv at /usr/include/bits/socket2.h:45 4 Frame 2 FileRead at fd.c:1191 13 Frame 2 secure_read at be-secure.c:304 4 Frame 3 mdread at md.c:640 13 Frame 3 pq_recvbuf at pqcomm.c:816 13 Frame 4 pq_getbyte at pqcomm.c:857 4 Frame 4 ReadBuffer_common at bufmgr.c:438 4 Frame 5 ReadBufferExtended at bufmgr.c:246 13 Frame 5 SocketBackend at postgres.c:345 3 Frame 6 index_getnext at indexam.c:514 13 Frame 6 ReadCommand at postgres.c:467 3 Frame 7 IndexNext at nodeIndexscan.c:78 13 Frame 7 PostgresMain at postgres.c:3932 13 Frame 8 BackendRun at postmaster.c:3611 3 Frame 8 ExecScanFetch at execScan.c:82 13 Frame 9 BackendStartup at postmaster.c:3296 3 Frame 9 ExecScan at execScan.c:167 4 Frame 10 ExecProcNode at execProcnode.c:398 13 Frame 10 ServerLoop at postmaster.c:1460 4 Frame 11 ExecNestLoop at nodeNestloop.c:174 13 Frame 11 PostmasterMain at postmaster.c:1121 4 Frame 12 ExecProcNode at execProcnode.c:439 13 Frame 12 main at main.c:199 4 Frame 14 ExecProcNode at execProcnode.c:439