쿼리 성능 테스트
작성된 쿼리가 얼마나 효율적이고 더 개선할 부분이 있는지 확인하려면 쿼리를 직접 실행해보는 방법이 가장 일반적일 것이다. 하지만 쿼리를 직접 실행해 보면서 눈으로 성능을 체크할 때는 여러 가지 방해 요소가 있는데, 이런 방해 요소를 간과하고 쿼리의 성능을 판단한다는 것은 매우 위험한 일이다. 이번에는 복잡한 벤치마킹 기술을 언급하려는 것이 아니라, 간단하게 쿼리의 성능을 판단해보기 위해서 어떠한 부분을 고려해야 하고, 어떤 변수가 있는지 살펴보겠다. 여기에 언급된 내용은 단순히 쿼리 테스트에만 필요한 지식이 아니라, 실제 쿼리가 실행될 때 거치는 과정을 이해하는 데도 도움될 것이다.
1. 쿼리의 성능에 영향을 미치는 요소
직접 작성한 쿼리를 실행해보고 성능을 판단할 때 가장 큰 변수는 MySQL 서버가 가지고 있는 여러 종류의 버퍼나 캐시일 것이다. 어떤 종류의 버퍼나 캐시가 영향을 미치는지 살펴보고, 영향력을 최소화하는 방법도 알아보겠다.
운영체제의 캐시
MySQL 서버는 운영체제의 파일 시스템 관련 기능(시스템 콜)을 이용해 데이터 파일을 읽어온다. 그런데 일반적으로 대부분의 운영체제는 한 번 읽은 데이터는 운영체제가 관리하는 별도의 캐시 영역에 보관해 뒀다가 다시 해당 데이터가 요청되면 디스크를 읽지 않고 캐시의 내용을 바로 MySQL 서버로 반환한다. InnoDB 스토리지 엔진은 일반적으로 파일 시스템의 캐시나 버퍼를 거치지 않는 Direct I/O를 사용하므로 운영체제의 캐시가 그다지 큰 영향을 미치지 않는다. 하지만 MyISAM 스토리지 엔진은 운영체제의 캐시에 대한 의존도가 높기 때문에 운영체제의 캐시에 따라 성능의 차이가 큰 편이다.
운영체제에 포함된 캐시나 버퍼는 프로그램 단위로 관리되기 때문에 프로그램(MySQL 서버)이 종료되면 해당 프로그램을 위한 캐시는 자동적으로 해제된다. 운영체제가 가지고 있는 캐시나 버퍼가 전혀 없는 상태에서 쿼리의 성능을 테스트하려면 MySQL 서버를 재시작하거나, 다음과 같이 캐시 삭제 명령을 실행하고 테스트하는 것이 좋다.
## 캐시나 버퍼의 내용을 디스크와 동기화한다.
shell > sync
## 운영체제에 포함된 캐시의 내용을 초기화한다.
shell > echo 3 > /proc/sys/vm/drop_cachesMySQL 서버의 버퍼 풀(InnoDB 버퍼 풀과 MyISAM의 키 캐시)
운영체제의 버퍼나 캐시와 마찬가지로 MySQL 서버에서도 데이터 파일의 내용을 페이지(또는 블록) 단위로 캐시하는 기능을 제공한다. InnoDB 스토리지 엔진이 관리하는 캐시를 버퍼 풀이라고 하며, MyISAM 스토리지 엔진이 관리하는 캐시는 키 캐시라고 한다. InnoDB의 버퍼 풀은 인덱스 페이지는 물론이고 데이터 페이지까지 캐시하며, 쓰기 작업을 위한 버퍼링 작업까지 겸해서 처리한다. 그와 달리 MyISAM의 키 캐시는 인덱스 데이터에 대해서만 캐시 기능을 제공한다. 또한 MyISAM의 키 캐시는 주로 읽기를 위한 캐시 역할을 수행하며, 제한적으로 인덱스 변경만을 위한 버퍼 역할을 수행한다. 결국 MyISAM 스토리지 엔진에서는 인덱스를 제외한 테이블 데이터는 모두 운영체제의 캐시에 의존할 수 밖에 없다. MySQL이 한번 기동된 상태에서는 InnoDB의 버퍼 풀과 MyISAM의 키 캐시 크기를 변경하거나 내용을 강제로 퍼지(Purge, 삭제)하는 명령이 없다. MySQL 서버에 포함된 키 캐시나 버퍼 풀을 초기화하려면 MySQL 서버를 재시작해야 한다.
쿼리 캐시를 사용하지 못하도록 힌트를 사용한 쿼리라 하더라도 처음 실행했을 때와 두 번째 실행했을 때 상당한 성능 차이가 발생할 수도 있다. 이는 버퍼 풀이나 키 캐시에 의한 성능 차이다. 일반적으로 서비스 쿼리는 버퍼 풀이나 키 캐시가 준비된 상태에서 실행되기 때문에 처음 실행했을 때의 결과는 버리고 여러 번 테스트해서 그 결과를 기준으로 판단하는 것이 좋다.
MySQL 쿼리 캐시
쿼리 캐시는 이전에 실행했던 SQL 문장과 그 결과를 임시로 저장해두는 메모리 공간을 의미한다. 만약 어떤 쿼리의 결과가 이미 쿼리 캐시에 있었다면 그 쿼리는 전체 실행 과정을 건너뛰기 때문에 실제 부하와 관계없이 아주 빠르게 처리될 것이다. 쿼리 캐시에서 결과를 가져온 경우에는 대부분 0.00초 내에 쿼리 결과가 반환된다. 쿼리 캐시에 저장된 데이터를 비우려면 "RESET QUERY CACHE" 명령을 이용하면 되는데, 쿼리를 테스트할 때마다 쿼리 캐시를 비우기란 번거로운 일일 것이다. 그래서 SELECT 쿼리에 SQL_NO_CACHE 힌트를 추가해서 쿼리의 성능을 테스트하는 것이 좋다.
RESET QUERY CACHE 명령은 MySQL 서버에 포함된 모든 쿼리 캐시 내용을 삭제하며, 삭제 작업이 진행되는 동안 (짧은 시간이겠지만) 모든 쿼리의 실행이 대기해야 한다. 따라서 서비스 중인 MySQL 서버에서는 이 명령을 실행할 때 주의해야 한다. 서비스 중인 MySQL 서버에서 쿼리의 성능을 확인해볼 때도 가끔 있다. 이때 서비스 중인 MySQL 서버의 쿼리 캐시를 지워서는 안되므로 SQL_NO_CACHE 힌트가 필요하다.
독립된 MySQL 서버
버퍼나 캐시와 관련된 부분은 아니지만, MySQL 서버가 기동 중인 장비에 웹 서버나 다른 배치용 프로그램이 실행되고 있다면 테스트하려는 쿼리의 성능이 영향을 받게 될 것이다. 이와 마찬가지로, MySQL 서버뿐 아니라 테스트 쿼리를 실행하는 클라이언트 프로그램이나 네트워크의 영향 요소도 고려해야 한다. MySQL 서버가 설치된 서버에 직접 로그ㅇ니해서 테스트해 볼 수 있다면 이러한 요소를 쉽게 배제할 수 있을 것이다.
실제 쿼리의 성능 테스트를 MySQL 서버의 상태가 워밍업된 상태(위에서 언급한 캐시나 버퍼가 필요한 데이터로 준비된 상태)에서 진행할지 아니면 콜드 상태(캐시나 버퍼가 모두 초기화된 상태)에서 진행할지도 고려해야 한다. 일반적으로 쿼리의 성능 테스트는 콜드 상태가 아닌 워밍업된 상태를 가정하고 테스트하는 편이다. 어느 정도 사용량이 있는 서비스라면 콜드 상태에서 워밍업 상태로 전환되는 데 그다지 많은 시간이 걸리지 않기 때문에 실제 서비스 환경의 쿼리는 대부분 콜드 상태보다는 워밍업 상태에서 실행된다고 볼 수 있다. 간단한 쿼리의 성능 비교 테스트에서는 특별히 영향을 미칠 만한 프로세스나 다른 쿼리가 실행되고 있는지 확인한 후, 쿼리 캐시만 사용하지 않도록 설정하고 테스트를 진행해보면 충분할 것이다.
운영체제의 캐시나 MySQL의 버퍼 풀, 키 캐시는 그 크기가 제한적이라서 쿼리에서 필요로 하는 데이터나 인덱스 페이지보다 크기가 작으면 플러시 작업과 캐시 작업이 반복해서 발생하므로 쿼리를 1번 실행해서 나온 결과를 그대로 신뢰하기 어렵다. 테스트하려는 쿼리를 번갈아 가면서 6~7번 정도 실행한 후, 처음 몇 번의 결과는 버리고 나머지 결과의 평균 값을 기준으로 비교하는 것이 좋다. 첫 번째는 항상 운영체제 캐시나 MySQL의 버퍼 풀과 키 캐시가 준비되지 않을 때가 많기 때문에 대체로 많은 시간이 소요되는 편이어서 편차가 클 수 있기 때문이다.
이런 사항을 고려해 쿼리의 성능을 비교하는 것은 결국 상대적인 비교이지 절대적인 성능이 아니다. 그래서 그 쿼리가 어떤 서버에서도 그 시간 내에 처리된다고 보장할 수는 없다. 실제 서비스용 MySQL 서버에서는 현재 테스트 중인 쿼리만 실행되는 것이 아니라 동시에 4~50개의 쿼리가 실행 중인 상태일 것이다. 각 쿼리가 자원을 점유하기 위한 경합 등이 발생하므로 항상 테스트보다는 느린 처리 성능을 보이는 것이 일반적이다.
사용자가 실행하는 모든 프로그램은 윈도우나 유닉스 운영체제에서 기동된다. 그리고 이러한 프로그램에서 필요로 하는 작업 중에서 하드웨어와 연관되는 모든 작업은 운영체제의 도움을 받게 된다. 모든 프로그램은 개발할 때 키보드 입력을 읽어온다거나 디스크로부터 파일을 읽고 쓰는 작업 등을 위해 운영체제에서 제공하는 API를 이용한다. JDBC나 MySQL C API와 같은 라이브러리와 구분해서 운영체제에서 하드웨어를 제어하도록 요청하는 API를 "시스템 콜(System call)" 또는 "커널 콜(kernel call)"이라고 표현한다.
2. 쿼리의 성능 테스트
이제 직접 쿼리 문장의 성능을 비교해보자. 다음 예제 쿼리는 둘 모두 employees 테이블과 departments 테이블로부터 1개씩 칼럼을 읽어오는 쿼리인데, STRAIGHT_JOIN 힌트를 이용해 조인의 순서를 다르게 실행할 때 어느 정도의 성능 차이가 발생하는지를 테스트해 보자.
SELECT SQL_NO_CACHE STRAIGHT_JOIN
e.first_name, d.dept_name
FROM employees e, dept_emp de, departments d
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no;
SELECT SQL_NO_CACHE STRAIGHT_JOIN
e.first_name, d.dept_name
FROM departments d, dept_emp de, employees e
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no;그런데 이 쿼리를 실제로 실행하면 30만 건의 레코드가 화면에 출력된다. 아마, 다 출력될 때까지 기다리면 테스트 해보기도 전에 지쳐버릴 것이다. 다음과 같이 쿼리를 조금 고쳐서 실행하는 방법을 생각해 볼 수 있다.
SELECT SQL_NO_CACHE COUNT(*) FROM
( SELECT STRAIGHT_JOIN
e.first_name, d.dept_name
FROM employees e, dept_emp de, departments d
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no
) dt;
SELECT SQL_NO_CACHE COUNT(*) FROM
( SELECT STRAIGHT_JOIN
e.first_name, d.dept_name
FROM departments d, dept_emp de, employees d
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no
) dt;이렇게 쿼리를 변경하면 원본 쿼리는 임시 테이블을 사용하지 않지만 테스트를 위해 변경된 쿼리는 임시 테이블을 사용하는 만큼 조금의 오차는 발생할 수 있다. 쿼리 결과가 큰 경우에는 디스크에 임시 테이블을 만들기 때문에 테스트하고자 하는 내용보다 더 큰 오버헤드를 만들 수 있으므로 주의해야 한다. 다른 방법으로는 LIMIT 0 조건을 SQL_CALC_FOUND_ROWS 힌트와 동시에 사용하는 것이다. LIMIT 0 조건 때문에 화면에 출력되는 레코드는 하나도 없다. 하지만 실제로 MySQL 서버는 SQL_CALC_FOUND_ROWS 힌트 때문에 끝까지 처리하므로 쿼리의 전체적인 처리 시간을 확인할 수 있다.
SELECT SQL_CALC_FOUND_ROWS SQL_NO_CACHE STRAIGHT_JOIN
e.first_name, d.dept_name
FROM employees e, dept_emp de, departments d
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no
LIMIT 0;
SELECT SQL_CALC_FOUND_ROWS SQL_NO_CACHE STRAIGHT JOIN
e.first_name, d.dept_name
FROM departments d, dept_emp de, employees e
WHERE e.emp_no=de.emp_no AND d.dept_no=de.dept_no
LIMTI 0;크게 중요한 요소는 아니지만, 위의 예제 쿼리는 모두 결과 데이터를 클라이언트로 가져오지 않으므로 네트워크 통신 비용만큼 부하가 줄어든다는 점을 기억해야 한다. 별도의 GUI SQL 도구를 사용하는 것이 아니라 MySQL 클라이언트의 PAGER 옵션을 변경해 결과의 출력을 다른 곳으로 보내거나 버리는 방법도 생각해 볼 수 있다. 유닉스 계열이라면 PAGER 옵션을 변경해서 출력되는 결과를 간단히 /dev/null로 리다이렉트할 수도 있다. 다음의 첫 번째 PAGER 명령은 가져온 결과를 /dev/null로 리다이렉트하게 한다. 그 결과 화면에는 소요된 시간만 출력될 것이다. 그리고 테스트가 완료되면 NOPAGER 명령으로 다시 쿼리 결과가 화면에 출력되게 할 수 있다.
mysql > PAGER /dev/null
mysql > SELECT .. FROM employees ..
-> 2 rows in set (0.00 sec)
mysql > NOPAGER이렇게 쿼리를 변경해서 6번씩 실행한 결과에서 첫 번째 결과는 버리고 2번째부터 6번째까지의 결과 평균을 계산했더니 대략 첫 번재 쿼리가 12.1초 정도이며, 두 번째 쿼리가 대략 2.3초 정도 결렸다. 여기서는 12.1초나 2.3초가 중요한 것이 아니라 두 쿼리의 성능이 대략 5.2배 정도의 차이가 난다는 점이 중요하다. 12.1초나 2.3초는 버퍼 풀의 크기나 CPU의 성능, 그리고 전체 메모리 크기 또는 디스크의 사양에 따라 달라지는 값이기 때문이다.
3. 쿼리 프로파일링
MySQL에서 쿼리가 처리되는 동안 각 단계별 작업에 시간이 얼마나 걸렸는지 확인할 수 있다면 쿼리의 성능을 예측하거나 개선하는 데 많은 도움이 될 것이다. 이를 위해 MySQL은 쿼리 프로파일링 기능을 제공한다. 프로파일링은 MySQL 5.1 이상에서만 지원되는 기능으로, 기본적으로는 활성화돼 있지 않기 때문에 필요하다면 먼저 프로파일링을 활성화해야 한다. 프로파일링을 활성화하는 방법은 다음 예제와 같이 SET PROFILELING 명령을 실행하면 된다.
mysql > SHOW VARIABLES LIKE 'profiling';
+-----------------+---------+
| Variable_name | Value |
+-----------------+---------+
| profilling | OFF |
+-----------------+---------+
mysql > SET PROFILING=1;
mysql > SHOW VARIABLES LIKE 'profiling';
+-----------------+---------+
| Variable_name | Value |
+-----------------+---------+
| profilling | ON |
+-----------------+---------+이제 프로파일링 기능을 활성화했으므로 간단하게 쿼리 한 두개를 실행하고 각 쿼리에 대한 프로파일 내용을 확인해 보자.
mysql > SELECT * FROM employees WHERE emp_no=10001;
mysql > SELECT COUNT(*) FROM employees WHERE emp_no BETWEEN 10001 AND 12000
GROUP BY first_name;
mysql > SHOW PROFILES;
+------------+-------------+-----------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+------------+-------------+-----------------------------------------------------------------------------------------+
| 1 | 0.00026300 | SELECT * FROM employees WHERE emp_no=10001 |
| 2 | 0.00521400 | SELECT COUNT(*) FROM employees WHERE emp_no BETWEEN 10001 AND 12000 GROUP BY first_name |
+------------+-------------------------------------------------------------------------------------------------------+분석된 쿼리의 목록을 확인하려면 SHOW PROFILES 명령을 사용하면 된다. 위 예제의 "SHOW PROFILES" 명령의 결과는 두 쿼리에 대한 프로파일링 정보가 저장돼 있음을 보여준다. 프로파일링 정보는 모든 쿼리에 대해 저장되는 것이 아니라 최근 15개의 쿼리에 대해서만 저장된다. 그 이상 저장하려면 profiling_history_size 시스템 설정 변수를 조정하면 되는데, 최대 가능한 값은 100이다.
저장된 프로파일링 정보는 한꺼번에 모든 것을 볼 수도 있고, 각 쿼리별로 시스템 자원의 영역별로 구분해서 조회하는 것도 가능하다. 특정 쿼리의 상세 프로파일링 정보를 조회하려면 "SHOW PROFILE FOR QUERY <쿼리번호>" 명령을 실행하면 된다. 여기서 "쿼리번호"는 SHOW PROFILES 명령의 결과로 출력된 각 쿼리의 "Query_ID"다. 가장 최근에 실행된 쿼리의 상세 프로파일링 정보를 조회하려면 특정 "쿼리번호"를 지정할 필요 없이 "SHOW PROFILE" 명령만 실행하면 된다.
mysql > SHOW PROFILE FOR QUERY 1
+-----------------------------------+------------+
| Status | Duration |
+-----------------------------------+------------+
| starting | 0.000028 |
| checking query cache for query | 0.000042 |
| Opening tables | 0.000024 |
| System lock | 0.000004 |
| Table lock | 0.000027 |
| init | 0.000025 |
| optimizing | 0.000010 |
| statistics | 0.000042 |
| preparing | 0.000017 |
| executing | 0.000003 |
| Sending data | 0.000015 |
| end | 0.000003 |
| query end | 0.000002 |
| freeing items | 0.000013 |
| storing result in query cache | 0.000005 |
| logging slow query | 0.000001 |
| cleaning up | 0.000002 |
+-----------------------------------+------------+
mysql > SHOW PROFILE;
+-----------------------------------+------------+
| Status | Duration |
+-----------------------------------+------------+
| starting | 0.000028 |
| Opening tables | 0.000024 |
...
+-----------------------------------+------------+각 쿼리의 프로파일링 정보 가운데 CPU나 MEMORY 또는 DISK와 관련된 내용만 구분해서 확인할 수도 있다. 다음 예제는 CPU에 대한 프로파일링 상세 정보다. CPU 키워드 대신 "BLOCK IO" 또는 "MEMEORY" 등의 키워드를 사용하면 해당 하드웨어에 대한 상세 프로파일링 정보를 확인할 수 있다.
mysql > SHOW PROFILE CPU FOR QUERY 2;
+---------------------+------------+------------+-------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------------------+------------+-------------+
| starting | 0.000063 | 0.000000 | 0.000000 |
| Opening tables | 0.000012 | 0.000000 | 0.000000 |
| System lock | 0.000004 | 0.000000 | 0.000000 |
| Table lock | 0.000009 | 0.000000 | 0.000000 |
| init | 0.000018 | 0.000000 | 0.000000 |
| optimizing | 0.000000 | 0.000000 | 0.000000 |
| statistics | 0.000010 | 0.000000 | 0.000000 |
| preparing | 0.000009 | 0.000000 | 0.000000 |
| executing | 0.000040 | 0.000000 | 0.000000 |
| Sending data | 0.700681 | 0.696894 | 0.003999 |
| end | 0.000016 | 0.000000 | 0.000000 |
| removing tmp table | 0.000008 | 0.000000 | 0.000000 |
| end | 0.000003 | 0.000000 | 0.000000 |
| query end | 0.000003 | 0.000000 | 0.000000 |
| freeing items | 0.000432 | 0.000000 | 0.000000 |
| logging slow query | 0.000003 | 0.000000 | 0.000000 |
| cleaning up | 0.000002 | 0.000000 | 0.000000 |
+----------------------------------+------------+-------------+프로파일링의 결과에서 일반적으로 "Sending data" 항목의 소요 시간이 크게 표시될 때가 많은데, 이는 "Sending data" 처리가 단순하게 클라이언트로 데이터를 전송하는 것만 의미하는 것이 아니라 쿼리의 실행 결과 데이터를 테이블로부터 읽으면서 전송하는 것까지 포함하기 때문이다.
프로파일링 정보 조회 명령에서 CPU 대신 "SOURCE"라는 키워드를 지정하면 MySQL 소스 파일의 몇 번째 라인에 위치한 함수에서 얼마나 시간을 소모했는지도 확인해 볼 수 있다. MySQL 소스를 분석해 보고 싶다면 다음과 같은 프로파일링 결과로 어느 소스 파일의 어디를 확인해 봐야 할지 확인하는데 크게 도움이 될 것이다.
mysql > SHOW PROFILE SOURCE FOR QUERY 2;
+---------------------+------------+-------------------+----------------+---------------+
| Status | Duration | Source_function | Source_file | Source_line |
+----------------------------------+-------------------+----------------+---------------+
| starting | 0.000063 | NULL | NULL | NULL |
| Opening tables | 0.000012 | unknown function | sql_base.cc | 4515 |
| System lock | 0.000004 | unknown function | lock.cc | 258 |
| Table lock | 0.000009 | unknown function | lock.cc | 269 |
| init | 0.000018 | unknown function | sql_select.cc | 2519 |
| optimizing | 0.000000 | unknown function | sql_select.cc | 828 |
| statistics | 0.000010 | unknown function | sql_select.cc | 1019 |
| preparing | 0.000009 | unknown function | sql_select.cc | 1041 |
| executing | 0.000040 | unknown function | sql_select.cc | 1775 |
| Sending data | 0.700681 | unknown function | sql_select.cc | 2329 |
| end | 0.000016 | unknown function | sql_select.cc | 2565 |
| removing tmp table | 0.000008 | unknown function | sql_select.cc | 10881 |
| end | 0.000003 | unknown function | sql_select.cc | 10906 |
| query end | 0.000003 | unknown function | sql.parse.cc | 5055 |
| freeing items | 0.000432 | unknown function | sql.parse.cc | 6086 |
| logging slow query | 0.000003 | unknown function | sql.parse.cc | 1709 |
| cleaning up | 0.000002 | unknown function | sql.parse.cc | 1677 |
+----------------------------------+-------------------+----------------+---------------+참고
- Real MySQL
