운영중 장애 징후 분석: MySQL fsync 최적화를 통한 Commit 지연 해결

 

11월에 행사를 진행하면서 트래픽 조금 경험한걸 아직도 곱씹어 먹고 있다.

 

트래픽이 많았다고 말하긴 애매하지만, 운영 환경에서 실제 사용자가 동시에 몰리는 상황을 처음을 제대로 겪은 경험이었다. 그고 항상 성능 테스트를 진행해도 spike 몰리는 상황을 염두해왔지 8시간이나 되는 장시간 트래픽 집중은 그 자체로 신선했다. 

 

Hack Playground: 부산대-부경대 해킹캠프 회고

 

대회 기간동안 발생한 슬로우 쿼리를 분석해서 인덱스 설계가 제대로 이뤄졌는지 평가하고 쿼리 튜닝을 진행할 목적이었다.

 

슬로우 쿼리 로그만으로는 부족하다

long_query_time을 1(sec)로 설정했다고 가정하자. 

 

1초 이상 걸린다고 해서 다 문제가 되는 쿼리인가? 극단적으로 트래픽이 많은 테이블에서 0.9초 쿼리가 10만번 일어나는 경우는 감지할 수 없다.

 

즉, 슬로우 쿼리만으로 어디가 원인인지 왈가왈부 평가하기 어렵다.

 

performance_schema도 같이 확인하자

아래 내용들은 전부 slow log만으로는 알 수 없는 정보들이다.

• 지연 원인이 락인가? IO인가? CPU 연산인가?
• 왜 같은 쿼리여도 시간대별로 차이가 나는가?

 

MySQL Performance Schema 검사를 통해서 다양한 실시간성 정보를 수집할 수 있다.

• 쿼리의 히스토리, 평균/최대 지연시간, wait event

아래와 같이 쿼리 형태로 상세한 정보를 확인할 수 있다.

SELECT *
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;

 

좀 더 정제해서 보면

SELECT DIGEST_TEXT, COUNT_STAR,
  ROUND(SUM_TIMER_WAIT/1e12, 2) AS total_sec,
  ROUND(AVG_TIMER_WAIT/1e6, 2)  AS avg_ms
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;

 

실험1: 호출 빈도가 제일 많았던 Commit

운영 MySQL 스냅샷을 로컬에서 performance_schema 돌려보면서 분석하던 중 사실을 발견할 수 있었다.

 

누적 시간(sum_timer_wait) 기준으로 정렬한 결과.

mysql> SELECT
    ->   LEFT(DIGEST_TEXT, 60) AS digest_short,
    ->   COUNT_STAR,
    ->   ROUND(SUM_TIMER_WAIT/1e12, 2) AS total_sec,
    ->   ROUND(AVG_TIMER_WAIT/1e6, 2) AS avg_ms
    -> FROM performance_schema.events_statements_summary_by_digest
    -> ORDER BY SUM_TIMER_WAIT DESC
    -> LIMIT 10;
+-----------------------------------------------------------+------------+-----------+-----------+
| digest_short                                              | COUNT_STAR | total_sec |  avg_ms   |
+-----------------------------------------------------------+------------+-----------+-----------+
| COMMIT                                                    |     130051 |    702.32 |   5400.34 |
| SET `autocommit` = ?                                      |     268293 |     38.32 |    142.84 |
| SELECT COUNT(*) FROM `problems`                           |        139 |     19.54 | 372260.89 |
| SELECT `u1_0` . `user_id` ...                             |         35 |     25.03 |  319400.3 |
| ...                                                       |        ... |       ... |       ... |
+-----------------------------------------------------------+------------+-----------+-----------+
10 rows in set (0.00 sec)

 

가장 문제가 된 쿼리는 비즈니스가 아니라 Commit이었다. 네?

 

뭔가 잘못 됐다. commit 지연이면 쿼리 문제라기보단 DB 병목의 신호이다.

 

autocommit 역시도 같은 맥락으로, 어디가 원인인지 분석해야한다.

 

쿼리 자체는 빠르지만 Flush나 IO 작업으로 꼬인다면 스케줄러 전체가 느려지기 때문에 지연 발생시 염두해둬야할 지점이다.

 

몰랏는데 새로 알았다 여기도 보자 이제!!!

 

부수적으로 발견한 쿼리 튜닝의 비효율 개선

아 그 과정에서 간단한 쿼리 튜닝도 했다.

 

점수(score)가 가장 높은 사용자 조회

• mysql 8에서는 desc 인덱스가 의미 있음. 이전 버전처럼 * (-1) 안그런다.
• index(score desc)가 없으면 filesort, limit이 있어도 full table scan

+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                                                                                                                                                                                                                                                                                               |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Limit: 20 row(s)  (cost=10.9 rows=20) (actual time=0.395..0.395 rows=0 loops=1)
    -> Sort: u.score DESC, limit input to 20 row(s) per chunk  (cost=10.9 rows=107) (actual time=0.391..0.391 rows=0 loops=1)
        -> Filter: (u.score > 1000)  (cost=10.9 rows=107) (actual time=0.36..0.36 rows=0 loops=1)
            -> Table scan on u  (cost=10.9 rows=107) (actual time=0.0585..0.236 rows=120 loops=1)
 |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

 

DESC 인덱스를 추가한 후, LIMIT 연산이 Index range scan 단계에서 적용되어서 정렬 과정을 생략할 수 있었다.

+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                                                                                                                                                 |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Limit: 20 row(s)  (cost=0.71 rows=1) (actual time=0.0419..0.0419 rows=0 loops=1)
    -> Index range scan on u using idx_user_score_desc over (score < 1000), with index condition: (u.score > 1000)  (cost=0.71 rows=1) (actual time=0.0386..0.0386 rows=0 loops=1)
 |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

 

실행계획상 불필요한 filesort는 제거했지만, 근본 원인을 해소하지 않는 이상 증상 완화에 불과하다.

 

슬로우 쿼리 로그를 통해 발견한 DB 병목

슬로우 쿼리가 발생했던 원인이 어느 정도 좁혀졌다.

 

분석하는 과정에서 비효율적인 쿼리를 찾고, 인덱스를 추가하기도 했지만 근본적인 원인이 아니였다.

 

인덱스가 없어서 해당 쿼리만 느린게 아니라, 모든 쿼리에 대한 commit 자체가 수백 초 걸린다.

 

즉, DB 자체가 잠깐 지연된 구간이 있었다.

 

예상하기로 아마 대학 동아리간 연합 CTF 대회때 트래픽이 몰리면서.. 열악한 성능을 버티지 못하고 DB 자체가 지연 → 인덱스 효율이 낮은(없는) 조회성 쿼리들이 슬로우 쿼리로 노출된 것으로 보인다.

 

DB 병목이 발생했다는 것으로 유추할 순 있었지만 그 병목 원인을 파악할 순 없다.

 

DB 병목의 원인은 그래서 뭐였을까?

막연하게 트래픽이 몰리던 대회날 수집된 거라고 추측하는 것을 넘어서 신뢰할만한 데이터로 문제를 확정하고 싶었다.

 

특정 테이블만의 문제가 아니였고, 전체적으로 SELECT, COUNT, UPDATE가 느려지는 현상이 있었다. (commit avg latency 5sec, max 수백 sec)

 

 

쓰기 작업에 대한 문제가 보이니 disk flush 과정에서 발생하는 fsync 지연을 의심했다.

 

먼저 운영 환경은 따로 DB 튜닝을 진행한 적이 없어서 날것 그대로의 순수한 default 세팅을 갖고 있었다.

 

주의해서 봐야할 튜닝 옵션은 아래와 같다.

mysql> SHOW VARIABLES LIKE 'sync_binlog';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sync_binlog   | 1     |
+---------------+-------+
1 row in set (0.05 sec)

mysql> SHOW VARIABLES LIKE 'innodb_flush_log_at_trx_commit';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| innodb_flush_log_at_trx_commit | 1     |
+--------------------------------+-------+
1 row in set (0.00 sec)

• innodb_flush_log_at_trx_commit: commit시 뭘 어디까지 보장할건가
  • 0: 응난몰라. 메모리에만 ack
  • 1: default. commit마다 fsync 1번 (정합선이 최우선인 phase로 동시 트랜잭션이 많으면 병목이 바로 생긴다!!)
  • 2: fsync는 1초마다 백그라운드에서 진행
• sync_binlog: N번의 COMMIT마다 binlog를 fsync 할 것인가?
  • commit시 실제 흐름은 InnoDB redo log 기록 → binlog 기록 → commit 반환이다.
  • 0: commit시 binlog 메모리에 기록만 하고 fsync 안하니까 disk flush도 os 마음대로 진행함. binlog 유실 가능
  • 1: commit마다 fsync 1회씩 하면 binlog가 100% disk에 기록된다.
  • N: n번 commit마다 1번식 fsync해서 n개 단위로 유실될 수는 있지만… commit 지연 급감

더 자세한 설명은 여기 참조

[MySQL/MariaDB] innodb_flush_log_at_trx_commit 파라미터 / 개념도

 

모든 commit마다 redo log와 binlog를 디스크에 sync flush하고 있는 셈이다. 

 

wait/io/file/innodb/innodb_log_file은 InnoDB redo log 파일에 대한 IO wait를 수집하고 있다.

 

여기에는 redo log의 쓰기나 flush(fsync) 와 같은 파일 작업에서 기다린 시간을 보여준다.

 

그럼 이제 wait event를 확인해서 대기 시간을 보자.

mysql> SELECT *
    -> FROM performance_schema.events_waits_summary_global_by_event_name
    -> WHERE EVENT_NAME LIKE 'wait/io/file/innodb/innodb_log_file';
+-------------------------------------+------------+------------------+----------------+----------------+----------------+
| EVENT_NAME                          | COUNT_STAR | SUM_TIMER_WAIT   | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+-------------------------------------+------------+------------------+----------------+----------------+----------------+
| wait/io/file/innodb/innodb_log_file |    1269680 | 1112217551109336 |              0 |      875982562 |   353111843406 |
+-------------------------------------+------------+------------------+----------------+----------------+----------------+
1 row in set (0.72 sec)

 

AVG_TIMER_WAIT가 거의 0.87s, MAX_TIMER_WAIT 는 353s 나온 적이 있다.

 

아직 이 redo log 대기 시간의 원인이 fsync인지 write인지 확정 지을 수는 없지만, 적어도 IO가 멈춘게 확실해진다.

 

하지만 앞서 Commit이 fync 빈도가 잦으며, 지연 시간 digest 1위라는 점도 함께 고려하면 디스크 flush시 발생한 지연이 원인이 된다는 것을 알 수 있었다.

 

innodb_flush_log_at_trx_commit=1, sync_binlog=1으로 commit당 fsync 2번씩 하면서 트래픽이 몰리는 순간 병목 지점이 된 것이다. (innodb쪽 fsync + binlog fsync)

 

 

자, 이제 commit 지연이 fsync 빈도로 인한 병목이라는 논리적 근거를 실제 실험을 통해서 검증하겠다.

실험 환경

이전에 구축해둔 실험 환경을 그대로 가져와서 대시보드나 비교군만 다시 설계했다.

 

낑낑거리면서 어떻게든 선언적으로 관리해볼려고 고민한게 안아까울만큼 알차게 써먹고 있다. 

 

Apache JMeter 기준 thread: 1000, 10sec, 10 count 상황을 고정해서 문제 풀이이력 등록하는 쓰기 작업 테스트를 진행했다.

 

일부러 DB의 병목을 시각적으로 확인하고자 짧은 시간내에 트래픽을 쑤셔박았다.

 

그리고 mysql-exporter를 통해서 쓰기 작업에 대한 세부 메트릭을 수집하기 위해서 죄다 긁어왔다.

--collect.perf_schema.eventsstatements
--collect.perf_schema.eventswaits
--collect.perf_schema.indexiowaits
--collect.perf_schema.tableiowaits
--collect.perf_schema.file_events
--collect.engine_innodb_status
--collect.info_schema.innodb_metrics
--collect.info_schema.processlist      
--collect.info_schema.tables
--collect.global_status

 

아, 당연하다면 당연하겠지만 mysql-exporter 접속에도 DB 커넥션을 사용하니 실험 환경에서 미리 염두해서 max_connections를 설정해야 한다.

 

그리고 접속하는 방법도 좀 특이했다. 

• mysqld.address=<URL>:<Port>
• mysqlid.username=<root>:<password>

 

튜닝전

먼저 눈에 띄는 패턴을 설명하고 가겠다.

 

commit 빈도와 Query per seconds가 비례하고 있다. 아래도 같이 보자

fsync Rate: 160 ops/s

 

fync rate까지도 commit, qps와 함께 선형적으로 같이 증가하고 있다. 

 

QPS가 증가하는 만큼 Commit수가 비례하는데, DB 설정으로 인해서 fsync가 비례해서 증가하는 증거이다.

 

commit avg latency: 20.7ms

 

이를 통해서 디스크 flush 대기열이 쌓이면서 전체적인 commit latency를 발생하고 있는 것을 관측할 수 있다.

 

튜닝후

사실 첫 실험에서는 binlog 30개당 fsync 1회으로 fsync 빈도를 극단적으로 줄이려고 했었다. 

 

• innodb_flush_log_at_trx_commit = 2
• sync_binlog = 30
• innodb_flush_method = O_DIRECT

이렇게 되면 redo log는 commit마다 fsync를 하지 않고 백그라운드에서 초당 1회씩 진행한다.

 

binlog 역시도 30개 단위로 syscall을 호출해서 fsync 호출 자체를 물리적으로 줄일 수 있다.

 

flush 방식에서 Direct IO를 도입했는데 이에 관한 설명도 이미 블로그에 공부한 내용을 올린 적이 있다.

InnoDB Flush 계층에서 본 Direct IO (feat. Zero Copy와의 차이점)

 

하지만 이 상태를 운영에 그대로 가져가도 되는가 생각해보면 영 글쎄올시다..

 

특히 sync_binlog를 N으로 설정해버리면 장애 발생시 최대 N개의 commit까지 binlog를 유실해버린다. binlog를 잃으면 복구나 백업도 못하고 영영 사라져버리는 셈이다. 

 

 

그래서 결국 최종 선택한 튜닝 결론은 다음과 같다.

• innodb_flush_method=O_DIRECT
• innodb_flush_log_at_trx_commit=2
• sync_binlog = 1 (rollback)

binlog를 원래 값으로 복원하여 장애가 발생해도 commit 단위로 복구를 보장하되, redo log의 flush 압박만 줄이는 쪽으로 선택했다.

fsync Rate: 5 ops/s, Commit avg latency: 1.47ms

 

결과적으로 튜닝 전보다 개선되었다고 할만한 수치적인 성과를 내면서도 장기적인 안정성을 유지할 수 있었다.

• fsync Rate: 160 → 5 (ops/s)
• commit avg latency: 20.7 → 1.47(ms)

 

결론

 

슬로우 쿼리 로그만으로 fsync, flush, IO 병목을 파악할 수 없다. 

• 슬로우 쿼리가 왜 발생했는지
• 왜 Commit이 가장 느린 쿼리로 나타났는지
• 왜 인덱스를 붙여도 해결되지 않는지

 

이 경우, 슬로우 쿼리는 쿼리 지연의 원인이 아니라 DB 병목의 결과일 수 도 있다.