잘못된 인덱스 사용으로 인해 장시간 Mysql 프로세스가 물리는 현상이 발생 할 경우

어떤 쿼리문이 이런 현상을 야기 시켰느냐에 대한 분석 시

Slow Query 를 사용하시면 손 쉽게 부하가 증가되는 쿼리를 찾으실 수 있으실 것입니다.

 

<사용 방법>

1. mysql 환경 설정 파일인 my.cnf 파일에 아래 내용을 추가 하시면 됩니다.

 

[mysqld]
long_query_time=초제한(1~10)

log-slow-queries=로그파일명

 

ex)

[mysqld]

log-slow-queries = /temp/mysql-slow.log
long_query_time = 3

위의 의미는 쿼리타임이 3초를 초과하는 쿼리에 대해 /temp/mysql-slow.log 파일에 로그를 남기라는 의미 입니다.

 

2. mysql 구동시 적용하는 방법이 있습니다.

$ mysqld_safe --datadir=데이터디렉토리 --log-slow-queries[=file_name] &

 

< 로그 파일의 내용 >

# Time: 080218 13:25:06
# User@Host: XXXXX[xxxxx] @ localhost [127.0.0.1]
# Query_time: 8  Lock_time: 0  Rows_sent: 1  Rows_examined: 98767
use CrediMail;

SELECT count(*) FROM test

 

위의 양식으로 slow 쿼리가 남게 됩니다.

slow log 로 남은 쿼리들은 explain 을 사용하여 정상적인 index를 타고 있는지 체크 해 보는 방법으로

문제점을 찾아 가시면 될 것입니다.

ex) mysql>explain 문제시 되는 쿼리;

 

<참고>

Query_time : 쿼리 처리 시간

Lock_time : lock 이 걸린 횟수

Row_sent : 조회 결과 Row 수

Rows_examined : 조회 대상 Row 수

 

Reference URL

http://dev.mysql.com/doc/refman/5.0/en/slow-query-log.html

http://www.sitepoint.com/forums/showthread.php?t=397521

MySQL을 운용하다보면 궁극적으로 봉착하는 문제가 바로 Slow queriy 다. 이 Slow query 야말로 모둔 query의 적이라 해도 과언이 아니라고 생각한다. MySQL에서는이 Slow query를 log로 기록할수 있게 되어있는데 이 설정이 꽤나 delicate 하다. 다음은 MySQL 5.0에서 동작하는 설정이다.

1. Check the gloval variables

in the mysql command prompt,

show global variables WHERE Variable_name LIKE ‘l%’;

+———————————+—————————+
| Variable_name | Value |
+———————————+—————————+
| language | /usr/share/mysql/english/ |
| large_files_support | ON |
| large_page_size | 0 |
| large_pages | OFF |
| license | GPL |
| local_infile | ON |
| locked_in_memory | OFF |
| log | OFF |
| log_bin | OFF |
| log_bin_trust_function_creators | OFF |
| log_error | |
| log_slave_updates | OFF |
| log_slow_queries | ON |
| log_warnings | 1 |
| long_query_time | 3 |
| low_priority_updates | OFF |
| lower_case_file_system | OFF |
| lower_case_table_names | 0 |
+———————————+—————————+

2. Configuration

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=1

# added 1007/10/05
max_connections = 10000
table_cache = 256
wait_timeout = 900
max_connect_errors = 10000
key_buffer = 16M
sort_buffer = 1M
set-variable = long_query_time=3
log-slow-queries=/var/log/mysqld-slow.log

[mysql.server]
user=mysql
basedir=/var/lib

[mysqld_safe]
log-error=/var/log/mysqld.log
#log-slow-queries=/var/log/mysqld-slow.log
pid-file=/var/run/mysqld/mysqld.pid

# added 2007/10/05
#set-variable = long_query_time=3
#log-slow-queries=/var/log/mysqld-slow.log

 

Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse and summarize the MySQL slow query log. Options are

  --verbose    verbose
  --debug      debug
  --help       write this text to standard output

  -v           verbose
  -d           debug
  -s ORDER     what to sort by (t, at, l, al, r, ar etc), 'at' is default
  -r           reverse the sort order (largest last instead of first)
  -t NUM       just show the top n queries
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time

 

 

Slow query filter

 

용도  : slow query log 에서 실행 시간이 일정 시간 이상이 되는 쿼리 와 일정 row 이상 access하는 쿼리만 filter 해 낼 수 있음

 

사용법

 

cat ‘slow query log’ msql_slow_log_filter -T timesec -R numrows  ( T, R option은 단독으로 사용할 수 있음 )

Ex)

cat  kidsmbbs1-slow.log | msql_slow_log_filter  -R 400000  ( 400000 row 이상 access 하는 쿼리만 추출 )

 

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_comment_121`;

# Time: 070307  <?xml:namespace prefix = "st1" ns = "urn:schemas-microsoft-com:office:smarttags" />5:01:11

# Query_time: 4  Lock_time: 0  Rows_sent: 31864  Rows_examined: 455198

select distinct code from tb_comment_121;

# Time: 070307  5:06:17

# Query_time: 5  Lock_time: 0  Rows_sent: 455596  Rows_examined: 455596

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_comment_121`;

# Time: 070308  5:01:09

# Query_time: 4  Lock_time: 0  Rows_sent: 31905  Rows_examined: 455596

select distinct code from tb_comment_121;

 

cat  kidsmbbs1-slow.log | msql_slow_log_filter  -T 8  ( 8초 이상 걸리는 쿼리만 추출 )

 

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_bbs_154`;

# Time: 070306  5:00:40

# Query_time: 8  Lock_time: 0  Rows_sent: 1  Rows_examined: 329849

select count(indexno) as su from tb_comment_160 where wdate>=1173020400 and wdate<=1173106800;

# Time: 070306 14:13:22

# Query_time: 15  Lock_time: 0  Rows_sent: 37014  Rows_examined: 37014

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_bbs_154`;

# Time: 070307  5:00:40

# Query_time: 14  Lock_time: 0  Rows_sent: 37014  Rows_examined: 37014

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_bbs_154`;

 

Aggregating slow query log

 

용도 : slow query log 에 있는 slow query에 대해서 aggregate 한 정보를 보여줌, 즉 실행 횟수, 평균 수행 시간, 총 수행 시간 , access 한 rows  , 개인적으로 mysqldumpslow 보다 보기  좋은 것 같습니다.

 

### 4 Queries

### Total time: 12, Average time: 3

### Taking 3 , 3 , 3 , 3  seconds to complete

### Rows analyzed 144673, 150153, 185656 and 189447

SELECT /*!XXX SQL_NO_CACHE */ * FROM `tb_bbs_limit`;

 

SELECT /*!40001 SQL_NO_CACHE */ * FROM `tb_bbs_limit`;

 

 

### 2 Queries

### Total time: 10, Average time: 5

### Taking 5 , 5  seconds to complete

### Rows analyzed 78261 and 81439

use ykids_bbs;

SELECT /*!XXX SQL_NO_CACHE */ * FROM `tb_bbs_XXX`;