MySQL에서 CPU가 높게 칠때

개요

며칠 전에 DB 부하로 인해 사내에서 작지 않은 장애가 났었다. write DB에서 CPU가 갑자기 높게 치더니 기어이 장애가 발생했다. 다행히 팀원 분들이 재빠르게 대처해 주셔서 곧바로 해결되었다.

그런데 생각해 보니 DB CPU가 언제 많이 쓰이는지 제대로 알지 못하고 있었다. IO에만 신경쓰고, CPU는 뭐 filesort할 때나 쓰이지 않을까 생각하고 있었는데 이번 일을 보니 꼭 그러한 건 아닌 것 같다.

 

따라서 이번 기회에 CPU가 언제 높게 치는지 몇가지 조사해 보았다.

 

1. 레코드 잠금 경합

트랜잭션 간 lock 경합이 발생할 때를 말한다. lock 경합을 확인할 때는 information_schema.innodb_lock_waits 테이블을 사용한다. 

 

다음 쿼리는 block된 트랜잭션과 연결된 block 트랜잭션을 볼 수 있도록 한다

SELECT
  t.trx_id,
  t.trx_state,
  t.trx_started,
  COUNT(distinct w.requesting_trx_id) AS blocked_trxs
FROM
  information_schema.innodb_lock_waits w
INNER JOIN information_schema.innodb_trx t
   ON t.trx_id = w.blocking_trx_id
GROUP BY t.trx_id,t.trx_state, t.trx_started
ORDER BY t.trx_id;

 

 

 

2. 메타데이터 잠금 경합

다음 명령어를 실행하면 연결된 모든 스레드를 반환한다. 현재 실행중인 SQL도 볼 수 있다.

 

SHOW [FULL] PROCESSLIST;

 

여기서 Updating 중인 스레드가 많으면 레코드 잠금 경합의 위험이 있고, 메타데이터 lock에 대해 Waiting이면 메타데이터 lock에 대한 위험을 가지고 있다

 

메타데이터 락이란 쉽게 말해 트랜잭션 도중에 ddl이 실행되지 못하도록 막는 것이고, ddl 뒤에 오는 작업들도 대기하는 것이다. 만약 ddl이 시작하기 전에 재수 없게 장기 트랜잭션이 들어오면? 계속 대기하면서 요청은 계속 받으니 쓰레드는 계속 늘고 컨텍스트 스위칭은 계속 하고 하면서 CPU 사용률이 느는 걸로 생각된다.

 

(우리가 겪은 문제도 이거였다)

 

메타 데이터 락에 대한 이해로는 다음 글이 도움이 많이 되었다

- https://blog.naver.com/PostView.nhn?blogId=seuis398&logNo=70144654434

MySQL 5.5 Metadata Locking

- https://leezzangmin.tistory.com/m/51

 

 

참고로, 활성 스레드 수는 다음 쿼리로 볼 수 있다

 

SHOW STATUS like 'Threads_%';

 

Threads_running 값이 높아지면 CPU 사용량도 늘어난다

3. 세마포어 경합

뮤텍스나 읽기 / 쓰기 래치가 경합 원인이 될 수도 있다고 한다. 다음 명령어로 세마포어 경합을 볼 수 있다고 하는데, 사실 무슨 말인지 정확힌 모르겠다.

 

내가 배우기로는 mutex는 단일 자원 / spin lock 방식으로 동작하고 세마포어는 다수 자원에 대해 interrupt를 날리는 식으로 동작하는 걸로 배웠는데... 내가 생각하는 이 개념이 맞나 싶다.

 

mysql> SHOW ENGINE INNODB STATUS\G
----------
SEMAPHORES
----------
...
  --Thread 140396021667584 has waited at row0purge.cc line 862 for 241.00 seconds the semaphore:
  S-lock on RW-latch at 0x30c03e8 created in file dict0dict.cc line 1183
  a writer (thread id 140395996489472) has reserved it in mode  exclusive
  number of readers 0, waiters flag 1, lock_word: 0
  Last time read locked in file row0purge.cc line 862
  Last time write locked in file /build/mysql-5.7-FFKPr6/mysql-5.7-5.7.22/storage/innobase/dict/dict0stats.cc line 2376
...

출처: https://cloud.google.com/sql/docs/mysql/optimize-cpu-usage?hl=ko

 

래치 관련해서는 다음 글이 적당히 도움 되었다. 쉽게 말해서 래치는 공유 자원에 대한 잠금을 말하는 것 같은데... 당장 떠오르는게 버퍼풀, 메타데이터 정도 외에는 없는 것 같다

 

https://seastar105.tistory.com/147

 

 

4. 커넥션 수 증가

커넥션 수가 늘면 그만큼 쓰레드 수도 늘어난다(MySQL이니까). 이때는 요청 수가 많으니까 처리하는 양 자체가 많아서 당연히 CPU도 높게 칠거고, context switching 자체도 빈번하니까 더 많이 필요하지 않을까... 하는 생각이 든다. 또 쿼리 파싱이라던가 전처리하는 거라던가 옵티마이저가 하는 동작들 (쿼리 변환 / 비용 최적화 / 실행계획 수립) 등도 모두 CPU 작업을 할테니까 당연히 많을 것이다

 

현재 접속해 있는 호스트들을 보려면 다음 명령어로 볼 수 있다

   select HOST,CURRENT_CONNECTIONS From performance_schema.hosts
   where CURRENT_CONNECTIONS > 0
   and host not in ('NULL','localhost');

 

 

5. 풀스캔시

엥? 풀스캔인데 IO 대기가 아니라 CPU를 왜 쓰지? 하는 생각이 들었는데 이것과 관련하여 재밌는 글을 하나 보았다.

https://www.percona.com/blog/reducing-high-cpu-on-mysql-a-case-study/

Reducing High CPU on MySQL: a Case Study

 

이 글의 사례에서는  다음과 같은 자료를 볼 수 있다. 이건 `Handler_read_rnd_next 를 본 건데, 이건 풀스캔시 row를 읽을 때마다 count한다고 한다. 여기서는 350개 항목에 대해서 약 250만 건에 대한 row 읽기를 하고 있음을 발견했다는데 이때 버퍼풀에 있는 걸 읽어서 IO가 아닌 CPU를 썼다는 것이다.

 

 

이 글에서 재밌었던 건 버퍼풀을 많이 써서 CPU를 많이 쓴 것도 있었지만, MySQL 핸들러를 활용해서 문제를 추적할 수 있다는 점도 재밌었다. RealMySQL 읽을 때는 아 이런게 있구나 정도에서 그쳤는데, 나중에 문제 생기면 핸들러 API 종류들을 슥 훑고 이거 한 번 볼 수 있겠는데? 싶으면 좋을 것 같다.

 

참조

- https://seastar105.tistory.com/147

- https://dev.mysql.com/doc/refman/8.0/en/memory-use.html

- https://learn.microsoft.com/en-us/azure/mysql/flexible-server/how-to-troubleshoot-high-cpu-utilization

- https://cloud.google.com/sql/docs/mysql/optimize-cpu-usage?hl=ko