Bruce Family

User Tools

Site Tools

Trace: • postgres_stack_traces
software:postgres_stack_traces

Differences

This shows you the differences between two versions of the page.

Link to this comparison view

Next revision		Previous revision
software:postgres_stack_traces [2025/10/23 01:00] – created timbsoftware:postgres_stack_traces [2025/10/23 01:10] (current) – timb
Line 1: Line 1:
 ====== Postgres Stack Traces ====== ====== Postgres Stack Traces ======
  
-See also [[software:Systems Monitoring]] | [[database:Database Information]], [[database:Postgres]], [[Index]]+See also [[software:Systems Monitoring]] | [[database:Database]] | [[database:Postgresql]] | [[Index]]
  
 Reference ``Matt Smiley's`` email Dated: ``23 Jan 2013`` Reference ``Matt Smiley's`` email Dated: ``23 Jan 2013``
Line 7: Line 7:
 Attached are annotated examples of: Attached are annotated examples of:
  
- * how to capture stack traces using the helper script+* how to capture stack traces using the helper script
  
- * a few tips on finding useful facts in the stack traces+* a few tips on finding useful facts in the stack traces
  
-== How to Capture ==+==== How to Capture ====
  
 <code> <code>
Line 20: Line 20:
 </code> </code>
  
-== How to Analyze ==+==== How to Analyze ====
  
- * For reference, the output files are usually ~100-1000 KB.+* For reference, the output files are usually ~100-1000 KB.
  
 <code> <code>
Line 54: Line 54:
 #4  0x0000000000612591 in ReadBuffer_common (smgr=<value optimized out>, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=11213365, mode=RBM_NORMAL, strategy=0x1665290, hit=0x7fff72cb703f "") at bufmgr.c:438 #4  0x0000000000612591 in ReadBuffer_common (smgr=<value optimized out>, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=11213365, mode=RBM_NORMAL, strategy=0x1665290, hit=0x7fff72cb703f "") at bufmgr.c:438
 ... ...
 +
 </code> </code>
  
  * There are currently 2 helper scripts to simplify and filter the stacks.  * There are currently 2 helper scripts to simplify and filter the stacks.
  
-   * ``stack_trace_filter.simplify_frames.pl``+ * ``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.  * Strips out all arguments from the function.  Does not remove other lines.  Intended as input for other filter script.
Line 64: Line 65:
  * Will consolidate at some point in the future.  * Will consolidate at some point in the future.
  
-   * ``stack_trace_filter.regexp_match_on_whole_stack.pl``+ * ``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.  * Show whole stack if any frame matches the given perl regexp.  Outputs 1 line per frame.
Line 76: Line 77:
 </code> </code>
  
- * Examples: 
  
- * Review each stack individually, but without the noise of the full stack trace output.+* Examples: 
 + 
 +* Review each stack individually, but without the noise of the full stack trace output.
  
 <code> <code>
Line 155: Line 157:
 Frame 30 PostmasterMain at postmaster.c:1121 Frame 30 PostmasterMain at postmaster.c:1121
 Frame 31 main at main.c:199 Frame 31 main at main.c:199
- 
 ... ...
 +
 </code> </code>
  
Line 162: Line 164:
  
 <code> <code>
 +
 [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' [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'
  
Line 181: Line 184:
 Frame 13 PostmasterMain at postmaster.c:1121 Frame 13 PostmasterMain at postmaster.c:1121
 Frame 14 main at main.c:199 Frame 14 main at main.c:199
 +
 </code> </code>
  
- * Aggregate frames from all stacks.  Sort by frame number.+* 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.+* This is helpful for seeing what are the most common frames among all the stacks.  Very helpful for performance profiling.
  
- * Particularly helpful for:+   * 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.+       * 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.+       * 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).+       * 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.).+  * 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.).
  
 <code> <code>
 +.
 [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 [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
 ------------------------------------------------------------------------------ ------------------------------------------------------------------------------
Line 233: Line 238:
       1 Frame 4 ResourceOwnerRelease at resowner.c:186       1 Frame 4 ResourceOwnerRelease at resowner.c:186
 ... ...
 +
 </code> </code>
  
Line 240: Line 246:
  
 <code> <code>
 +
 [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' [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'
 ------------------------------------------------------------------------------ ------------------------------------------------------------------------------
Line 270: Line 277:
      13 Frame 12 main at main.c:199      13 Frame 12 main at main.c:199
       4 Frame 14 ExecProcNode at execProcnode.c:439       4 Frame 14 ExecProcNode at execProcnode.c:439
 +
 </code> </code>
  
software/postgres_stack_traces.1761181258.txt.gz · Last modified: by timb