❗ 해당 포스트는 MacOS 환경에서 MySQL 5.7 기준으로 작성되었습니다. 그리고 예제에서 사용되는 모든 테이블은 InnoDB 엔진을 사용합니다.

MySQL 성능 개선을 위한 프로파일링 1편

최근 웹 애플리케이션 서버의 API가 성능이 너무 낮아 튜닝을 해야 하는 상황이 찾아왔다. 해당 API는 유저가 생성한 트랜잭션의 목록을 반환한다. 병목 지점을 찾기 위해서는 먼저 부하 테스트를 수행해야 한다. 그 뒤에 웹 애플리케이션을 프로파일링 하고 나서 RDBMS를 프로파일링하는 것이 정석이다. 이 포스트는 RDBMS(MySQL) 프로파일링에만 집중하겠다.

MySQL을 프로파일링을 하려면 가장 먼저 무엇을 해야할까? 하나씩 알아보자.

---

1. 슬로우 쿼리 로그를 켜자

문제가 생겼다면 가장 먼저 해야 하는 일은 로그를 남기는 것이다. 비단 MySQL뿐만 아니라 웹 애플리케이션에서도 장애를 쉽게 추적하기 위해서는 로그를 남겨야 한다. MySQL에서는 여러 로그를 남길 수 있다. 수행 시간이 오래 걸리는 쿼리를 잡기 위해서는 슬로우 쿼리 로그를 활성화해야 한다.

💁 슬로우 쿼리 로그란?

지정한 초(seconds) 이상의 시간이 소요된 쿼리가 기록되는 파일이다.
파일에 기록할 수도 있고 테이블에 기록할 수도 있다. 자세한 내용은 아래 링크에서 확인할 수 있다.
https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

❗ 슬로우 쿼리 로그는 에러가 발생한 쿼리는 기록하지 않습니다. 제너럴 로그에서는 에러가 발생한 쿼리를 포함해서 모든 쿼리를 기록하므로 두 개의 로그를 모두 활성화하면 프로파일링에 좀 더 도움이 될 수 있습니다.

슬로우 쿼리 로그 활성화(설정 파일)

슬로우 쿼리 로그를 활성화하기 위해서는 MySQL Configuration 파일을 찾아야 한다. 아래 명령어를 수행하면 my.cnf 파일을 찾을 수 있다. 아래 디렉터리 중 한 곳에 my.cnf가 있을 것이다. 여러 디렉토리에 동시에 my.cnf 파일이 존재하면 왼쪽 디렉토리 순서대로 우선 적용된다.

$ mysql --verbose --help | grep my.cnf
/etc/my.cnf /etc/mysql/my.cnf /usr/local/etc/my.cnf ~/.my.cnf

파일을 찾았다면 아래처럼 수정한다.

[mysqld]
# 슬로우 쿼리를 TABLE로 출력한다. FILE로도 설정할 수 있다
# FILE로 설정했다면 slow_query_log_file로 출력할 파일 위치를 설정할 수 있다
log_output = TABLE

# 슬로우 쿼리 활성화
slow_query_log = 1

# 아래 변수에 지정된 초(seconds)이상 쿼리가 수행되면 슬로우 쿼리에 기록된다
# 여기서는 테스트를 위해 0.05초로 지정했다
long_query_time = 0.05

# log_ouput을 TABLE로 설정했다면 slow_query_log_file 변수는 주석 처리하자
# MySQL 버그인지 필자의 개발환경 문제인지 모르겠지만, log_output을 TABLE로 설정했을 때
# 해당 변수가 설정되어 있으면 슬로우 쿼리가 활성화되지 않는 문제가 발생했다
# slow_query_log_file=...
# ...

파일을 수정했다면 MySQL 서버를 재시작한다. 만약 MySQL 서버를 재시작하지 않고 슬로우 쿼리를 활성화하고 싶다면 MySQL 서버에서 아래 명령어를 실행하면 된다. 다만 MySQL 서버가 재시작했을 때 원상 복구된다.

SET GLOBAL log_output = 'TABLE';
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 0.05;

아래 명령어를 MySQL 서버에서 실행하면 슬로우 쿼리가 설정되었는지 확인할 수 있다.

SHOW VARIABLES WHERE 
Variable_Name LIKE 'slow_query_log' OR 
Variable_Name LIKE 'long_query_time' OR
Variable_Name LIKE 'log_output';

아래는 필자가 MySQL Workbench에서 위 명령어를 수행했을 때 출력된 결과이다.

슬로우 쿼리 로그 활성화(MySQL Workbench)

MySQL Workbench를 사용하면 쉽게 슬로우 쿼리를 활성화할 수 있다. 먼저 연결된 Connection에서 Edit Connection을 선택한다.

System Profile 탭에서 Configuration File의 위치가 잘 들어가 있는지 확인한다. 비어 있다면 아래 명령어를 통해 my.cnf 위치를 찾을 수 있다. 아래 디렉토리 중 어디에 있는지는 하나씩 직접 확인해봐야 한다.

$ mysql --verbose --help | grep my.cnf
/etc/my.cnf /etc/mysql/my.cnf /usr/local/etc/my.cnf ~/.my.cnf

설정을 완료했으면 DB에 접속하자. 그러면 아래와 같은 화면이 뜨는데 왼쪽 탭의 Administration -> Instance -> Options File을 클릭하면 아래와 같이 설정 파일을 수정할 수 있다. 아래 처럼 항목들을 수정한다.

✅ long_query_time=0.05
✅ log_output=TABLE
✅ slow_query_log
❌ slow_query_log_file

위처럼 수정했다면 MySQL 서버를 재실행한다.

---

2. 슬로우 쿼리 로그 조회

슬로우 쿼리를 활성화 했으니 잘 동작하는지 확인해보자. 필자는 테스트를 위해 아래 깃허브의 덤프를 사용했다. https://github.com/datacharmer/test_db/blob/master/employees.sql

덤프를 모두 로드했으면 아래 쿼리를 실행해 보자. 컴퓨터 성능에 따라 다르겠지만 InnoDB 에서 전체 테이블 레코드의 개수를 세는 것은 보통 인덱스 풀 스캔을 해야 하기 때문에 0.05초 이상 걸릴 것이다. 필자의 컴퓨터에서는 0.054 초가 걸렸다. 여러 번 같은 쿼리를 수행하면 쿼리 캐시 때문에 결과가 금방 나올 수도 있다. 그럴 때는 long_query_time 을 조절해서 테스트하면 된다.

SELECT COUNT(*) FROM employees; # 0.054 sec

SQL 사용

mysql DB의 slow_log 테이블을 조회하면 슬로우 쿼리를 확인할 수 있다. sql_text 컬럼이 blob이기 때문에 sql_text 컬럼을 CONVERT 해서 실제 쿼리를 확인하자. 2번째 쿼리는 주요한 내용만 뽑은 쿼리이다.

SELECT * FROM mysql.slow_log;
# 또는
SELECT start_time, user_host, query_time, lock_time, rows_sent, rows_examined, db, CONVERT(sql_text USING utf8 ) sql_text
FROM mysql.slow_log;

필자는 2번째 쿼리를 실행했을 때 아래와 같은 결과를 얻을 수 있었다.

각 컬럼의 의미는 대략 아래와 같다. 공식 설명은 아래 페이지에서 찾을 수 있지만, 자세하게 나와 있지는 않다.
https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html#slow-query-log-contents

start_time: 쿼리가 시작된 시간
user_host: 쿼리를 실행한 사용자
query_time: 쿼리가 실행되는 데 걸린 시간
lock_time: 테이블 잠금에 대한 대기 시간
rows_sent: 실제 클라이언트에 전달된 레코드의 수
rows_examined: 쿼리가 처리되기 위해 실제 접근한 레코드의 수
db: 쿼리가 수행된 데이터베이스
sql_text: 실제 수행된 쿼리

MySQL Workbench 사용

MySQL Workbench를 사용하면 쉽게 로그를 조회할 수 있다. 먼저 DB를 접속하고 왼쪽 탭에서 Administration -> Instance -> Server Logs를 클릭하면 아래와 같이 로그를 조회할 수 있다.

---

3. 결론

슬로우 쿼리를 활성화함으로써 어떤 쿼리가 병목을 가져오는지 쉽게 캐치할 수 있다. 이런 로그가 없다면 성능 개선을 위해 슬로우 쿼리를 찾는 데만 엄청난 시간이 걸릴 것이다. 심지어 애플리케이션에서 쿼리 빌더를 통해서 쿼리를 생성하는 경우에는 생성된 쿼리를 일일이 애플리케이션에서 찍지 않으면 실제로 수행되는 쿼리가 무엇인지 알기 어렵다. 다행히 어떤 쿼리가 병목을 만들어내는지 로그를 남길 수 있으므로 실행 계획을 분석해서 쿼리를 개선할 수 있을 것이다. 다음 편에서는 실행 계획을 분석해보겠다.

여담이지만 깊이 생각하지 않고 ORM과 같은 쿼리 빌더를 사용하면 슬로우 쿼리가 만들어지는 경우가 많다. 실제로 이번에 개발된 API들을 리뷰하면서 해당 케이스를 발견했다.