monによるMySQLのデッドロック検知とロギング

更新が激しいDB（MySQL)でInnoDBのロック競合が発生し、アプリケーションサーバが詰まる状況が発生してしまいました。
障害監視はmonというアプリケーションで行なっているのですが、
今回はこのmonを使ってMySQL デッドロックの検知とロギングを行いたいと思います。

monについては下記の資料をご参照ください。
Mon, Muninによる楽々監視生活

デッドロック解析は下記サイトのSQLを利用しています。
MySQL InnoDBにおけるロック競合の解析手順

前提
・MONのサーバは既に構築済みであること
・DBサーバはMySQL5.5であること（MySQL5.1+InnoDB pluginでも可）

〜〜〜　以下、監視対象のDBサーバにて作業　〜〜〜

SNMPインストール

yum install net-snmp

lockを検知するスクリプト作成

vim /usr/local/sbin/mysql_lock_check.sh

#!/bin/sh

#--------------------#
# Define ENV         #
#--------------------#
export PATH=$PATH:/usr/local/mysql/bin:/usr/bin/mysql
HOST=`hostname`

#--------------------#
# DIR & FILE         #
#--------------------#
NAME=`basename $0 .sh`
PIDFILE=`dirname $0`/$NAME.pid
MYSQL_DIR='/data/mysql'

if [ -f "$PIDFILE" ]
then
    echo 2
    exit 2;
fi

echo $$ > $PIDFILE

CNT=`mysql -N -uroot -e 'select count(*) from information_schema.INNODB_LOCK_WAITS'`

    if [ "${CNT}" != "0" ]; then
        rm $PIDFILE
　　　　echo `date` >> ${MYSQL_DIR}/${HOST}_innodb_lock.log
        mysql -uroot -e 'select t_b.trx_mysql_thread_id blocking_id,t_w.trx_mysql_thread_id requesting_id,p_b.HOST blocking_host,p_w.HOST requesting_host,l.lock_table lock_table,l.lock_index lock_index,l.lock_mode lock_mode,p_w.TIME seconds,p_b.INFO blocking_info,p_w.INFO requesting_info from information_schema.INNODB_LOCK_WAITS w,information_schema.INNODB_LOCKS l,information_schema.INNODB_TRX t_b,information_schema.INNODB_TRX t_w,information_schema.PROCESSLIST p_b,information_schema.PROCESSLIST p_w where w.blocking_lock_id = l.lock_id and w.blocking_trx_id = t_b.trx_id and w.requesting_trx_id = t_w.trx_id and t_b.trx_mysql_thread_id = p_b.ID and t_w.trx_mysql_thread_id = p_w.ID order by requesting_id,blocking_id \G' >> ${MYSQL_DIR}/${HOST}_innodb_lock.log
        echo 1
        exit 1;
    fi

rm $PIDFILE
echo 0
exit 0;

SNMPの設定変更

vim /usr/local/net-snmp/etc/snmpd.conf

下記を追記

extend .1.3.6.1.4.1.3000.40 mysql_lock /bin/sh /usr/local/sbin/mysql_lock_check.sh

〜〜〜　以下、MONサーバで作業　〜〜〜

MONのチェックスクリプト作成

vim /usr/local/mon/mon.d/mysql_InnoDB_lock_check.monitor

#!/bin/sh

RET=''
ERRORWORD="MySQL InnoDB lock check failed."
ERRORWORD1="MySQL InnoDB locked."
ERRORWORD2="MySQL InnoDB lock check is already running."

for host in "$@"
do

    #EXEC
    RET=`/usr/local/net-snmp/bin/snmpwalk -v2c -c casnmp ${host} .1.3.6.1.4.1.3000.40.3.1.4 | gawk '{print $4}'`

    #RET CHECK
    if [ "${RET}" = 0 ]; then
            :
    else
        if [ "$SummaryOutput" = "" ]; then
                SummaryOutput=${host}
                eval DetailedText=\${host}\" : \"\${ERRORWORD${RET}}
        else
                SummaryOutput="${SummaryOutput} ${host}"
                eval DetailedText=\${DetailedText}\" \\n\"\${host}\" : \"\${ERRORWORD${RET}}
        fi
    fi

done

# ERROR CHECK
if [ "${SummaryOutput}" != "" ]; then
        echo "${SummaryOutput}"
        echo -e "${DetailedText}"
        exit 1
fi

exit 0

MONの設定ファイルに追記

vim /usr/local/mon/etc/mon.cf

hostgroup hogehoge-mysql-InnoDB_lock {監視対象IPアドレス}

watch hogehoge-mysql-InnoDB_lock
   service mysql_InnoDB_lock
      interval 3m
      monitor mysql_InnoDB_lock_check.monitor
      allow_empty_group
      period wd {Sun-Sat}
         alertevery 5m
         alertafter 3 15m
         alert mail.alert -f {アラートメール送信先@hogehoge.com}
         upalert mail.alert -f {アラートメール送信先@hogehoge.com} -S "hogehoge server is back up [mysql_InnoDB_lock]" -u {アラートメール送信先@hogehoge.com}

MONサーバ再起動
/etc/init.d/mon stop
/etc/init.d/mon start

ロック情報のログの見方
mysqlのディレクトリにログを吐いてます。

less  ${MYSQL_DIR}/hostname_innodb_lock.log

0 : 2013年 3月 14日 木曜日 16:02:20 JST
*************************** 1. row ***************************
1 : blocking_id: 220
2 : requesting_id: 227
3 : blocking_host: 10.*.*.101:53890
4 : requesting_host: 10.*.*.102:32783
5 : lock_table: `hoge`.`user_status_5`
6 : lock_index: `PRIMARY`
7 : lock_mode: X
8 : seconds: 38
9 : blocking_info: NULL
10: requesting_info: update user_status_5 set f_cnt = f_cnt+1 where user_id = 130

このログからは
1行目と2行目と8行目の情報から
　220番のスレッドが227番のスレッドを38秒待たせている

5行目と6行目の情報から
　220番のスレッドはuser_status_5テーブルの主キーを排他ロックしている

3行目の情報から
　10.*.*.101のサーバがブロックしている

9行目の情報から
　220番のスレッドは現在アイドル状態である

10行目の情報から
　227番のスレッドはuser_id:130のレコードを更新しようとしている

デッドロックを検知したら、どのアプリケーションサーバがブロックしているのかわかるのでそのプロセスを殺すなりしましょう。
頻繁に発生するようなら、データ更新の仕組み自体も改善してもらいましょう…。