발생한 상황
- 여러 카프카 토픽의 Lag이 증가
- 여러 DB에서 입력 지연이 확인이 됨
- 주로 COPY FROM 구문을 사용하는 입력 구문에서 지연이 보였음
장애 복기
데이터 입력이 성능이 잘 나오지 않는 상황에서 카프카에 큐가 쌓이며 서비스 장애까지 이어졌던 상황이 발생하였습니다.
대략적으로 10,000건의 데이터를 PostgreSQL의 Bulk 방식인 COPY 구문을 사용하였는데 10초 가량 소요되고 있었고
CPU는 20%내외 메모리도 여유로운 상태여서 원인을 파악을 잘하지 못하고 서비스를 중단한 뒤 큐가 빠지는걸 기다릴 수 밖에 없었습니다.
원인을 찾기 위해 재현 환경을 구성하고 테스트를 진행하며 COPY 구문이 일반적인 INSERT와 차이가 어떤점이 있는지 확인하고자 하였습니다.
COPY 구문이 INSERT 구문보다 처리가 빠른건 일반적으로 자명한 사실이며 RING BUFFER를 사용하여 버퍼풀의 오염도 또한 낮추어주는 것을 인지하고 있었습니다. 내부 테스트에서도 INSERT로 처리속도를 따라가기 어려워 성능 테스트에서 COPY 처리를 사용하였으며 당시에는 이슈가 되지 않았습니다.
운영이 지속되면서 입력 성능이 테스트 때에 비하여 차이가 발생하고 성능 저하도 여러 인스턴스에서 동시다발적으로 발생하면서 성능이 떨어졌다가 올라갔다가 하는 모습을 빈번히 확인하여 개발팀과 데이터 생성양이 증가하였는지 확인과 DB 데이터 건수도 확인하였지만 항상 평소와 동일한 데이터 건수여서 원인을 조사하지 못하고 있었습니다.
재현 환경에서도 이슈 당시의 TPS보다 높은 상황에서 이슈 없이 데이터는 1초 내외로 정상 입력되어 해당 시점의 성능 지표를 좀 더 유심히 확인하였습니다.
눈에 보이는건 Bulk ReadTime이 전체 Duration의 약 90%를 차지한다는 점이었습니다.
Write 구문에서 ReadTime이 높은 부분이 이상하게 느껴졌는데 인덱스가 많은편인 테이블은 5개정도를 가지고 있는 경우였으며 일반적인 운영 상황에서 해당 숫자가 성능에 영향을 준다고 느끼진 못하였습니다.
어쨋든 Read를 한다는건 메모리에 올린다는 개념이라고 생각하여 pg_buffercache를 extension 하여 버퍼 캐시를 조사하였을 때 특이사항을 확인하였습니다. 이슈가 있던 여러 인스턴스에서 공통적으로 특정 컬럼 (요청의 id를 가지는 값으로 서비스에서 랜덤하게 생성)이 버퍼캐시의 많은 부분을 차지하는 것을 보았고 해당 컬럼의 데이터를 조사하였을 때 데이터가 순차 증가가아닌 상당히 랜덤하게 입력이 되는 것을 보았습니다.
이를 바탕으로 이슈 시점의 데이터를 추출하고 해당 데이터를 직접 COPY 구문을 사용하여 재현환경에서 입력을 테스트했을 때 LIVE의 이슈 상황고 동일한 처리 속도와 통계 값들을 확인할 수 있었습니다.
이슈가 있는 테이블들은 모두 사이즈가 TB 단위였고 그런 상황에서 입력을 하기위해 매번 문제가 되는 컬럼의 인덱스를 디스크에서 I/O가 발생하는 상황으로 확인되었습니다. 해당 상황을 방지하기 위해 웜업을 하기도 어려운 상황이었고 일단 개발팀의 단순 조회를 위해 생성한 인덱스를 제거하였을 때 성능이 90% 가까이 개선되었습니다.
다만 인덱스 삭제는 상당히 조건이 붙는 케이스이기에 파티션 테이블을 사용하여 테이블, 인덱스 파일당 사이즈를 줄여서 데이터 입력시 필요한 범위 사이즈를 줄이고 서비스에서 해당 컬럼을 순차 증가하는 값으로 사용할 수 있도록 개선 방향을 잡았습니다.
평소 큰 사이즈의 테이블을 운영할 때 적절한 쿼리 튜닝과 인덱스를 생성해둔 상태라면 인덱스 생성, 일부 컬럼 작업의 메인터넌스 작업 외엔 어려움 없이 운영할 수 있다고 생각하였는데 해당 상황을 통해 큰 사이즈의 테이블은 항상 위험성이 있고 파티션 테이블을 통해 관리하는 것이 검토가 필요하다는 교훈과 이슈 상황에서 통계, 데이터 등을 확인하는 기본을 다시 한번 상기시킬 수 있었습니다.
원인 파악간 확인한 내용
COPY FROM 구문 처리 방식
--서버 내부 처리 과정 상세 분석
1. COPY 상태 초기화 (PostgreSQL 코드 기준)
// commands/copy.c
CopyState BeginCopyFrom(ParseState *pstate, Relation rel, ...) {
CopyState cstate = (CopyState) palloc0(sizeof(CopyStateData));
// 파티션 라우팅 설정
if (rel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) {
cstate->partition_tuple_routing =
ExecSetupPartitionTupleRouting(NULL, rel);
}
// 트리거 설정
cstate->range_table = pstate->p_rtable;
// 버퍼 초기화 (기본 64KB)
cstate->raw_buf = (char *) palloc(RAW_BUF_SIZE + 1);
return cstate;
}
2. 데이터 수신 및 파싱 루프
// 메인 처리 루프
uint64 CopyFrom(CopyState cstate) {
uint64 processed = 0;
while (NextCopyFrom(cstate, econtext, values, nulls)) {
// 1. 파티션 라우팅 (필요시)
if (cstate->partition_tuple_routing) {
target_rel = ExecFindPartition(...);
}
// 2. 제약 조건 검사
ExecConstraints(resultRelInfo, slot, estate);
// 3. BEFORE 트리거 실행
if (resultRelInfo->ri_TrigDesc &&
resultRelInfo->ri_TrigDesc->trig_insert_before_row) {
slot = ExecBRInsertTriggers(estate, resultRelInfo, slot);
}
// 4. 힙 삽입 (배치 최적화)
if (proute) {
heap_multi_insert(target_rel, slots, nslots, ...);
} else {
table_tuple_insert(resultRelInfo->ri_RelationDesc, slot, ...);
}
// 5. 인덱스 업데이트
if (resultRelInfo->ri_NumIndices > 0) {
ExecInsertIndexTuples(slot, estate, false, NULL, NIL);
}
// 6. AFTER 트리거 실행
ExecARInsertTriggers(estate, resultRelInfo, slot, NIL);
processed++;
}
return processed;
}
3. 버퍼 관리 및 I/O 최적화
클라이언트 버퍼링: 네트워크 왕복 최소화
서버 버퍼링: 파싱 효율성과 배치 처리
--POSTGRESQL.C
// 서버 측 버퍼 관리
#define RAW_BUF_SIZE 65536 // 64KB 기본 버퍼
static bool CopyLoadRawBuf(CopyState cstate) {
int bytesread = CopyGetData(cstate, cstate->raw_buf,
1, RAW_BUF_SIZE);
// 네트워크에서 데이터 수신
// EOF 처리
// 에러 상황 처리
}
--PGX
// PGX는 Go의 io.Writer 인터페이스 활용
type copyFromWriter struct {
conn *Conn
buf []byte
maxBuf int
}
func (w *copyFromWriter) Write(p []byte) (int, error) {
// 버퍼가 가득 차면 플러시
if len(w.buf) + len(p) > w.maxBuf {
if err := w.flush(); err != nil {
return 0, err
}
}
w.buf = append(w.buf, p...)
return len(p), nil
}
--blk_read_time이 높은 이유
--인덱스 탐색 비용
// btree 인덱스 삽입시 발생하는 읽기
Datum bt_insert(Relation rel, Datum *values, bool *isnull, ...) {
// 루트에서 리프까지 경로 탐색
while (!P_ISLEAF(opaque)) {
// 각 레벨마다 페이지 읽기 발생
page = BufferGetPage(ReadBuffer(rel, blkno));
}
// UNIQUE 제약시 중복 검사로 추가 읽기
if (checkUnique != UNIQUE_CHECK_NO) {
// 기존 키 존재 여부 확인
}
}
--Free Space Map 조회
// 힙 페이지 선택시 FSM 읽기
static Buffer GetPageWithFreeSpace(Relation relation, Size spaceNeeded) {
BlockNumber blkno = GetPageWithFreeSpace(relation, spaceNeeded);
if (blkno != InvalidBlockNumber) {
// FSM에서 추천한 페이지 읽기
buffer = ReadBuffer(relation, blkno);
}
}
원인 파악
여러 성능 저하 테이블 중 테이블 A에 대한 통계
| 시점 | Hit rate (%) | rows | AVG Block Hit | AVG Block Read | Total Latency | Read Latency |
| 이슈 이전 | 98.7 | 1,080 | 12,520 | 172 | 203 | 183 |
| 이슈 시점 | 94.21 | 7,740 | 98,540 | 6,500 | 5,230 | 5,081 |
| 스펙 증설 직후 | 91.52 | 10,000 | 112,550 | 10,430 | 14,520 | 14,333 |
원인 확인을 위한 내용
--스키마 정보
Table "public.TABLEA"
Column | Type | Collation | Nullable | Default | Storage | Compression | Stats target | Description
---------------+-----------------------------+-----------+----------+----------------------------------------------------+----------+-------------+--------------+-------------
PK | bigint | | not null | nextval(' '::regclass) | plain | | |
COLA | character varying(255) | | not null | | extended | | |
COLD | character varying(150) | | not null | | extended | | |
JSONCOLA | json | | not null | | extended | | |
JSONCOLB | json | | not null | | extended | | |
COLC | boolean | | not null | | plain | | |
COLB | timestamp without time zone | | not null | | plain | | |
created_at | timestamp with time zone | | | CURRENT_TIMESTAMP | plain | | |
Indexes:
"TABLEA_pk_PK" PRIMARY KEY, btree (core_log_sn)
"TABLEA_nc_COLA_COLB" btree (COLA, COLB)
"TABLEA_nc_COLC_COLD_COLB" btree (COLC, COLD, COLB) WHERE COLC = false
"TABLEA_nc_COLB" btree (COLB)
"TABLEA_nc_COLD_COLB" btree (COLD,COLB)
Access method: heap
Options: autovacuum_vacuum_insert_scale_factor=0.2, autovacuum_vacuum_insert_threshold=1000
TABLEA 2109 GB 5,861,586,332
TABLEA_nc_COLA_COLB 419 GB
TABLEA_nc_COLC_COLD_COLB 656 kB
TABLEA_nc_COLB 123 GB
TABLEA_nc_COLD_COLB 1036 GB
TABLEA_pk_PK 123 GB
--버퍼 캐시 상태
nspname | relname | buffers
---------+-----------------------------------------------+---------
public | TABLEA | 105570
public | TABLEA_nc_COLA_COLB | 82964
public | TABLEA_pk_PK | 41973
public | TABLEA_nc_COLC_COLD_COLB | 449
public | TABLEA_nc_COLB | 369
--STEP 1 COPY FROM 입력
--통계
latency, blks_hit, blks_read
18152, 160772, 12157
--버퍼캐시 변화
nspname | relname | buffers
---------+-----------------------------------------------+---------
public | TABLEA | 106064
public | TABLEA_nc_COLA_COLB | 95167
public | TABLEA_pk_PK | 42001
public | TABLEA_nc_COLC_COLD_COLB | 485
public | TABLEA_nc_COLB | 397
--STEP 2 동일 데이터 COPY FROM 입력
--버퍼캐시 변화
nspname | relname | buffers
---------+-----------------------------------------------+---------
public | TABLEA | 106565
public | TABLEA_nc_COLA_COLB | 95167
public | TABLEA_pk_PK | 42028
public | TABLEA_nc_COLC_COLD_COLB | 494
public | TABLEA_nc_COLB | 412
--통계
latency, blks_hit, blks_read
864, 172,651, 43
--STEP 3 인덱스 삭제 drop index TABLEA_nc_COLA_COLB;
nspname | relname | buffers
---------+-----------------------------------------------+---------
public | TABLEA | 106565
public | TABLEA_pk_PK | 42028
public | TABLEA_nc_COLC_COLD_COLB | 494
public | TABLEA_nc_COLB | 412
--STEP 4 COPY FROM 입력
--버퍼캐시 변화
nspname | relname | buffers
---------+-----------------------------------------------+---------
public | TABLEA | 107061
public | TABLEA_pk_PK | 42055
public | TABLEA_nc_COLC_COLD_COLB | 516
public | TABLEA_nc_COLB | 434
--통계
latency, blks_hit, blks_read
541, 122,220, 33
COLA 데이터 입력 상태 (데이터는 유사 패턴으로 수정 (최근 10,000건 pk 기준 정렬 조회)
12532940345123
2144365475454213435
673454745734643
asdeg41232145355
hrr32r9382930342390
3052i9532u9032
...
35434235353532
341253647346438
5632432643734535
...
53326843892503409
TXIDd36ed6q5qnbc
3904849213038
...
23563457568653453245
2353213434578658453efegy65i8ewdw23124352
13534653214545u6yewlcmsaiodj3
3254643923058643906
23t5u4fjioegh849uy402
tx6t321e154532tejwkqn35324
app-web1243920t24qewru2390r3029
46230e821re83290fu31
tx3264362313412362623
...
34y5g23df3f32f
3256436758976546t4te
tx12433264346532r3fr3
1245325136t4y3gf4f42
...
--16버전에서 테스트
--pg_stat_io 확인
backend_type | object | context | reads | read_time | writes | write_time | writebacks | writeback_time | extends | extend_time | op_bytes | hits | evictions | reuses | fsyncs | fsync_time | stats_reset
---------------------+---------------+-----------+-------+-----------+--------+------------+------------+----------------+---------+-------------+----------+------+-----------+--------+--------+------------+-------------------------------
client backend | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | bulkwrite | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | normal | 9 | 16.042 | 0 | 0 | | | 0 | 0 | 8192 | 107 | 0 | | | | 2025-10-01 06:54:18.840935+00
client backend | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background worker | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | bulkwrite | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background worker | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background writer | relation | normal | | | 0 | 0 | | | | | 8192 | | | | | | 2025-10-01 06:54:18.840935+00
hits : Shared Buffer에서 원하는 Block을 찾은 횟수
evictions : 새로운 블록을 위해 공간 확보를 한 횟수
--COPY 이후
--통계
calls | total_exec_time | min_exec_time | max_exec_time | mean_exec_time | stddev_exec_time | rows | shared_blks_hit | shared_blks_read | shared_blks_dirtied | shared_blks_written | local_blks_hit | local_blks_read | local_blks_dirtied | local_blks_written | temp_blks_read | temp_blks_written | blk_read_time | blk_write_time | wal_records | wal_fpi | wal_bytes
1 | 41781.52254 | 41781.52254 | 41781.52254 | 41781.52254 | 0 | 10000 | 217448 | 23968 | 0 | 390 | 0 | 0 | 0 | 0 | 0 | 0 | 40514.479561 | 2.221663 | 0 | 0 | 0
--pg_stat_io 확인
--버퍼를 다른 테이블로 채운 후
backend_type | object | context | reads | read_time | writes | write_time | writebacks | writeback_time | extends | extend_time | op_bytes | hits | evictions | reuses | fsyncs | fsync_time | stats_reset
---------------------+---------------+-----------+-------+-----------+--------+------------+------------+----------------+---------+-------------+----------+--------+-----------+--------+--------+------------+-------------------------------
client backend | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
client backend | relation | bulkwrite | 142 | 240.768 | 0 | 0 | | | 256 | 0.37 | 8192 | 81 | 398 | 0 | | | 2025-10-01 05:27:42.706244+00
client backend | relation | normal | 23614 | 39004.805 | 0 | 0 | | | 123 | 1.673 | 8192 | 208590 | 23738 | | | | 2025-10-01 05:27:42.706244+00
client backend | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
client backend | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
client backend | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 05:27:42.706244+00
background worker | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
background worker | relation | bulkwrite | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
background worker | relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 05:27:42.706244+00
background worker | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
background worker | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 05:27:42.706244+00
background worker | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 05:27:42.706244+00
background writer | relation | normal | | | 0 | 0 | | | | | 8192 | | | | | | 2025-10-01 05:27:42.706244+00
--버퍼를 초기화 한 후 (클러스터 재시작)
client backend | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | bulkwrite | 175 | 284.036 | 0 | 0 | | | 256 | 0.397 | 8192 | 48 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | normal | 23814 | 40274.052 | 0 | 0 | | | 134 | 1.823 | 8192 | 219058 | 0 | | | | 2025-10-01 06:54:18.840935+00
client backend | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
client backend | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background worker | relation | bulkread | 0 | 0 | 0 | 0 | | | | | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | bulkwrite | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background worker | relation | index | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | relation | vacuum | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | 0 | | | 2025-10-01 06:54:18.840935+00
background worker | temp relation | normal | 0 | 0 | 0 | 0 | | | 0 | 0 | 8192 | 0 | 0 | | | | 2025-10-01 06:54:18.840935+00
background writer | relation | normal | | | 0 | 0 | | | | | 8192 | | | | | | 2025-10-01 06:54:18.840935+00
checkpointer | relation | normal | | | 0 | 0 | | | | | 8192 | | | | | | 2025-10-01 06:54:18.840935+00
--버퍼 확인
--버퍼를 다른 테이블로 채운 후
nspname | relname | buffers
---------+---------------------------------------------------+---------
public | 문제가 되는 컬럼이 있는 인덱스 1 | 11810
public | 문제가 되는 컬럼이 있는 인덱스 2 | 11472
public | 테이블 | 623
public | 일반인덱스1 | 80
public | 일반인덱스2 | 80
public | 일반인덱스3 | 32
public | 일반인덱스4 | 1
--버퍼를 초기화 한 후 (클러스터 재시작)
nspname | relname | buffers
---------+---------------------------------------------------+---------
public | 문제가 되는 컬럼이 있는 인덱스 1 | 11838
public | 문제가 되는 컬럼이 있는 인덱스 2 | 11476
public | 테이블 | 879
public | 일반인덱스1 | 83
public | 일반인덱스2 | 83
public | 일반인덱스3 | 32
--> Evction 으로 인한 성능 저하가 눈에 띄게 더 발생하진 않음
테이블A : 2,109GB 5,861,586,332 건 데이터
제거 인덱스 : 컬럼A+B 복합인덱스 (419GB) (A : VARCHAR(255), B : timestamp)
재현 테스트 (1만건 COPY FROM 입력)
| Hit rate (%) |
버퍼 캐시 조회 (블록 수) | 디스크 조회(블록 수) | Latency (ms) | |
| 인덱스 삭제 전 | 92 | 160,772 | 12,157 | 18,152 |
| 인덱스 삭제 후 | 99 | 122,220 | 33 | 541 |
'공부 > DATABASE' 카테고리의 다른 글
| [Aurora Postgresql] VACUUM 정리 (0) | 2025.10.08 |
|---|---|
| [Aurora PostgreSQL] 성능 개선 도우미(PI), pg_stat_statements 지표 (0) | 2025.10.08 |
| [Aurora, Elasticache] 대역폭 관련 (0) | 2025.10.08 |
| [Aurora PostgreSQL] Toast 테이블과 VACUUM (0) | 2025.10.08 |
| [ElastiCache] 실시간 알람을 위한 PUB/SUB (0) | 2025.10.08 |