@Transactional의 해로움

들어가며: 23.12.31 Database outage

새해를 하루 앞둔 12월 31일 자정을 얼마 지나지 않아, 채널톡 서비스에 약 15분 간 지속된 서비스 장애가 발생했습니다. 00:37 ~ 00:52 시간대에 메인 데이터베이스로 사용하고 있는 RDS의 성능이 크게 저하되었으며 메인 API 서버가 함께 영향을 받아 응답 속도가 크게 떨어졌습니다. 장애 알람을 받은 팀에서는 RDS restart를 진행했고, 데이터베이스 지표와 메인 서버의 지표는 바로 정상으로 돌아왔습니다. 장애가 발생한 시점은 주로 batch 작업을 진행하는 시간대였기 때문에, 급한 문제점이 해소된 이후 수행되었어야 할 작업의 정합성에 관해 팀에서 조사를 진행했습니다. 정합성 검사와 후속 작업을 통해 장애로 인해 영구적인 문제나 손실이 발생하지 않도록 챙겨주셨습니다. 연말 클로징 중이었음에도 불구하고 새벽 시간대에 대응해주신 팀원들께 감사의 말씀 드립니다!

메인 데이터베이스의 문제는 금방 서비스 전반에 대한 장애로 확산되기 때문에 가장 높은 우선순위로 예방해야 할 이슈 중 하나입니다. 특정 테이블이나 쿼리에 대한 성능 저하는 관련된 기능에 한정된 장애로 영향을 미치는 범위가 적습니다. 당일 새벽에 진행된 조사에서는 문제의 직접적인 원인이 00:30 에 실행된 batch 작업일 것이라고 추측했습니다. 지표를 살펴보았을 때, 해당 작업에 연관된 테이블의 query latency가 00:30 ~ 00:36 범위에서 크게 증가했었으며, 이러한 상황이 방치되어 00:37 이후 데이터베이스 전반에 대한 장애로 확산되었을 것이라고 어렴풋하게 예상했기 때문입니다. 하지만 완전한 설명이 아니었기 때문에, 정확하게 원인을 찾아 추후 동일한 이슈가 발생하는 것을 예방하기 위해 조사를 진행했으며, 그 결과를 이 글을 통해 공유하려고 합니다.

본격적인 글에 들어가기에 앞서 이슈 발생 시간대에서 관찰할 수 있었던 몇몇 지표를 함께 살펴봅시다:

먼저 RDS 인스턴스의 CPU Utilization 지표입니다. Batch job이 수행되는 00:30 ~ 00:36 구간에는 평소보다 높은 CPU usage를 보입니다. (이러한 패턴은 장애를 겪지 않은 이전 job 실행에서도 동일하게 관찰할 수 있습니다.) 다만 실제로 장애를 겪은 00:37 ~ 00:52 시간대에는 오히려 낮은 CPU usage가 측정되었습니다.

AWS RDS는 performance insights 기능을 통해 데이터베이스가 겪는 load를 종류별로, 또 query별로 수집하여 볼 수 있습니다. 장애가 발생한 시간대에는 평균적인 부하의 수백 배 이상의 부하가 발생했는데, 이 부하의 종류는 LWLock:MultiXactMemberBuffer 와 LWLock:MultiXactMemberSLRU 로 나타납니다. 이것은 평소 부하 패턴에서는 관찰할 수 없었던 것이기 때문에 장애 직후에는 이 지표가 무엇을 의미하는지 알지 못했습니다만, 이 주제에 대해 더 공부해보고 나니 12월 31일 발생한 장애의 원인과 해결 방법을 추측해볼 수 있게 되었습니다.

MultiXact?

Performance insights에서 읽어낸 MultiXact라는 단어는 Postgres에서 MVCC와 row-level lock이 구현된 방식과 깊은 관련이 있습니다.

Postgres Tuple

RDS는 동시에 진행되는 transaction에게 일관성 있는 데이터를 제공해야 합니다. 예를 들면, 어떤 transaction에서 row를 읽었다면, 그 transaction은 그 이후에 시작된 다른 transaction이 해당 row를 수정했더라도 수정 이전의 데이터를 계속 읽을 수 있어야 합니다 (Repeatable read). Postgres는 이 specification을 구현하기 위해 row가 수정될 때마다 수정 이전과 이후 버전을 모두 저장하고 있으며, 이 버전 각각을 tuple이라고 부릅니다.

Tuple에는 그 record를 볼 수 있는 가장 빠른 transaction (t_xmin)과 가장 늦은 transaction(t_xmax) 정보가 함께 저장되어 있습니다.

예를 들어, 위 그림처럼 어떤 table에 row가 insert되면 insert를 수행한 transaction의 id가 xmin에 기록됩니다.

이 row가 수정되면 (txid = 3), 이 transaction은 기존 tuple의 xmax를 덮어쓰고 (xmax = nil → 3) 새로운 tuple을 추가합니다 (xmin = 3, xmax = nil). 동시에 수행되는 transaction은 해당 row에 접근할 때 txid가 xmin, xmax 사이여야만 그 tuple을 읽을 수 있습니다. 따라서 txid = 2인 transaction은 수정 이전의 tuple을, txid = 4인 transaction은 수정 이후의 tuple을 읽게 됩니다.

테이블에서 가지고 있는 low-level tuple과, 각 tuple xmin, xmax 등 메타데이터를 확인해보고 싶다면 pageinspect extension을 추가하여 직접 확인할 수 있습니다. 아래 쿼리를 실행하면 <table_name> 테이블에 있는 <page> 번째 page의 tuple 목록을 보여줍니다.

 lp | lp_off | lp_flags | lp_len |  t_xmin  | t_xmax | t_field3 | t_ctid | t_infomask2 | t_infomask | t_hoff | t_bits | t_oid |     t_data
----+--------+----------+--------+----------+--------+----------+--------+-------------+------------+--------+--------+-------+-----------------
  1 |   8064 |        1 |    121 | 19628344 |      0 |        1 | (0,1)  |           4 |      11010 |     24 |        |       | ...
  2 |   7936 |        1 |    121 | 18885050 |      0 |        1 | (0,2)  |           4 |      11010 |     24 |        |       | ...
  3 |   7808 |        1 |    121 | 19125057 |      0 |        1 | (0,3)  |           4 |      11010 |     24 |        |       | ...
  4 |   7680 |        1 |    121 | 18472155 |      0 |        1 | (0,4)  |           4 |      11010 |     24 |        |       | ...
 ...

Write가 일어날 때마다 새로운 tuple이 생성되어 저장된다면, 데이터베이스의 저장 공간은 금방 폭주할 것입니다. 테이블을 읽는 쿼리도 row의 tuple 목록을 확인하여 해당 transaction이 읽을 수 있는 tuple을 찾아야 하기 때문에 실행 비용도 계속해서 늘어납니다. 따라서 background에서 주기적으로 필요 없는 tuple을 찾아서 청소하는 작업을 진행하는데, 이 작업을 vacuum이라고 부릅니다.

Row-level Locks

MVCC와 상관 없을 것 같은 lock 또한 tuple의 xmin, xmax field를 통해 구현되어 있습니다. Postgres는 row-level lock을 인메모리에서 관리하는 것이 아니라 데이터와 동일하게 disk에 저장합니다! Tuple의 xmin, xmax field를 이용하면 아무리 큰 테이블에서 lock을 많이 걸더라도 RAM이나 disk storage를 추가로 사용하지 않고 공짜로 관리할 수 있는 것이죠.

예를 들면, txid = 2 인 transaction이 row에 lock을 걸면, 해당하는 tuple의 xmax field에 자기 txid를 기록하고, 해당 tuple의 metadata flag에 lock이 걸렸다고 표기해둡니다. 그 이후에 다른 transaction이 이 tuple에 write를 시도하면, 이 tuple에 lock을 건 transaction이 이미 있다는 것을 확인할 수 있습니다.

MultiXact

여기에서 MultiXact에 대한 필요성이 등장합니다. Tuple에 lock을 걸 수 있는 transaction은 하나가 아니라 더 많을 수 있습니다. SELECT FOR UPDATE 처럼 해당 row에 대한 exclusive lock을 획득하는 쿼리의 경우도 있지만, SELECT FOR SHARE 의 경우 read-level lock이기 때문에 여러 transaction이 lock을 획득할 수 있습니다.

그러면 postgres의 구현에서는 문제가 있습니다. xmax field에는 txid 하나만 기록할 수 있기 때문에, 여러 txid를 기록할 공간이 없습니다.

이것을 해결하기 위해 postgres는 별도의 자료구조를 관리합니다. 여러 transaction이 tuple에 대한 lock을 획득하는 경우를 위해 txid의 리스트를 관리하는 것입니다. Map<int, List<int>> 형태로 관리되는 자료구조에 txid 리스트를 보관하고, tuple의 xmax field에 map의 id를 적는다고 이해하면 됩니다. (이 id를 바로 MultiXactId라고 부릅니다.)

(정확하게는 Map<int, List<int>> 자료구조가 disk에 그대로 저장된다기보다는, multixact_offset 과 multixact_member 두 개의 array를 사용합니다. Member array가 모든 txid의 목록을 compact하게 들고 있고, offset array가 각 key에 대해 member array에 해당하는 offset을 들고 있습니다.)

Postgres의 구현을 구체적으로 살펴보니, 이 자료구조는 여러 가지 쎄한 점이 있었습니다.

• 테이블 별로 따로 관리되지 않는 global data structure입니다.

• Multixact id를 관리하기 위한 자료구조는 in-memory가 아니라 disk에 저장되는 데이터입니다.

  • 빈번한 disk 접근을 예방하기 위해 앞단에 LRU 정책에 의한 cache가 달려있습니다. (MultiXactMember, MultiXactOffset 이름을 가진 SLRU - Simple LRU - 입니다.)

• Multixact 메커니즘이 필요한 모든 경우 (여러 transaction이 tuple에 대한 lock을 획득하는 상황)에 read/write 접근이 일어납니다.

• Concurrent 접근이 일어나는 data structure이기 때문에 global lock 에 의해 관리되고 있습니다.

• 이 자료구조도 주기적으로 예전 transaction을 날리기 위한 청소가 필요한데, vacuum 도중에 청소를 해줍니다.

여기까지 알아보고 나니 RDS의 급격한 성능 저하 원인이 맞춰지는 듯 했습니다.

• Global lock이기 때문에 높은 contention 상황에서 성능이 급격하게 떨어집니다.

  → 장애 시간대의 performance insights에서 확인한 LWLock:MultiXactMemberBuffer 와 LWLock:MultiXactMemberSLRUlock이 바로 이것입니다.

• Vacuum이 제대로 수행되지 않아 자료구조가 커지면 SLRU cache 크기를 넘어 cache hit 비율이 떨어지고, disk R/W가 빈번해져 성능이 급격하게 떨어질 수 있습니다.

• 또 특정 access pattern이나 특정 query로 인해 multixact 자료구조의 성능을 떨어뜨리면, 그 쿼리가 건드리는 테이블 뿐만 아니라 multixact 메커니즘이 사용되는 다른 쿼리도 다같이 함께 느려질 수 있을 것 같네요.

음.. 그런데 저희 팀은 SELECT FOR SHARE 문을 사용하는 곳이 없었는데, multixact관련 접근은 대체 어디에서 온 것일까요..? 🤔

MultiXact는 어디에서

Notes on some PostgreSQL implementation details article에서 이 질문에 대한 답을 얻을 수 있었습니다. 이 글에서는 exclusive lock (SELECT FOR UPDATE 문) 과 subtransaction을 함께 사용했을 때 multixact를 타게 되고, 이로 인해 성능 저하가 발생할 수 있다는 점을 소개합니다.

앞서 pageinspect extension을 통해 raw tuple의 데이터를 확인할 수 있다고 소개했는데, t_infomask field에서 tuple의 xmax field에 multixact id가 들어있는지도 확인할 수 있습니다. Source를 보면 t_infomask 의 13번째 bit가 이 flag를 저장하고 있기 때문에 아래 쿼리를 돌려보면 됩니다.

lp |  t_xmin  | t_xmax | t_ctid | t_infomask | is_multixact  
----+----------+--------+--------+------------+--------------
  1 | 19628344 |      0 | (0,1)  |      11010 | f
  2 | 18885050 |      0 | (0,2)  |      11010 | f
  3 | 19125057 |      0 | (0,3)  |      11010 | f
  4 | 18472155 |      0 | (0,4)  |      11010 | f
  5 | 19016393 |      0 | (0,5)  |      11010 | f
  6 | 19367245 |      0 | (0,6)  |      11010 | f
  7 | 19369310 |      0 | (0,7)  |      11010 | f
  8 | 19376958 |      0 | (0,8)  |      11010 | f
  ...

이 article을 더 읽어보시면, SELECT FOR UPDATE 로 exclusive lock을 잡고, savepoint를 만든 후, 해당 row에 UPDATE 를 사용하면 해당 tuple에 multixact가 걸린다는 것을 직접 체크해볼 수 있어요.

@Transactional

이 글을 읽고 다음으로 한 일은 메인 application 서버에서 활용하는 패턴이 savepoint를 활용하는지 확인하는 것이었습니다. 아래와 같이 nested transaction이 활용되는 경우 이것이 어떻게 처리되는지 알아보았습니다.

Java-Dropwizard 기반으로 구성된 채널톡 메인 application 서버에서 사용하는 RDS에 대한 DSL은 jOOQ입니다. jOOQ에서 제공하는 @Transactional annotation이 붙은 method를 호출했을 때 일어나는 일을 확인하기 위해 jOOQ TransactionProvider interface의 구현을 확인했습니다.

DefaultTransactionProvider 에서 이 부분의 구현을 보면 다음과 같습니다.

DefaultTransactionProvider 는 nested 설정을 통해 nested transaction 메커니즘을 사용할 지 외부에서 선택할 수 있지만, 기본값은 true (nested trx 허용) 입니다.

• 실행 context에서 savepoint의 deque를 관리합니다.

• @Transactional 이 붙은 method가 호출되면,

  • Top-level 이라면 (savepoint deque가 비어있다면) dummy savepoint

  • Top-level이 아니라면 실제로

    SAVEPOINT;

• Method 호출이 끝나고, commit 시

  • Top-level이라면 진짜로 COMMIT;

  • Top-level이 아니라면 RELEASE SAVEPOINT;

• Method 호출이 끝나고, rollback 시

  • Top-level이라면 ROLLBACK;

  • Top-level이 아니라면 deque에서 pop한 savepoint로 ROLLBACK TO SAVEPOINT;

이 구현을 체크하고 나니 아래와 같은 application code의 구현은:

다음과 같은 SQL code를 실행함을 확인할 수 있었습니다. 실제로 debug level log를 확인하니 @Transactional 이 붙은 method를 중첩하여 실행할 때 SET SAVEPOINT 쿼리가 실행되는 것도 확인했습니다.

조사를 통한 소결론

배경 조사를 통해 얻은 논리의 흐름은 다음과 같습니다.

• Nested @Transactional method call 안쪽의 SELECT FOR UPDATE + UPDATE 패턴은 postgres가 multixact 자료구조에 접근하도록 한다.

• (추측) Multixact 자료구조는 global lock에 의해 관리되고, cache hit rate가 떨어지면 disk I/O를 유발할 수 있어 잠재적으로 성능 저하 요인이 된다(고 여러 글에서 읽었다).

• (추측) Multixact 자료구조가 느려지면 simple read/write는 괜찮지만 locked update하는 패턴의 경우 다같이 함께 느려질 수 있다. 전역 자료구조이기 때문에 전혀 관련없는 테이블에 접근하는 쿼리도 함께 느려진다.

• (추측) Multixact 자료구조를 청소하는 것은 vacuum이기 때문에 vacuum을 못하면 문제가 생길 것 같다.

가설을 설정했으니 이제 실제로 성능 저하의 여파를 확인하는 것만 남았습니다!

가설 검증하기: 실험과 결과

성능 비교를 위해 multixact 자료구조에 접근하는 access pattern을 준비했습니다.

그리고 이와 비교할 대조군으로 savepoint를 만드는 쿼리 대신 no-op select를 수행하는 쿼리도 준비했습니다.

위 쿼리를 실행하면서, auto vacuum을 막았을 때의 영향을 관찰하기 위해 별도의 session에 긴 transaction을 실행했습니다. 이 transaction은 아무 테이블도 읽지 않고 그저 기다리도록 구성했어요.

pgbench

실험 진행을 위해 AWS EC2에 postgres 14.10 버전을 설치하여 진행했습니다. 먼저 m5.2xlarge (8 vcpus, 32GB RAM) 인스턴스를 사용했으며, 부하를 가하고 데이터를 측정하기 위해 pgbench 를 사용했습니다.

테스트를 위해 100,000 row의 데이터베이스를 세팅하고 측정을 수행한 커맨드입니다.

쿼리 성능 실험

벤치마크를 실행하고 60초 후 쿼리 속도가 일정해졌을 때, 10분 길이의 long transaction을 시작하여 performance 추이를 관찰했습니다. 쿼리 TPS와 latency를 측정한 결과 그래프입니다.

multixact.sql 가 no-multixact.sql 보다 더 빠른 성능 저하를 보여줍니다. Multixact 메커니즘이 적용된 경우 long transaction 시작 1분 후 latency가 1.1배, 3분 후에는 1.8배 증가하여 최종적으로 3.2배까지 증가했습니다. 물론 multixact를 사용하지 않는 경우도 vacuum이 돌지 않았을 때 성능 저하가 있긴 합니다 (최종적으로 1.5배 성능 감소). Long transaction이 끝나고 auto vacuum이 실행되자 다시 쿼리 속도가 원래대로 복원되었습니다.

두 경우에 유의미한 차이가 있었으나, 실제 production에서 발생했던 장애는 2~3배의 성능 저하보다 훨씬 더 큰 장애였습니다. 트래픽 레벨이 너무 낮아 multixact 자료구조에 충분한 경합이 발생하지 않은 것으로 추측하여 더 높은 트래픽으로 실험을 한 차례 더 진행했습니다. 새로운 실험에서는 m5.4xlarge 인스턴스로 진행했고, 아무 영향이 없을 때의 TPS가 3.5k rps에서 22.8k rps가 되도록 올렸습니다. (참고로, 채널톡 production RDS는 주간에 15k TPS 정도의 요청을 받고 있습니다.)

이번 차례에 사용한 벤치마크 스크립트입니다. 준비한 데이터베이스의 크기도 이전과 비교해 100배 늘렸습니다만 (1000만 row), 실험 결과에 큰 영향은 없었습니다. 데이터베이스 크기에 더해, postgres의 shared_buffer (general disk I/O 앞에서 사용할 인메모리 버퍼의 크기) 도 변경하며 실험해보았습니다. 200MB 정도가 기본값인데, AWS RDS에서 권장치로 나와있는 16GB (RAM의 25%) 로도 바꿔보았으나 실험 결과에 차이가 없었습니다.

이번 실험 결과의 경우 성능 저하가 더 두드러지게 나타났습니다. Long transaction이 시작된 지 60초 만에 multixact.sql 쿼리의 TPS는 8.5배 감소했으며, 10분 이후에는 26배까지 성능 감소가 일어났습니다. Multixact 접근이 일어나지 않는 경우의 성능 저하와 비교하면 차이가 이전 실험보다 더 큽니다. Transaction이 끝난 직후 실행된 vacuum 작업도 큰 부담이 되었는지 이 구간에는 쿼리 latency가 2.8초까지 증가하기도 했습니다. (아마 이것이 production에서 일어난 장애의 일부 원인이 될 수 있지 않을까요?)

메인 API 서버에서 작성한 코드 중 긴 transaction의 경우 실행 시간을 1분 미만으로 제한하고 있습니다. 1분짜리 쿼리의 경우에도 급격하게 8배 이상의 성능 저하가 일어났으며, 이전 실험과 비교하면 이 효과는 데이터베이스가 처리하는 트래픽이 높을수록 증폭될 가능성이 높습니다.

또한 이 성능 저하의 경우 많은 요청이 문제가 되는 것이 아니라, 단 하나의 long transaction이 이와 같은 영향을 미친다는 것이 걱정스럽습니다. 심지어 이 transaction은 아무 데이터도 읽고 쓰지도 않는데도 말입니다. 부주의한 코드를 작성하여 transaction 실행 시간 제한 조건을 빼먹었다면 수 분 길이의 slow query만으로도 (코드상으로도 전혀 관련없는) multixact 관련 쿼리가 급격하게 느려질 수 있는 것이죠. 그 직후 발생하는 vacuum 작업도 RDS가 일반 요청을 처리하는 데 부담을 줄 수 있을 것입니다.

MultiXact SLRU Cache

쿼리 속도가 어떤 원인으로 저하되었는지 더 많은 정보를 알아내기 위해 postgres의 SLRU cache 접근에 관한 통계 데이터도 확인했습니다. Postgres는 pg_stat_slru 를 통해 이 데이터를 제공하고 있고, 이 중에는 우리가 관심 있는 Multixact 관련 SLRU (MultiXactMember, MultiXactOffset) 관련 이력도 포함되어 있습니다.

사실 저는 앞선 실험을 진행하면서 아래 커맨드를 통해 5초마다 pg_stat_slru 를 조회하고 있었기 때문에, 이 데이터도 함께 확인하여 분석했습니다. 😁

pg_stat_slru 테이블에서 우리가 관심있는 정보는 다음과 같습니다.

여기에서 blks_hit 과 blks_read 를 비교하면 cache hit rate를 알 수 있으므로, SLRU cache의 효율을 측정할 수 있습니다.

먼저 m5.2xlarge 인스턴스에서 진행한 첫번째 실험의 결과이며,

이것은 m5.4xlarge 인스턴스에서 진행한 두번째 실험의 결과입니다.

Long transaction이 시작되자 99% 이상이던 cache hit rate가 급격하게 감소하는 것을 두 실험 모두에서 관찰할 수 있습니다. Transaction 시작 1분이 지나지 않아 cache hit rate는 10% 이하로 감소하며, disk read 또한 초당 100k blocks 정도로 빠르게 늘어났습니다. 또한, Transaction이 끝나고 auto vacuum이 진행된 이후에도 cache 효율이 완벽하게 복원되지는 않았습니다.

실제 production 환경과 더 가까운 workload를 부여하고, vacuum의 영향 또한 궁금했기 때문에 10분짜리 긴 transaction 대신 1분짜리 transaction을 반복적으로 수행했을 때의 실험도 진행했습니다. Application server에서는 종종 batch job을 작성할 때 긴 쿼리를 수행하고 이 transaction의 길이를 1분으로 제한하는 경우가 많아, 이 세팅이 장애 상황과 더 가깝다고 생각했습니다.

일부 transaction이 끝나고 latency가 spike치는 것을 통해 auto vacuum이 당시에 trigger되었음을 추측할 수 있습니다. (사실 pg_stat_user_table 을 보면 auto vacuum이 언제 수행되었는지도 체크해볼 수 있는데, 더블체크하지는 않았어요) Transaction이 끝난 직후에도 바로 성능이 원래만큼 복원되지는 않았습니다. 앞선 실험에서 보았듯 1분짜리 transaction에도 성능은 8배 이상 감소할 수 있기 떄문에, 이러한 job이 수행된다면 전반적인 query latency가 증가할 것임은 다시 한 번 확인할 수 있었습니다.

Datadog에서 확인한, 장애 시간대의 실제 query latency입니다. 장애 직전 00:30 ~ 00:36 구간에는 latency가 증가했다가 다시 감소하는 것을 반복합니다. 앞선 실험의 결과가 이 상황을 어느 정도 재현하지 않나 합니다.

1분짜리 transaction을 활용한 실험에서 측정한 SLRU 관련 데이터 또한 함께 공유합니다.

여러 차례 진행한 benchmark에서 00:37 이후 발생한 장애 상황을 재현할 수는 없었습니다.

하지만 performance insights에서 볼 수 있었듯 장애 시간대에서 RDS에 주어진 부하는 Multixact 관련 lock에 대한 contention이었습니다. 또한 해당 시간대에 RDS에 연결된 session 수가 급격히 증가한 것을 확인할 수 있었습니다. 여기부터는 완전한 추측입니다만:

• 쿼리 속도가 5~10배 이상 전반적으로 감소했을 때 application의 connection pool에서 새롭게 connection을 열게 됩니다.

• 하지만 문제는 global lock과 disk I/O로 인한 contention이었기 때문에 connection을 더 연다고 문제가 해결되지는 않고, 오히려 contention이 더 증가합니다.

• 이러한 상황이 positive feedback으로 작용하여 문제가 증폭됩니다.

와 같은 경로로 장애가 발생했을 것이라고 생각합니다.

실험을 통해 확인한 내용

• Multixact 메커니즘에 접근하는 쿼리와 그렇지 않은 쿼리 간에는 유의미한 성능 차이가 있다.

• 단 하나의 long transaction도 이러한 성능 저하를 유발할 수 있으며, vacuum이 잘 작동해야만 원래 성능으로 되돌아간다.

• 1분짜리 (그렇게 길지 않은) long transaction도 8배의 성능 저하의 원인이 되었다.

문제 해결

그래서 이걸 어떻게 고치면 좋을까요? 🤔

A) 공격적인 수단으로는 nested transaction 자체를 사용하지 않으면 됩니다..! 아마 신사업이나 나중에 창업해서 새롭게 application을 개발한다면 잊지 말고 기억해야 할 점 중 하나가 아닌가 싶습니다. Nested transaction에 의존하지 않고 비즈니스 로직을 개발해 나가는 편이 가장 정석적인 해결방법입니다.

예를 들어 저희 메인 application 서버의 경우 jOOQ 설정을 통해 TransactionProvider 의 nested 옵션을 false 로 지정하여 중첩된 @Transactional 메소드를 호출하더라도 savepoint를 지정하지 않도록 설정할 수 있습니다.

실제로 이렇게 코드를 바꿔본 후 로컬 환경에서 간단히 측정을 해보았습니다. 로컬 환경이기 때문에 여러 요소에 영향을 받지만 간단한 검증을 위해서 한 번 해보았습니다! RDS에 일반적인 read/write 부하를 가하면서, 장애 시점에 수행되던 00:30 작업을 수동 실행해 보았습니다. 이 workload를 넣으면서 nested option을 켰을 때와 껐을 때의 지표를 비교했습니다.

nested = true

nested = false

nested = true 일 때만 SLRU blocks read 이력이 있으므로, 이 때만 SLRU cache miss가 발생하는 것을 관찰할 수 있습니다. 따라서 nested = false 로 지정하는 것은 MultiXact 문제의 해결 방법이 될 수 있음을 보여줍니다. 다만 로컬에서 실행한 workload의 경우 hit / miss 비율이 10:1 정도 되었기 때문에 (hit rate > 90%) 유의미한 성능 저하가 관찰되지는 않았습니다. 하지만 앞서 진행했던 실험 결과처럼 hit rate가 크게 떨어지면 바로 큰 성능 저하로 이어질 수 있다는 것은 이미 확인했습니다. 그래서 이 정도 수준에서 검증한 것으로 만족했습니다.

이 방법의 경우 기존에 잘 운영되던 프로젝트의 경우 nested transaction 메커니즘에 의존하는 것이 많거나, 모르고 의존하던 부분에 breaking change가 생기는 것이 걱정되어 적용할 수 없는 해결책인 것 같습니다.

B) 모니터링 하기: 이번 조사와 실험으로 인해 MultiXact라는 것이 있고, 이 자료구조에 대한 접근을 관리하는 SLRU cache 데이터가 여러 정보를 줄 수 있음을 새롭게 알게 되었습니다.

로컬 환경에서 조사를 진행할 때는 postgres에서 pg_stat_slru 통계를 수집하여 시각화하기 위해 prometheus와 grafana를 연결하여 사용했습니다.

• Postgres → Prometheus exporter

  • 다만 pg_stat_slru 에 대한 데이터 수집은 기본적으로 해주지 않아서, 이 부분은 제가 새롭게 코드를 작성해서 넣은 후 다시 컴파일 했습니다 😅

또한 query별로 부하의 원인을 구체적으로 보여주는 pg_stat_statements extension도 쓸만할 것 같았는데 이번 조사에서 사용하지는 않았습니다.

장애가 발생하기 5분 정도 전 전조 증상으로 SLRU cache hit rate가 급격하게 감소하는 현상이 나타났으니, 이 지표에 대한 알람을 설정하여 문제 상황이 발생했을 때 원인이 되는 job을 죽이고 vacuum을 공격적으로 돌리는 등의 대응이 이루어져야 합니다.

C) 코드 패턴 개선하기: 지금까지 소개한 내용을 조사하면서 의문이 되었던 점은, 기존에도 @Transactional annotation과 수 분짜리 transaction은 오랫동안 있어왔는데 왜 지금 갑자기 문제가 터졌냐는 점이었습니다. 낮은 트래픽 수준에서는 SLRU cache hit rate가 크게 떨어지지 않기 때문에 성능 저하를 관찰할 수 없었을지도 모르겠지만, 정작 이슈는 새벽 시간대에 발생했으니까요.

그래서 코드 수정 이력을 살펴보니, 최근 업데이트에서 @Transactional annotation 사용이 급격하게 늘어난 것을 확인했습니다. (Annotation이 총 사용되는 곳이 총 300여개 있는데, 그 중 80여 개가 지난달에 추가된 코드였습니다.) 그리고 코드를 좀 더 읽어보니 nested transaction이 여러 번 발생하도록 호출이 이루어지고 있었습니다. 예를 들면 어떤 긴 플로우의 경우 SET SAVEPOINT 과 RELEASE SAVEPOINT 문이 40여 번 발생하는 곳도 있었습니다.

이번 조사를 통해 nested transaction이 큰 성능 저하의 원인이 될 수 있으며 @Transactional annotation은 신중하게 걸어야 할 대상이라는 것을 확인했습니다. A) 해결책처럼 급진적으로 savepoint를 한 번에 제거하기는 어렵습니다. 다만 불필요한 annotation을 삭제하고 @Transactional 을 걸 수 있는 곳에 대한 가이드라인을 만들어서 코드 리뷰 중 지적될 수 있도록 하는 것은 필요하다고 생각합니다. 예를 들면 package-public한 method에만 @Transactional 을 걸 수 있도록 규칙을 만드는 것도 좋을 것 같네요. 그러면 package를 관리하는 팀에서는 외부의 호출로부터 데이터 정합성을 보호할 수 있으면서, transaction을 최소화할 수 있으니까요.

D) Slow query 조사하기: 이번 조사를 통해 SET STATEMENT TIMEOUT = 1min; 의 소중함에 대해서도 알게 되었습니다! Slow query가 lock을 걸지 않더라도, 데이터를 읽고 쓰지 않더라도, 그냥 존재하기만 하더라도 전혀 상관없는 다른 쿼리의 성능 저하를 일으키는 것을 실험을 통해 확인했습니다. 꼭 Multixact 뿐만 아니더라도, 일반 쿼리 또한 수 분 정도 되는 transaction이 수행되자 latency가 3~4배 증가하는 결과를 관찰했습니다.

부주의하게 코드 리뷰에서 놓친 단 하나의 transaction이 이런 문제를 만들 수 있어요! 😭

전체적으로 transaction의 길이를 제한하는 정책을 도입하는 것이 필요하다고 느꼈습니다.

결론

23.12.31 새벽 발생한 서비스 장애로부터 시작하여, 다음과 같은 내용을 조사와 실험을 통해 알아보았습니다. 정리한 내용을 끝으로 글을 마무리하려고 합니다.

• MultiXact 란 Postgres에서 한 tuple에 여러 transaction이 lock을 걸려고 할 때 trigger되는 메커니즘이다.

• Application level에서 @Transactional 이 붙은 메소드를 중첩하여 실행하면 multixact 관련 접근이 일어날 수 있다.

• Vacuum이 원활하지 않은 상황 (e.g. long transaction) 에서 multixact 관련 접근은 큰 경합을 발생시켜 RDS의 성능을 크게 저하시킨다.

• 관련 지표를 관찰하여 알람을 지정하고, nested transaction을 코드에서 제거하고, vacuum이 원활히 실행하도록 보장해야 한다.