Oracle Linux上使用MySQL卡死的问题处理(时间变化导致MySQL hung up)

本文主要是介绍Oracle Linux上使用MySQL卡死的问题处理(时间变化导致MySQL hung up)，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

预先操作

打开MySQL的general log, 方便排查
临时一次: mysql -uroot -p 进入，set global general_log='ON';
永久: MySQL配置文件, /etc/my.cnf 在[mysqld]下添加 general-log=1
默认日志位置: /var/lib/mysql/localhost.log

打开events_statements_history 历史语句事件表

update performance_schema.setup_consumers set ENABLED = 'YES' where NAME='events_statements_history';

复现MySQL卡死的情形, 并检查相关日志, 处理问题

mysql -uroot -p 进入MySQL

查看事务卡住前10秒的SQL语句信息

mysql> SELECT ->     ps.id AS processlist_id,->     trx_started,->     trx_isolation_level,->     esh.EVENT_ID,->     esh.TIMER_WAIT,->     esh.event_name AS EVENT_NAME,->     esh.sql_text AS sql1,->     esh.RETURNED_SQLSTATE,->     esh.MYSQL_ERRNO,->     esh.MESSAGE_TEXT,->     esh.ERRORS,->     esh.WARNINGS-> FROM->     information_schema.innodb_trx trx->         JOIN->     information_schema.processlist ps ON trx.trx_mysql_thread_id = ps.id->         LEFT JOIN->     performance_schema.threads th ON th.processlist_id = trx.trx_mysql_thread_id->         LEFT JOIN->     performance_schema.events_statements_history esh ON esh.thread_id = th.thread_id-> WHERE->     trx.trx_started < CURRENT_TIME - INTERVAL 10 SECOND->         AND ps.USER != 'SYSTEM_USER'-> ORDER BY esh.EVENT_ID;

输入SHOW ENGINE INNODB STATUS\G, 查看是否有死锁, 是否有事务卡住

本次异常部分:

------------
TRANSACTIONS
------------
---TRANSACTION 8548, ACTIVE 18 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 100, OS thread handle 139649020675840, query id 5122 localhost vmi updating
UPDATE `django_session` SET `session_data` = 'session date', `expire_date` = '2019-12-02 06:22:38.968049' WHERE `django_session`.`session_key` = 'c6721mjofbqdc8fktku48ek1x16qbfbi'
------- TRX HAS BEEN WAITING 18 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 162 page no 4 n bits 72 index PRIMARY of table `vmi`.`django_session` trx id 8548 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 5; compact format; info bits 00: len 30; hex 63363732316d6a6f666271646338666b746b753438656b31783136716266; asc c6721mjofbqdc8fktku48ek1x16qbf; (total 32 bytes);1: len 6; hex 000000002162; asc     !b;;2: len 7; hex 0100000141137f; asc     A  ;;3: len 30; hex 5a5463314e4463775a544130596a63344e6a426a4d6a63324d446b795a57; asc ZTc1NDcwZTA0Yjc4NjBjMjc2MDkyZW; (total 252 bytes);4: len 8; hex 99a4c465a20b7899; asc    e  x ;;------------------
---TRANSACTION 8547, ACTIVE 19 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 88, OS thread handle 139649022445312, query id 5119 localhost vmi updating
UPDATE `django_session` SET `session_data` = 'session data', `expire_date` = '2019-12-02 06:22:37.552609' WHERE `django_session`.`session_key` = 'c6721mjofbqdc8fktku48ek1x16qbfbi'
------- TRX HAS BEEN WAITING 19 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 162 page no 4 n bits 72 index PRIMARY of table `vmi`.`django_session` trx id 8547 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 5; compact format; info bits 00: len 30; hex 63363732316d6a6f666271646338666b746b753438656b31783136716266; asc c6721mjofbqdc8fktku48ek1x16qbf; (total 32 bytes);1: len 6; hex 000000002162; asc     !b;;2: len 7; hex 0100000141137f; asc     A  ;;3: len 30; hex 5a5463314e4463775a544130596a63344e6a426a4d6a63324d446b795a57; asc ZTc1NDcwZTA0Yjc4NjBjMjc2MDkyZW; (total 252 bytes);4: len 8; hex 99a4c465a20b7899; asc    e  x ;;------------------
---TRANSACTION 8546, ACTIVE (PREPARED) 22 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 96, OS thread handle 139649020970752, query id 5116 localhost vmi starting
commit
--------

没有 LATEST DETECTED DEADLOCK 列, 只有TRANSACTIONS列, 且显示隔离级别已经是READ COMMITTED, 查询时不会锁表，不会导致update卡住。
说明没有发生死锁，只是事务hung up.
复制卡住的事务, 到general log 中搜索, 排查前后的SQL语句, 发现发生hung up的前后时间发生变化, 网上有资料显示时间变化会导致MySQL卡住.

排查时间变化的原因

/var/log/message 日志中显示重启之后server有两次时间变化, 对比正常的server只有一次"Time has been changed", 这一次是执行启动之后的时间同步脚本产生的.

新建一台没有装我们服务的Oracle Linux Server, 发现每次reboot, Server都会有时间变化. 无论重启前是否设置硬件时间为系统时间hwclock --systohc.

[root@localhost ~]# timedatectlLocal time: Wed 2019-12-04 16:44:49 CSTUniversal time: Wed 2019-12-04 08:44:49 UTC #国际统一时钟RTC time: Wed 2019-12-04 08:44:49 #硬件时钟Time zone: Asia/Shanghai (CST, +0800)NTP enabled: yes
NTP synchronized: yesRTC in local TZ: no DST active: n/a

reboot之后Universal time会变, 改变时message里面的记录:

Dec  3 17:46:59 localhost systemd-logind: Watching system buttons on /dev/input/event0 (Power Button)
Dec  3 17:46:59 localhost systemd-logind: New seat seat0.
Dec  3 17:46:59 localhost systemd: Started Dump dmesg to /var/log/dmesg.
Dec  3 17:46:59 localhost rsyslogd: [origin software="rsyslogd" swVersion="8.24.0" x-pid="6113" x-info="http://www.rsyslog.com"] start
Dec  3 17:46:59 localhost systemd: Started System Logging Service.
Dec  3 17:46:59 localhost systemd: Started Resets System Activity Logs.
Dec  3 17:46:59 localhost systemd: Started GSSAPI Proxy Daemon.
Dec  3 17:46:59 localhost systemd: Reached target NFS client services.
Dec  3 17:46:59 localhost systemd: Starting NFS client services.
Dec  3 17:46:59 localhost journal: Pref_Init: Using '/etc/vmware-tools/vgauth.conf' as preferences filepath
Dec  3 17:46:59 localhost polkitd[6122]: Started polkitd version 0.112
`Dec  3 17:46:59 localhost journal: Core dump limit set to -1`
`Dec  4 01:39:08 localhost systemd: Time has been changed`
Dec  4 01:39:08 localhost systemd: Started Authorization Manager.
Dec  4 01:39:08 localhost systemd: Starting firewalld - dynamic firewall daemon...
Dec  4 01:39:09 localhost systemd: Started firewalld - dynamic firewall daemon.
Dec  4 01:39:09 localhost systemd: Reached target Network (Pre).
Dec  4 01:39:09 localhost systemd: Starting Network (Pre).
Dec  4 01:39:09 localhost systemd: Dependency failed for Network Manager Wait Online.

reboot之后，重启时系统时间改变(7小时52分)这个问题，目前没有找到原因。

解决办法:

在启动时再init.d中设置脚本, 先用ntpdate同步时间. 此方法有问题在于，不能控制脚本执行的时间在本身系统时间变化之后，所以不可行。

自启动的服务:

server1:~ # systemctl cat set_my_clock.service
# /usr/lib/systemd/system/set_my_clock.service
[Unit]
Description=Syncing system and hardware clock[Service]
Type=oneshot
ExecStart=/etc/init.d/set_my_clock start
ExecStop=/etc/init.d/set_my_clock stop
RemainAfterExit=true[Install]
WantedBy=basic.target

开机自启动的脚本

# cat /etc/init.d/set_my_clock
#!/bin/bash
set -x
case "$1" instart|stop)echo "Set Sys time according to Hardware Clock";# This will force sync the local system clock with NTP server/sbin/ntpdate -u 192.168.1.00 192.168.1.101;# This will sync our hwclock with the system clock time/sbin/hwclock --systohc;;;*)echo "Usage: $0 {start|stop}"exit 1;;
esacecho "done !"
exit 0

启用这个服务

# systemctl enable set_my_clock.service

在同步时间之前先停止我们的服务，等到同步完成，再启动我们的服务。

systemctl stop ntpd
SERVER=pool.ntp.org
if ntpdate -t 15 ${SERVER}; then # -t 15:超时时间为15秒echo "sync time succeed"
elseecho "sync time failed"
fi
hwclock --systohc #将硬件时钟调整为与目前的系统时钟一致。
systemctl start ntpd
brctl stp virbr0 off
timedatectl set-local-rtc 0 #0: 将你的硬件时钟设置为协调世界时（UTC）1: 将硬件时钟设置为本地时区：