MySQL CPU Saturation Analysis

분석 배경

최근 서비스의 DB 장비에 동일한 쿼리가 동시다발적으로 실행되면서 서버의 User CPU 사용률이 거의 100% 에 도달하여 서비스 장애로까지 이어졌던 일이 있었습니다.

그때 당시, 부하를 유발하던 SELECT 쿼리 이외에 다른 DML 쿼리가 문제되진 않았었으며, SELECT 쿼리로 인한 부하임에도 불구하고 DB 내부적으로 경합이 매우 심했고 DML 쿼리들도 평소보다 유입이 확 줄어들었었습니다.

사실 이러한 케이스들은 이전에도 있었으며, 이렇게 SELECT 쿼리로 인해 부하가 높은 상태에서 DML 유입이 줄고 DB 내부 경합이 심해지는게 우리가 이미 여러 DB서버에서 많이 사용하고 있는 DB내 쓰레드풀 기능의 영향인건지 원인을 파악하기 위해 분석 테스트를 진행하였습니다.

이를 통해 추후에 발생하는 동일한 형태의 장애를 예방 및 진단하는데 활용하고자 합니다.

아래는 문제 시점 당시 서버 및 MySQL 관련 지표들을 나타낸 그래프입니다.

원인 분석을 위한 테스트

문제 현상이 동일하게 재현될 수 있는 테스트 환경을 구축한 뒤 원인을 분석하였습니다.

•  테스트 환경 구축
  MySQL version : 5.5.24-MariaDB_for_Kakao2
  CPU : 12 Core (2.40 Hz)
  Memory : 32G (Innodb buffer pool size is 24G)
  Disk : NVMe SSD
  1.  문제가 발생했던 DB 장비에 테스트 DB 장비를 연결
  2.  MRTE(Mysql Real Traffic Emulator)를 통해 실제 서비스 장비에 유입되고 있는 트래픽을 테스트 장비에 전송 (SELECT 쿼리 트래픽만)
  3.  문제 시점 당시 수행됐던 SELECT 쿼리를 약 30개 스레드에서 계속 실행하는 쉘 스크립트를 실행
  4.  현상 관찰

• 모의 테스트 진행
  본래 장비와 동일하게 트래픽을 받는 상태에서 쉘 스크립트로 동일한 쿼리를 계속 수행하여 실제 장애 상황과 동일한 현상이 발생하는지 테스트 진행.
  테스트를 수행한 결과, 이전에 문제되었던 때와 동일하게 User CPU 사용률이 100% 까지 증가하고 InnoDB 내부 뮤텍스/세마포어 관련 수치가 매우 높게 올라갔음.

      

      

• 문제 현상이 동일하게 재현되는 환경에서 원인 분석을 위해 아래와 같이 테스트를 진행하였습니다.

TEST 1.   Remove Thread Pool

-   분석 초기에 원인으로 추정했던 쓰레드 풀 사용을 중단하기 위해 Thread 설정을 'one-thread-per-connection' 으로 변경한 뒤 다시 테스트를 진행함.

-   테스트한 결과, 이전과 동일하게 부하와 경합이 발생하였음.

TEST 2.   InnoDB Buffer Pool Instance 갯수 변경 ( 1 -> 20 )

-   1번 테스트를 통해 쓰레드풀이 쿼리 실행시간 및 서버 부하에 큰 영향을 주지 않았다는 것을 알게됨.

-   Disk Read도 없는 상태에서 세마포어 경합 수치가 올라간 것을 미루어 보았을 때, 메모리 내부적으로 lock 경합이 있었을 것으로 추정하여 메모리 내부 뮤텍스/세마포어 등의 경합을 줄이기 위해 1개로 설정되어 있던 innodb_buffer_instance 갯수를 20개로 조정함.
     (참고로 기존 서비스 DB도 1로 설정되어 있는 상태임.)

-   버퍼풀 인스턴스 갯수 조정 후 다시 테스트를 진행한 결과, 이전과 달라지는게 없었음. 동일하게 부하 및 경합이 발생함.

TEST 3.  innodb_buffer_pool_instance = 1 & performance_schema = ON

-   DB 내부적으로 어떤 부분에서 경합이 발생하는지 알아보기 위해 performance schema를 키고 다시 테스트 진행함.
     (innodb_buffer_pool_instance 는 다시 1로 조정하였음.)

-   performance schema를 킨 상태에서 부하를 준 결과, events_waits_current 테이블에서 각 스레드들이 buf_pool_page_hash_latch 에 read lock(S-lock)을 걸기 위해 대기하고 있는 상태가 포착됨.

     하지만 EVENT_ID 값이 계속 바뀌는 것으로 보아, buf_pool_page_hash_latch 에 대한 lock 경합이 실제로 부하를 유발하지 않는 것으로 보였음.

     (s-lock일 뿐더러, Disk read도 없었기 때문에 buffer pool page hash table이 변경될 가능성
     (즉,  buf_pool_page_hash_latch에 대한 x-lock 점유)이 없어보였음. 또한 테스트하는 동안
     performance_schema.rwlock_instances 테이블에서 buf_pool_page_hash_latch 에 대한 WRITE_LOCKED_BY_THREAD_ID 값이
     계속 NULL이였음.) 

-   테스트를 진행하던 도중 show engine innodb status 의 Semaphore 섹션에서 동일한 block->mutex(메모리 주소가 모두 같음)에 대하여 쓰레드들이 lock을 걸기 위해 대기하는 모습이 포착되었음.

---------- SEMAPHORES ---------- .... --Thread 139754297358080 has waited at buf0buf.ic line 372 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139782798149376 has waited at buf0buf.ic line 1269 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139782374692608 has waited at buf0buf.ic line 1269 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139754351617792 has waited at buf0buf.ic line 1269 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139782798681856 has waited at buf0buf.ic line 1269 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139782375491328 has waited at buf0buf.ic line 372 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139754423187200 has waited at buf0buf.ic line 372 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 --Thread 139754322257664 has waited at buf0buf.ic line 372 for 0.0000 seconds the semaphore: Mutex at 0x7f1b9b7983f8 '&block->mutex', lock var 1 waiters flag 1 ....

-   동일한 형태의 쿼리가 여러 스레드에서 실행되면서 버퍼풀 내의 특정 데이터 블록에 동시다발적으로 접근하다보니 뮤텍스 경합이 심해져 User CPU를 모두 소진하는 것으로 보였으며,

     이 결과를 바탕으로 innodb_sync_spin_loops/innodb_spin_wait_delay 값을 조정해가면서 CPU 사용률 등을 체크해보았음. (TEST 4)

TEST 4.  innodb_sync_spin_loops / innodb_spin_wait_delay 값 조정

-   innodb_sync_spin_loops, innodb_spin_wait_delay 변수 모두 쓰레드 대기와 관련이 있는 설정변수들임. 정확한 의미는 아래 내용을 참고. (MySQL Menual 페이지에서 발췌하였음.)

• • innodb_sync_spin_loops : The number of times a thread waits for an InnoDB mutex to be freed before the thread is suspended. (Default 30.)
  • innodb_spin_wait_delay : The maximum delay between polls for a spin lock. (Default 6.)

-    위 두 값을 조정하면서, CPU 사용률과 InnoDB Mutex 수치를 측정하였음.

      테스트 DB에 적용된 두 변수 값은 각각 innodb_sync_spin_loops = 100, innodb_spin_wait_delay = 6 이며, 이는 기존 서비스 DB 장비에 설정된 값과 동일함.

1)  innodb_spin_wait_delay = 6 인 상태에서,
     innodb_sync_spin_loops 값을 100 -> 50 -> 30 -> 10 -> 5 로 조정

           
           
           

- 10:35:30 : innodb_sync_spin_loops = 100 (Current value)

- 10:35:50 : innodb_sync_spin_loops = 50

- 10:36:10 : innodb_sync_spin_loops = 30  (Default value)

- 10:36:30 : innodb_sync_spin_loops = 10

- 10:36:50 : innodb_sync_spin_loops = 5

- 10:37:10 : innodb_sync_spin_loops = 10

innodb_sync_spin_loops 값에 따라 User CPU 사용률의 변화가 컸으며, Sys CPU 사용률과 Idle CPU 사용률을 보았을 때 값이 10일 때가 가장 적절해 보임.

2)   innodb_sync_spin_loops = 100 인 상태에서,
      innodb_spin_wait_delay 값을 6 -> 3 -> 1 -> 0 으로 조정

           

           

           

- 10:45:41 : innodb_spin_wait_delay = 6  (Current & Default value)

- 10:46:00 : innodb_spin_wait_delay = 3

- 10:46:20 : innodb_spin_wait_delay = 1

- 10:46:40 : innodb_spin_wait_delay = 0

- 10:47:02 : innodb_spin_wait_delay = 6

CPU 사용률이 높은 상황에선 innodb_spin_wait_delay 값을 줄여도 크게 영향을 미치진 않았음. 극단적으로 값을 0으로 설정해야 User CPU 사용이 줄어들었음.

3)  innodb_sync_spin_loops = 10 인 상태에서,
     innodb_spin_wait_delay 값을 6 -> 3 -> 1 -> 0 으로 조정

           

           

           

- 10:54:31 : innodb_spin_wait_delay = 6  (Current & Default value)

- 10:54:51 : innodb_spin_wait_delay = 3

- 10:55:11 : innodb_spin_wait_delay = 1

- 10:55:30 : innodb_spin_wait_delay = 0

- 10:55:50 : innodb_spin_wait_delay = 6

CPU가 어느정도 여유가 있는 상태에서 innodb_spin_wait_delay 값을 조정한 결과 어느정도 영향력을 가짐. 그러나 큰 차이는 없어서 디폴트값인 6으로 설정해도 무방해보임.

결론

동일한 쿼리가 동시다발적으로 유입되어 여러 스레드에서 메모리내의 같은 데이터 블록에 접근하여 뮤텍스 경합이 발생, CPU 부하가 높아지는 경우 innodb_sync_spin_loops 변수 값을 조정함으로써 긴급한 상황에서 부하를 좀 더 낮출 수 있을 것으로 보입니다.
innodb_sync_spin_loops 의 디폴트 값이 30 이나, 위에서 살펴본 것처럼 어느 정도 부하가 높은 상태에서는 30 이상의 값은 모두 user cpu를 많이 소모하였으므로 만일의 상황을 대비하여 초기에 설정 값을 10으로 가져가는 것도 나쁘지 않아 보입니다.