My Postgres Trail: February 2019

server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. The connection to the server was lost. Attempting reset: Failed.!>

$ gdb postgres core.2779 Using host libthread_db library "/lib64/libthread_db.so.1". Core was generated by `postgres: emerson postgres [local] CREATE INDEX '. Program terminated with signal 11, Segmentation fault. #0 0x000000000059487a in function (arguments) at file_name.c:527 527 bool hasnulls = TupleHasNulls(tuple);

Sometimes we see that the postgres server crashes while running some command and in this blog we shall see how to check if it caused by OOM (Out of Memory) error.

Problem:

The server crashed while I was running a command.


server closed the connection unexpectedly
 This probably means the server terminated abnormally
 before or while processing the request.
psql: FATAL:  the database system is in recovery mode

The postgres logfile showed:

2019-02-19 17:34:12.074 IST [24391] LOG:  server process (PID 24403) was terminated by signal 9: Killed

dmesg revealed that the process was killed because of OOM error:

$ dmesg
   .
   .
Out of memory: Kill process 24403 (postgres) score 832 or sacrifice child
[20631.325314] Killed process 24403 (postgres) total-vm:5252708kB, anon-rss:1605692kB, file-rss:0kB, shmem-rss:940kB
  

Debug:

Open a new psql session and get the backend process id.

postgres=# SELECT pg_backend_pid();
 pg_backend_pid
----------------
           5379
(1 row)

Attach gdb to the process. Set breakpoint at AllocSetAlloc and ignore some 100000 runs on that breakpoint

gdb -p 5379
(gdb) b AllocSetAllocBreakpoint 1 at 0xab6f49: file aset.c, line 716.
(gdb) ignore 1 99999
Will ignore next 99999 crossings of breakpoint 1.

Run the command that caused the crash and when it breaks in gdb, call MemoryContextStats.

(gdb) call MemoryContextStats(TopMemoryContext)

The output of MemoryContextStats is seen in the server logfile. A snippet is shown below:

TopPortalContext: 8192 total in 1 blocks; 7656 free (0 chunks); 536 used
    PortalContext: 5102824 total in 626 blocks; 64424 free (626 chunks); 5038400 used:
      ExecutorState: 8192 total in 1 blocks; 7152 free (0 chunks); 1040 used
        ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
      TupleSort main: 32832 total in 2 blocks; 6800 free (1 chunks); 26032 used
        Caller tuples: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
      TupleSort main: 1581120 total in 2 blocks; 6800 free (8 chunks); 1574320 used
        Caller tuples: 2097152 total in 9 blocks; 783776 free (2 chunks); 1313376 used

As seen, the PortalContext seems to be filling up. First check whether the current context where gdb had stopped is PortalContext.

(gdb) p *context
$2 = {type = T_AllocSetContext, isReset = false, allowInCritSection = false, methods = 0xd11840 ,
  parent = 0x1fa58c0, firstchild = 0x203d120, prevchild = 0x0, nextchild = 0x0, name = 0xd14150 "PortalContext",
  ident = 0x1fa9400 "", reset_cbs = 0x0}

Since I am already at the intended context, I can simply use the gdb command backtrace, to check from where memory is been allocated and then take necessary actions like using pfree on variables or switching to a temporary context or reseting the current context, etc.

If there current MemoryContext is different, then we can set a conditional breakpoint for the intended context and when gdb halts get the backtrace.

(gdb) break aset.c:717 if $_streq(context->name, "PortalContext")
Breakpoint 2 at 0xab6f47: file aset.c, line 717.

(The AllocSetAlloc starts at line number 716 in aset.c and so this breakpoint specifies the line just after it).

My Postgres Trail

Postgres Crash: Segmentation Fault

Problem:

Debug:

Postgres Crash: OOM error debug

Problem:

Debug: