Postgres C 코드에서 메모리 누수 찾기
필 이튼
2024년 3월 27일
지난주 동안 Postgres의 WAL Sender 프로세스에서 메모리 누수를 찾는 작업을 했습니다. Valgrind와 gcc/clang의 Sanitizer를 더 잘 이해하기 위해 며칠을 보냈지만, 결국 그들로부터는 유용한 결과를 얻지 못했습니다. 마침내 bcc 도구 모음에 포함된 memleak 프로그램을 발견했고, 이를 통해 문제의 원인을 바로 찾아낼 수 있었습니다.
처음 이 과정을 이해하는 데 약간 어려움이 있었기 때문에, 제가 거친 과정을 공유하고자 합니다. 이 글에서는 의도적으로 메모리 누수를 유발하는 코드를 사용해 실험합니다.
비록 Postgres에서 발생한 일이긴 하지만, 이 글에서 Postgres에 누수를 도입하여 조사를 시작한다는 점을 제외하면 이 기술들은 폭넓게 유용합니다.
특히, 이 글의 마지막에는 실행 중인 프로그램을 수정하지 않고도 메모리 누수로 이어지는 스택 트레이스를 확인하는 방법을 알 수 있습니다.
135168 bytes in 1 allocations from stack
0x0000ffff7fb7ede8 sysmalloc_mmap.isra.0+0x74 [libc.so.6]
0x0000ffff7fb7fc40 sysmalloc+0x200 [libc.so.6]
0x0000ffff7fb80fbc _int_malloc+0xdfc [libc.so.6]
0x0000ffff7fb81c50 __malloc+0x22c [libc.so.6]
0x0000fffffffff000 [unknown] [[uprobes]]
0x0000000000927714 palloc+0x40 [postgres]
0x00000000007df2f4 PostgresMain+0x1ac [postgres]
0x0000000000755f34 report_fork_failure_to_client+0x0 [postgres]
0x0000000000757e94 BackendStartup+0x1b8 [postgres]
0x000000000075805c ServerLoop+0xfc [postgres]
0x00000000007592f8 PostmasterMain+0xed4 [postgres]
0x00000000006927d8 main+0x230 [postgres]
0x0000ffff7fb109dc __libc_start_call_main+0x7c [libc.so.6]
0x0000ffff7fb10ab0 __libc_start_main@GLIBC_2.17+0x9c [libc.so.6]
0x00000000004912f0 _start+0x30 [postgres]Valgrind
컴퓨터 공학을 전공하는 학생들은 보통 프로그램에서 메모리 누수를 디버깅하기 위해 Valgrind를 사용하는 법을 배웁니다. 하지만 Valgrind는 주로 프로그램 실행 중이 아니라 종료 시점에서 누수를 검사합니다.
예를 들어, 아래와 같은 간단하고 메모리 누수가 있는 main.c 코드에서:
#include "stdio.h"
#include "string.h"
int main() {
char* x = strdup("flubber");
printf("%s\n", x);
return 1;
}Valgrind로 빌드하고 실행하면, 메모리 누수에 대해 알려줍니다:
$ gcc main.c
$ valgrind --leak-check=full ./a.out
==203008== Memcheck, a memory error detector
==203008== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==203008== Using Valgrind-3.22.0 and LibVEX; rerun with -h for copyright info
==203008== Command: ./a.out
==203008==
flubber
==203008==
==203008== HEAP SUMMARY:
==203008== in use at exit: 8 bytes in 1 blocks
==203008== total heap usage: 2 allocs, 1 frees, 1,032 bytes allocated
==203008==
==203008== 8 bytes in 1 blocks are definitely lost in loss record 1 of 1
==203008== at 0x48C0860: malloc (vg_replace_malloc.c:442)
==203008== by 0x49A8FB3: strdup (strdup.c:42)
==203008== by 0x4101FB: main (in /home/phil/tmp/a.out)
==203008==
==203008== LEAK SUMMARY:
==203008== definitely lost: 8 bytes in 1 blocks
==203008== indirectly lost: 0 bytes in 0 blocks
==203008== possibly lost: 0 bytes in 0 blocks
==203008== still reachable: 0 bytes in 0 blocks
==203008== suppressed: 0 bytes in 0 blocks
==203008==
==203008== For lists of detected and suppressed errors, rerun with: -s
==203008== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)올바르게 free(x) 호출을 추가할 수 있습니다.
#include "stdio.h"
#include "string.h"
#include "stdlib.h"
int main() {
char* x = strdup("flubber");
printf("%s\n", x);
free(x);
return 1;
}다시 빌드하고 Valgrind로 다시 실행합니다:
$ gcc main.c
$ valgrind --leak-check=full ./a.out
==203099== Memcheck, a memory error detector
==203099== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==203099== Using Valgrind-3.22.0 and LibVEX; rerun with -h for copyright info
==203099== Command: ./a.out
==203099==
flubber
==203099==
==203099== HEAP SUMMARY:
==203099== in use at exit: 0 bytes in 0 blocks
==203099== total heap usage: 2 allocs, 2 frees, 1,032 bytes allocated
==203099==
==203099== All heap blocks were freed -- no leaks are possible
==203099==
==203099== For lists of detected and suppressed errors, rerun with: -s
==203099== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)그리고 Valgrind는 실제로 누수가 없다는 것을 알려줍니다.
Arena에서의 메모리 누수
하지만 메모리를 관리하는 방법은 다양합니다. Postgres 코드에서는 보통 malloc을 직접 호출하지 않습니다. 대신, palloc을 사용하여 메모리를 MemoryContext(다른 코드베이스에서는 “arena”라고도 불림)에 할당합니다. MemoryContext는 palloc이 메모리를 가져가는 자유 메모리 덩어리이며, 이후 특정 시점에 한꺼번에 해제됩니다.
문제는 MemoryContext의 생명주기 동안 메모리 누수가 발생할 수 있다는 점입니다. 그리고 Valgrind는 이러한 누수를 쉽게 감지할 수 없습니다.
Postgres에는 메모리 컨텍스트 정보를 덤프할 수 있는 유용한 내장 메서드가 있습니다. 예를 들어, 이를 함수에 추가하거나, gdb에서 실행할 수도 있습니다:
MemoryContextStats(TopMemoryContext);그리고 메모리 컨텍스트와 모든 하위 메모리 컨텍스트에서의 메모리 할당 정보를 stderr에 출력하게 됩니다. 시간이 지남에 따라 MemoryContextStats가 출력하는 할당량 증가를 관찰하거나 추가적인 메모리 컨텍스트를 추가하면, 누수 위치를 발견할 수 있습니다.
하지만 이 호출을 명시적으로 추가하거나 gdb를 통해 사용하는 것은 꽤 수동적인 작업입니다. 메모리 할당이 증가하는 상황을 자동으로 알려주는 시스템이 있다면 훨씬 더 편리할 것입니다.
이제 Postgres에 누수를 의도적으로 삽입하고, 어디에서 누수가 발생하는지 모르는 상황을 재현하며 이를 발견하는 방법을 살펴보겠습니다.
설정
먼저 Postgres를 가져와 16.2 버전을 체크아웃하고 빌드합니다:
$ git clone https://github.com/postgres/postgres
$ cd postgres
$ git checkout REL_16_2
$ ./configure \
CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer -DUSE_VALGRIND" \
--prefix=$(pwd)/build \
--libdir=$(pwd)/build/lib \
--enable-debug
$ make && make install이 플래그들은 Valgrind를 활성화하고, 디버그 모드를 활성화하며, 전역이 아닌 로컬에 설치하도록 빌드를 설정합니다.
빌드가 완료되면 Postgres 데이터베이스를 생성할 수 있습니다:
$ ./build/bin/initdb test-db
The files belonging to this database system will be owned by user "phil".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.UTF-8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
creating directory test-db ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... America/New_York
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... ok
initdb: warning: enabling "trust" authentication for local connections
initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
Success. You can now start the database server using:
build/bin/pg_ctl -D test-db -l logfile start그런 다음 포그라운드에서 Postgres 서버를 시작합니다:
$ ./build/bin/postgres --config-file=$(pwd)/test-db/postgresql.conf -D $(pwd)/test-db -k $(pwd)/test-db
2024-03-21 16:08:10.984 EDT [213083] LOG: starting PostgreSQL 16.2 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 13.2.1 20231205 (Red Hat 13.2.1-6), 64-bit
2024-03-21 16:08:10.986 EDT [213083] LOG: listening on IPv6 address "::1", port 5432
2024-03-21 16:08:10.986 EDT [213083] LOG: listening on IPv4 address "127.0.0.1", port 5432
2024-03-21 16:08:10.987 EDT [213083] LOG: listening on Unix socket "/home/phil/tmp/postgres/test-db/.s.PGSQL.5432"
2024-03-21 16:08:10.989 EDT [213086] LOG: database system was shut down at 2024-03-21 16:07:20 EDT
2024-03-21 16:08:10.992 EDT [213083] LOG: database system is ready to accept connections두 번째 터미널에서 우리가 빌드한 psql을 사용하여 서버에 연결합니다:
./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=# select 1;
?column?
----------
1
(1 row)좋습니다! 이제 메모리 누수를 유발해 보겠습니다.
메모리 누수 유발하기
src/backend/tcop/postgres.c 파일에 있는 PostgresMain() 함수에는 거대한 루프가 있는데, 이것이 적합해 보입니다.
4417 /*
4418 * Non-error queries loop here.
4419 */
4420
4421 for (;;)
4422 {
4423 int firstchar;
4424 StringInfoData input_message;
4425
4426 #define CHUNKSIZE 4096
4427 char* waste = palloc(CHUNKSIZE);
4428 printf("%d from %d", CHUNKSIZE, getpid());다음과 같이 변경해 봅시다:
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 36cc99ec9c..28d08f3b11 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4423,6 +4423,10 @@ PostgresMain(const char *dbname, const char *username)
int firstchar;
StringInfoData input_message;
+ #define CHUNKSIZE 4096
+ char* waste = palloc(CHUNKSIZE);
+ printf("%d from %d\n", CHUNKSIZE, getpid());
+
/*
* At top of loop, reset extended-query-message flag, so that any
* errors encountered in "idle" state don't provoke skip.메인 Postgres 루프에서 메모리를 할당했기 때문에, 동일한 연결에서 하나의 연결된 클라이언트가 문(statement)을 보낼 때마다 4KB 크기의 새로운 메모리 청크가 할당됩니다.
palloc을 사용하기 때문에, 모든 메모리는 프로세스 종료 시 Valgrind가 유효하다고 간주하는 방식으로 해제됩니다. 하지만 단일 클라이언트의 생명주기 동안, 해당 연결을 처리하는 Postgres 백엔드 프로세스는 클라이언트가 문을 보낼 때마다 메모리가 계속 증가하게 됩니다.
이것이 바로 메모리 누수입니다! 극단적인 경우 클라이언트가 100만 개의 문을 보낸다면, 4KB * 1,000,000 = 4GB의 메모리가 단일 프로세스에서 할당되고, 프로세스가 종료될 때까지 해제되지 않습니다. 이는 다소 의도적인 경우이지만, 실제로 이런 상황이 발생할 수 있습니다.
Valgrind 래퍼 설정
이제 변경 사항을 반영하여 다시 빌드해 보겠습니다. 참고로, Valgrind는 이미 활성화되어 있습니다.
$ make && make installPostgres를 Valgrind로 래핑(wrap)해야 합니다. Tom Lane이 Postgres 메일링 리스트에서 이에 대한 래퍼 스크립트를 공유했는데, 이를 약간 수정해 사용했습니다. 아래 내용을 Postgres 저장소의 루트 디렉토리에 postgres.valgrind 파일로 추가하세요:
#!/usr/bin/env bash
mkdir -p $HOME/valgrind-logs
SCRIPT_DIR=$( cd -- "$( dirname -- "${BASH_SOURCE[0]}" )" &> /dev/null && pwd )
exec valgrind \
--quiet \
--show-leak-kinds=all \
--track-origins=yes \
--verbose \
--suppressions=$(realpath $SCRIPT_DIR/../../)/src/tools/valgrind.supp \
--time-stamp=yes --error-exitcode=128 --trace-children=yes \
--log-file=$HOME/valgrind-logs/%p.log \
$SCRIPT_DIR/postgres.orig "$@"참고로, 이 Valgrind 스크립트를 --leak-check=full 플래그와 함께 실행하려고도 해봤지만, 이 플래그를 사용하면 Postgres가 항상 충돌했습니다. 이유는 잘 모르겠습니다.
이제 현재 Postgres 바이너리 이름을 postgres.orig로 변경한 뒤, 이 스크립트를 새로운 Postgres 바이너리로 복사하세요:
$ mv build/bin/postgres build/bin/postgres.orig
$ chmod +x postgres.valgrind
$ cp postgres.valgrind build/bin/postgres서버를 시작합니다(다시 initdb를 실행할 필요는 없습니다):
$ ./build/bin/postgres --config-file=$(pwd)/test-db/postgresql.conf -D $(pwd)/test-db -k $(pwd)/test-db
2024-03-21 16:18:28.233 EDT [216336] LOG: starting PostgreSQL 16.2 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 13.2.1 20231205 (Red Hat 13.2.1-6), 64-bit
2024-03-21 16:18:28.234 EDT [216336] LOG: listening on IPv6 address "::1", port 5432
2024-03-21 16:18:28.234 EDT [216336] LOG: listening on IPv4 address "127.0.0.1", port 5432
2024-03-21 16:18:28.234 EDT [216336] LOG: listening on Unix socket "/home/phil/tmp/postgres/test-db/.s.PGSQL.5432"
2024-03-21 16:18:28.236 EDT [216336] LOG: database system was shut down at 2024-03-21 16:18:00 EDT
2024-03-21 16:18:28.238 EDT [216336] LOG: database system is ready to accept connections이전과 같이 psql로 연결합니다:
$ ./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=#Postgres 서버 프로세스에서 로그 라인을 바로 확인할 수 있습니다:
4096 from 216344이것이 우리가 유발한 메모리 누수입니다. 동일한 psql 프로세스에서 여러 번 SELECT 1을 실행하면:
$ ./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)서버 로그에서 동일한 수의 출력 문을 확인할 수 있습니다:
... omitted ...
2024-03-21 16:18:28.238 EDT [216336] LOG: database system is ready to accept connections
4096 from 216344
4096 from 216344
4096 from 216344
4096 from 216344
4096 from 216344이제 서버 프로세스에서 Ctrl-c를 누르면, Valgrind 로그를 확인할 수 있습니다.
$ cat ~/valgrind-logs/*
==00:00:00:00.000 216336== Memcheck, a memory error detector
==00:00:00:00.000 216336== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==00:00:00:00.000 216336== Using Valgrind-3.22.0 and LibVEX; rerun with -h for copyright info
==00:00:00:00.000 216336== Command: /home/phil/tmp/postgres/build/bin/postgres.orig --config-file=/home/phil/tmp/postgres/test-db/postgresql.conf -D /home/phil/tmp/postgres/test-db -k /home/phil/tmp/postgres/test-db
==00:00:00:00.000 216336== Parent PID: 143066
==00:00:00:00.000 216336==
==00:00:00:14.925 216336==
==00:00:00:14.925 216336== HEAP SUMMARY:
==00:00:00:14.925 216336== in use at exit: 218,493 bytes in 75 blocks
==00:00:00:14.925 216336== total heap usage: 1,379 allocs, 353 frees, 1,325,653 bytes allocated
==00:00:00:14.925 216336==
==00:00:00:14.926 216336== LEAK SUMMARY:
==00:00:00:14.926 216336== definitely lost: 410 bytes in 5 blocks
==00:00:00:14.926 216336== indirectly lost: 3,331 bytes in 45 blocks
==00:00:00:14.926 216336== possibly lost: 102,984 bytes in 8 blocks
==00:00:00:14.926 216336== still reachable: 47,148 bytes in 182 blocks
==00:00:00:14.926 216336== suppressed: 0 bytes in 0 blocks
==00:00:00:14.926 216336== Rerun with --leak-check=full to see details of leaked memory
==00:00:00:14.926 216336==
==00:00:00:14.926 216336== For lists of detected and suppressed errors, rerun with: -s
==00:00:00:14.926 216336== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)Valgrind는 단 410바이트만 확실히 손실된 것으로 발견했습니다. 클라이언트 문(statement)마다 축적된 4,096 * 5 = 20,480바이트 손실을 설명할 방법이 없습니다.
게다가 Valgrind는 매우 느립니다. Valgrind 매뉴얼에서는 다음과 같이 설명합니다:
“프로그램은 정상 실행 속도보다 훨씬 느리게 실행됩니다(예: 20~30배 느려짐), 그리고 훨씬 더 많은 메모리를 사용합니다.”
다른 방법을 시도해야 할 것 같습니다.
AddressSanitizer, LeakSanitizer
Valgrind는 2002년에 처음 등장했습니다. 하지만 2013년경 Google이 유사한 기능을 clang에 도입했고, 이후 gcc에도 포함되었습니다. 이 역사는 다소 복잡하지만, AddressSanitizer와 LeakSanitizer는 한때 독립적이었던 것으로 보이며, 현재는 AddressSanitizer에 LeakSanitizer가 포함되어 있습니다. 이를 사용하려면 단순히 코드를 -fsanitize=address 플래그로 컴파일하면 됩니다.
이제 그 간단하고 메모리 누수가 있는 main.c 프로그램으로 돌아가 봅시다:
$ cat main.c
#include "stdio.h"
#include "string.h"
#include "stdlib.h"
int main() {
char* x = strdup("flubber");
printf("%s\n", x);
return 1;
}그리고 Sanitizer를 활성화하여 컴파일하고 실행합니다:
$ gcc -fsanitize=address main.c
$ ./a.out
flubber
=================================================================
==223338==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 8 byte(s) in 1 object(s) allocated from:
#0 0xffff90c817d4 in __interceptor_strdup (/lib64/libasan.so.8+0x817d4) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x410238 in main (/home/phil/tmp/a.out+0x410238) (BuildId: e98d3e4308c692d5fedef8494d1a925d8f40759a)
#2 0xffff90a609d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#3 0xffff90a60aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0x41012c in _start (/home/phil/tmp/a.out+0x41012c) (BuildId: e98d3e4308c692d5fedef8494d1a925d8f40759a)
SUMMARY: AddressSanitizer: 8 byte(s) leaked in 1 allocation(s).좋아요, 완벽하네요. Valgrind를 사용하고 래퍼를 요구하는 것보다 훨씬 간단합니다. 누수 감지 기능이 바이너리에 바로 내장되어 있습니다.
Postgres에서의 테스트
이제 Postgres에서 이를 시도해 봅시다.
이전에 클론한 Postgres Git 저장소로 돌아가면, 클라이언트 문(statement)마다 메모리가 누수되도록 수정된 변경사항(diff)이 적용되어 있다는 점을 기억하세요.
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 36cc99ec9c..28d08f3b11 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4423,6 +4423,10 @@ PostgresMain(const char *dbname, const char *username)
int firstchar;
StringInfoData input_message;
+ #define CHUNKSIZE 4096
+ char* waste = palloc(CHUNKSIZE);
+ printf("%d from %d\n", CHUNKSIZE, getpid());
+
/*
* At top of loop, reset extended-query-message flag, so that any
* errors encountered in "idle" state don't provoke skip.make clean과 autoconf를 다시 실행하되, 이번에는 CFLAGS 값에 -fsanitize=address를 추가합니다. 그런 다음 다시 빌드합니다.
$ make clean
$ ./configure \
CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer -fsanitize=address" \
--prefix=$(pwd)/build \
--libdir=$(pwd)/build/lib \
--enable-debug
$ make && make install이제 Postgres 서버를 다시 실행합니다:
./build/bin/postgres --config-file=$(pwd)/test-db/postgresql.conf -D $(pwd)/test-db -k $(pwd)/test-db
2024-03-22 10:31:54.724 EDT [233257] LOG: starting PostgreSQL 16.2 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 13.2.1 20231205 (Red Hat 13.2.1-6), 64-bit
2024-03-22 10:31:54.725 EDT [233257] LOG: listening on IPv6 address "::1", port 5432
2024-03-22 10:31:54.725 EDT [233257] LOG: listening on IPv4 address "127.0.0.1", port 5432
2024-03-22 10:31:54.727 EDT [233257] LOG: listening on Unix socket "/home/phil/tmp/postgres/test-db/.s.PGSQL.5432"
2024-03-22 10:31:54.731 EDT [233260] LOG: database system was interrupted; last known up at 2024-03-22 10:28:56 EDT
2024-03-22 10:31:54.740 EDT [233260] LOG: database system was not properly shut down; automatic recovery in progress
2024-03-22 10:31:54.741 EDT [233260] LOG: invalid record length at 0/1531B08: expected at least 24, got 0
2024-03-22 10:31:54.741 EDT [233260] LOG: redo is not required
2024-03-22 10:31:54.742 EDT [233258] LOG: checkpoint starting: end-of-recovery immediate wait
2024-03-22 10:31:54.793 EDT [233258] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.050 s, sync=0.001 s, total=0.052 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB; lsn=0/1531B08, redo lsn=0/1531B08
=================================================================
==233260==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 328 byte(s) in 1 object(s) allocated from:
#0 0xffffaa8e57b0 in malloc (/lib64/libasan.so.8+0xc57b0) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x10104ac in save_ps_display_args /home/phil/tmp/postgres/src/backend/utils/misc/ps_status.c:165
#2 0x9aed7c in main /home/phil/tmp/postgres/src/backend/main/main.c:91
#3 0xffffa9fb09d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0xffffa9fb0aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#5 0x4a15ac in _start (/home/phil/tmp/postgres/build/bin/postgres+0x4a15ac) (BuildId: 4cede14f9b35edbb8bf598d2efbc883c4ace6797)
SUMMARY: AddressSanitizer: 328 byte(s) leaked in 1 allocation(s).
2024-03-22 10:31:54.831 EDT [233257] LOG: startup process (PID 233260) exited with exit code 1
2024-03-22 10:31:54.831 EDT [233257] LOG: terminating any other active server processes
2024-03-22 10:31:54.831 EDT [233257] LOG: shutting down due to startup process failure
2024-03-22 10:31:54.832 EDT [233257] LOG: database system is shut down
=================================================================
==233257==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 328 byte(s) in 1 object(s) allocated from:
#0 0xffffaa8e57b0 in malloc (/lib64/libasan.so.8+0xc57b0) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x10104ac in save_ps_display_args /home/phil/tmp/postgres/src/backend/utils/misc/ps_status.c:165
#2 0x9aed7c in main /home/phil/tmp/postgres/src/backend/main/main.c:91
#3 0xffffa9fb09d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0xffffa9fb0aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#5 0x4a15ac in _start (/home/phil/tmp/postgres/build/bin/postgres+0x4a15ac) (BuildId: 4cede14f9b35edbb8bf598d2efbc883c4ace6797)
SUMMARY: AddressSanitizer: 328 byte(s) leaked in 1 allocation(s).좋습니다, 서버가 바로 충돌했습니다! 흥미롭군요.
하지만 자세히 살펴보면, 메시지는 1) 우리가 의도적으로 유발한 4096바이트 누수와는 관련이 없고, 2) 프로그램 초기화와 관련된 것으로 보이기 때문에 실제로 중요한 누수처럼 보이지 않습니다. 이러한 할당은 루프 내에 있지 않으므로 시간이 지나면서 계속 증가하지 않을 것입니다. 따라서 큰 문제는 아닙니다.
그렇다면 우리가 만든 누수는 어디에 있을까요?
기본적으로 AddressSanitizer/LeakSanitizer는 첫 번째 오류에서 프로그램을 충돌시키는 동작을 합니다. 이러한 동작은 특히 나중에 Sanitizer를 도입한 프로덕션 시스템에서는 유용하지 않을 수 있습니다. 다행히 Sanitizer에는 환경 변수로 설정할 수 있는 런타임 옵션이 있습니다.
이제 환경 변수 ASAN_OPTIONS="halt_on_error=false"를 설정하고 Postgres를 다시 실행해 봅시다:
$ ASAN_OPTIONS="halt_on_error=false" ./build/bin/postgres --config-file=$(pwd)/test-db/postgresql.conf -D $(pwd)/test-db -k $(pwd)/test-db
2024-03-22 10:38:07.588 EDT [233554] LOG: starting PostgreSQL 16.2 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 13.2.1 20231205 (Red Hat 13.2.1-6), 64-bit
2024-03-22 10:38:07.589 EDT [233554] LOG: listening on IPv6 address "::1", port 5432
2024-03-22 10:38:07.589 EDT [233554] LOG: listening on IPv4 address "127.0.0.1", port 5432
2024-03-22 10:38:07.591 EDT [233554] LOG: listening on Unix socket "/home/phil/tmp/postgres/test-db/.s.PGSQL.5432"
2024-03-22 10:38:07.595 EDT [233557] LOG: database system was shut down at 2024-03-22 10:38:06 EDT
=================================================================
==233557==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 336 byte(s) in 1 object(s) allocated from:
#0 0xffffbc6957b0 in malloc (/lib64/libasan.so.8+0xc57b0) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x10104ac in save_ps_display_args /home/phil/tmp/postgres/src/backend/utils/misc/ps_status.c:165
#2 0x9aed7c in main /home/phil/tmp/postgres/src/backend/main/main.c:91
#3 0xffffbbd609d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0xffffbbd60aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#5 0x4a15ac in _start (/home/phil/tmp/postgres/build/bin/postgres+0x4a15ac) (BuildId: 4cede14f9b35edbb8bf598d2efbc883c4ace6797)
SUMMARY: AddressSanitizer: 336 byte(s) leaked in 1 allocation(s).
2024-03-22 10:38:07.651 EDT [233554] LOG: database system is ready to accept connections좋습니다! 누수를 보고했지만 실행은 계속되었습니다. 이전처럼 psql로 연결하여 우리가 추가한 누수를 유발해 봅시다.
$ ./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)그리고 연결을 종료합니다. psql 프로세스 자체에 대한 누수 보고서를 볼 수 있을 수도 있습니다. 하지만 우리가 찾고 있는 누수는 Postgres 백엔드 프로세스에 있습니다.
2024-03-22 10:38:07.651 EDT [233554] LOG: database system is ready to accept connections
4096 from 233705
4096 from 233705
4096 from 233705
4096 from 233705
4096 from 233705
=================================================================
==233710==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 336 byte(s) in 1 object(s) allocated from:
#0 0xffffbc6957b0 in malloc (/lib64/libasan.so.8+0xc57b0) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x10104ac in save_ps_display_args /home/phil/tmp/postgres/src/backend/utils/misc/ps_status.c:165
#2 0x9aed7c in main /home/phil/tmp/postgres/src/backend/main/main.c:91
#3 0xffffbbd609d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0xffffbbd60aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#5 0x4a15ac in _start (/home/phil/tmp/postgres/build/bin/postgres+0x4a15ac) (BuildId: 4cede14f9b35edbb8bf598d2efbc883c4ace6797)
SUMMARY: AddressSanitizer: 336 byte(s) leaked in 1 allocation(s).
=================================================================
==233705==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 336 byte(s) in 1 object(s) allocated from:
#0 0xffffbc6957b0 in malloc (/lib64/libasan.so.8+0xc57b0) (BuildId: 3109905b64795755dad05d7bb29ad23633a06660)
#1 0x10104ac in save_ps_display_args /home/phil/tmp/postgres/src/backend/utils/misc/ps_status.c:165
#2 0x9aed7c in main /home/phil/tmp/postgres/src/backend/main/main.c:91
#3 0xffffbbd609d8 in __libc_start_call_main (/lib64/libc.so.6+0x309d8) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#4 0xffffbbd60aac in __libc_start_main@@GLIBC_2.34 (/lib64/libc.so.6+0x30aac) (BuildId: 8adf04071ee0060cbf618c401e50c21b9070755f)
#5 0x4a15ac in _start (/home/phil/tmp/postgres/build/bin/postgres+0x4a15ac) (BuildId: 4cede14f9b35edbb8bf598d2efbc883c4ace6797)
SUMMARY: AddressSanitizer: 336 byte(s) leaked in 1 allocation(s).하지만 우리가 의도적으로 만든 누수에 대한 정보는 없네요! 아마도 Sanitizer는 이 점에서 Valgrind와 비슷하게 작동하는 것 같습니다. 프로세스가 종료될 때 메모리가 해제되었기 때문에 누수를 감지하지 못한 것으로 보입니다. 단지 그 전에 해제되지 않았을 뿐이죠.
이 시점에서 잠시 막막한 기분이 들었습니다.
eBPF와 bcc 도구
최근 Brendan Gregg의 Systems Performance 책을 읽고 있어서, 실행 중인 프로그램의 메모리 사용량을 기록하고 할당이 어디에서 발생했는지 확인할 방법이 있는지 궁금해졌습니다. 저는 perf를 함수 프로파일링에 사용해 본 적은 있지만, 메모리 사용량 프로파일링에는 사용해 본 적이 없었습니다. 스택 트레이스를 포함한 메모리 할당을 기록하는 방법을 찾아봤지만, 뚜렷한 해결책을 찾지 못했습니다.
그래서 bpf 프로파일링을 조사하다가 Brendan Gregg의 메모리 누수 관련 페이지를 발견했습니다. 그리고 메모리 누수를 직접 식별할 수 있는 memleak.py라는 도구가 있다는 것을 알게 되었습니다!
이 도구를 사용하려면, 아직 설치하지 않았다면 bcc 도구 모음을 설치하세요. 각 배포판에서 프로그램 이름이 조금씩 다를 수 있으니, find 명령어를 사용하는 것이 가장 쉬울 수 있습니다:
$ sudo find / -name '*memleak*'
/tmp/kheaders-6.5.6-300.fc39.aarch64/include/linux/kmemleak.h
/usr/share/man/man3/curs_memleaks.3x.gz
/usr/share/man/man8/bcc-memleak.8.gz
/usr/share/bcc/tools/doc/memleak_example.txt
/usr/share/bcc/tools/memleak
/usr/src/kernels/6.7.9-200.fc39.aarch64/include/linux/kmemleak.h
/usr/src/kernels/6.7.9-200.fc39.aarch64/samples/kmemleak좋습니다, 도구가 /usr/share/bcc/tools/memleak에 있습니다.
이제 Sanitizer를 비활성화하고 Postgres를 다시 빌드해 봅시다:
$ make clean
$ ./configure \
CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer" \
--prefix=$(pwd)/build \
--libdir=$(pwd)/build/lib \
--enable-debug
$ make && make installPostgres 서버를 실행합니다:
$ ./build/bin/postgres --config-file=$(pwd)/test-db/postgresql.conf -D $(pwd)/test-db -k $(pwd)/test-db
2024-03-22 11:36:06.364 EDT [245850] LOG: starting PostgreSQL 16.2 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 13.2.1 20231205 (Red Hat 13.2.1-6), 64-bit
2024-03-22 11:36:06.364 EDT [245850] LOG: listening on IPv6 address "::1", port 5432
2024-03-22 11:36:06.364 EDT [245850] LOG: listening on IPv4 address "127.0.0.1", port 5432
2024-03-22 11:36:06.365 EDT [245850] LOG: listening on Unix socket "/home/phil/tmp/postgres/test-db/.s.PGSQL.5432"
2024-03-22 11:36:06.368 EDT [245853] LOG: database system was shut down at 2024-03-22 11:36:05 EDT
2024-03-22 11:36:06.370 EDT [245850] LOG: database system is ready to accept connectionspsql을 시작하고, 서버에서 우리의 요청을 처리하는 관련 백엔드 프로세스의 PID를 확인합니다:
$ ./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=# select pg_backend_pid();
pg_backend_pid
----------------
245858
(1 row)새 터미널 세션을 열고, psql 연결과 Postgres 서버 프로세스를 유지한 상태로 memleak 프로그램을 실행합니다:
$ sudo /usr/share/bcc/tools/memleak -p 245858
Attaching to pid 245858, Ctrl+C to quit.
[11:37:19] Top 10 stacks with outstanding allocations:
[11:37:24] Top 10 stacks with outstanding allocations:이 프로그램은 5초마다 누수를 보고하기 시작합니다.
psql 세션에서 SELECT 1 문을 계속 실행하며 누수를 더 적극적으로 유발해 봅시다:
$ ./build/bin/psql -h localhost postgres
psql (16.2)
Type "help" for help.
postgres=# select pg_backend_pid();
pg_backend_pid
----------------
245858
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)
postgres=# select 1;
?column?
----------
1
(1 row)SELECT 1 명령을 약 20~30번 실행한 후, memleak 프로그램에서 다음과 같은 보고를 확인할 수 있습니다:
135168 bytes in 1 allocations from stack
0x0000ffff7fb7ede8 sysmalloc_mmap.isra.0+0x74 [libc.so.6]
0x0000ffff7fb7fc40 sysmalloc+0x200 [libc.so.6]
0x0000ffff7fb80fbc _int_malloc+0xdfc [libc.so.6]
0x0000ffff7fb81c50 __malloc+0x22c [libc.so.6]
0x0000fffffffff000 [unknown] [[uprobes]]
0x0000000000927714 palloc+0x40 [postgres]
0x00000000007df2f4 PostgresMain+0x1ac [postgres]
0x0000000000755f34 report_fork_failure_to_client+0x0 [postgres]
0x0000000000757e94 BackendStartup+0x1b8 [postgres]
0x000000000075805c ServerLoop+0xfc [postgres]
0x00000000007592f8 PostmasterMain+0xed4 [postgres]
0x00000000006927d8 main+0x230 [postgres]
0x0000ffff7fb109dc __libc_start_call_main+0x7c [libc.so.6]
0x0000ffff7fb10ab0 __libc_start_main@GLIBC_2.17+0x9c [libc.so.6]
0x00000000004912f0 _start+0x30 [postgres]
그리고 이것이 메모리 누수입니다. 아름다운 스택 트레이스 덕분에 정확히 어디에서 발생했는지 찾을 수 있습니다.
