2장 병목 지점 찾기

무엇을 측정할 것인가

• 단위 시간당 트랜잭션
• 반응 시간 또는 대기시간
• 성능 확장성
• 동시성: 중요한 것은 주어진 시간 동안 쿼리를 실행하는 연결이 몇 개냐 되느냐다. 즉, 동시에 작업 중인 스레드나 연결의 개수를 뜻하는 유효 동시성이 중요하다. 동시성이 증가할 때 성능이 크게 떨어지지 않는지 측정해보자.
  

MySQL 프로파일링

쿼리를 로그로 남기기

MySQL 에는 제네럴 로그와 슬로우 로그가 있다. 제네럴 로그는 서버가 쿼리를 받는 대로 모든 쿼리를 기록하므로 오류 때문에 실행되지 않은 쿼리도 기록된다. 그리고 연결이나 연결 끊기 같은 비 쿼리 이벤트까지 포함해 모든 쿼리를 기록한다. 구성 지시문 한 줄이면 이 기능을 활성화할 수 있다.

1

log = <file_name>

반면에 슬로우 쿼리는 실행된 쿼리만 포함된다. 특히 지정된 시간보다 오래 걸린 쿼리를 로그로 남긴다. 아래의 구성 예제는 슬로우 쿼리를 활성화하여 2초 이상 걸린 쿼리를 모두 잡아내며 인덱스를 전혀 사용하지 않은 쿼리를 로그로 남긴다.

1
2
3
4

log-slow-queries = <file_name>
long_query_time = 2
log-queries-not-using-indexes
log-slow-admin-statements

인덱스를 쓰지 않더라도 쿼리 속도가 아주 빠르고 자주 실행되는 쿼리도 얼마든지 있을 수 있지만 log-queries-not-using-indexes 설정이 있으면 그런 쿼리를 모두 로그로 남기게 되고, 이는 성능 문제와 디스크 공간을 과하게 차지하는 문제가 발생하게 된다. 슬로우 로그를 사용해 느린 쿼리 문제를 해결하는 일이 항상 명확하진 않기 때문에 슬로우 쿼리를 너무 맹신하지는 말자.

• 테이블이 잠겨서 쿼리가 대기해야 했을 수 있다. Lock_time 은 쿼리가 잠금이 풀리기를 얼마나 기다렸는지 알려준다.
• 데이터나 인덱스가 메모리에 캐싱되기 전일지 모른다. 이는 MySQL 이 처음 시작되었거나 아직 튜닝되지 않았을 때 흔하다.
• 야간 백업 과정이 진행 중으라 모든 디스크의 I/O 가 느려졌을지 모른다.
• 서버가 다른 쿼리를 동시에 실행해 이 쿼리가 느려진 것일지 모른다.

MySQL 서버 프로파일링

서버가 시간을 가장 많이 소모하는 작업이 무엇인지 알아내는 최고의 서버 프로파일링 방법 중 하나는 SHOW STATUS 를 사용하는 것이다. 이 때의 유용한 변수는 아래와 같다.

• Bytes_received 와 Bytes_sent: 서버와 주고 받은 트래픽
• Com_* : 서버가 실행한 명령어
• Created_* : 쿼리 실행 과정에서 만든 임시 테이블과 파일
• Hanlder_* : 스토리지 엔진 연산
• Select_* : 다양한 유형의 조인 실행 계획
• Sort_* : 몇 가지 유형의 정렬 정보

SHOW PROCESSLIST 를 사용하거나 SHOW STATUS 를 사용하면 프로파일링에 도움이 된다. (innotop 과 같은 도구를 쓰는 것도 편하다)

운영체제 프로파일링

네트워크 활동을 발견하고 기본적인 문제 해결을 찾는 예시를 살펴보자.
MySQL 의 SHOW PROCESSLIST 를 실행했을 때 아래와 같은 내용이 출력이 된다.

1
2
3
4

Id: 91296
User: Web
Host: sargon.cluster3:37636
...

이제 netstat 을 통해 어느 프로세스가 포트 번호 37636 을 이용해 연결을 열었는지 알아낸다.

1
2
3

root@saragon# netstat -ntp | grep :37676

tcp 0 0 192,168,0,12:37636 192.168.0.21:3306 ESTABLISHED 16072/apache2

프로세스 번호와 이름은 출력 결과의 마지막 부분에 나온다. 프로세스 16072 가 이 연결을 시작했고 이 연결은 Apache 웹 서버에서 왔다. 프로세스 ID 를 알았으면 더 나아가 프로세스가 가진 다른 네트워크 연결은 무엇인지 등 프로세스에 관한 그 밖의 정보를 많이 알아낼 수 있다.

1
2
3
4
5

root@saragon# netstat -ntp | grep 16072/apache2

tcp 0 0 192,168,0,12:37636 192.168.0.21:3306 ESTABLISHED 16072/apache2
tcp 0 0 192,168,0,12:37636 192.168.0.21:3306 ESTABLISHED 16072/apache2
tcp 0 0 192,168,0,12:57917 192.168.0.3:389 ESTABLISHED 16072/apache2

Apache 의 작업 스레드가 MySQL 두 개(포트 3306)와 다른 컴퓨터에 대한 연결(포트 389)을 연 것 같다. 389번 포트 정보를 알기 위해 아래를 실행한다.

1
2
3
4

root@saragon# grep 389 /etc/services

ldap   389/tcp # Lightweight Directory Access Protocol
ldap   389/udp

이제 이 서버가 LDAP 인증을 이용한다는 사실을 알게 됐다. 그럼 프로세스 16702 에 대해 더 알아보자. ps 를 이용하면 프로세스가 무슨 일을 하는지 아주 쉽게 알 수 있다.

1

root@saragon# ps -eaf | grep 'UID\|16702'

프로세스가 연 파일을 lsof 명령어를 이용해 나열할 수도 있다. 이 기능은 유형에 상관없이 정보를 찾아낼 때 아주 좋은데 유닉스에선 모든 게 파일이기 때문이다.

1

root@saragon# lsof -i -P | grep 16702