记一次MySQL与NFS锁问题的分析与处理

字数 3825阅读 6353评论 0赞 6

事件背景

在周五晚上，对行内 zabbix 监控中的告警主机做一些参数调优与异常处理的过程中，进入了一台运行 Redis 与 MySQL 的服务器，发现 mysqld 进程运行，但是没有发现监听端口或套接字，重新启动 mysqld 依旧无法开启监听，但显示日志都是正常级别，这个问题一下子就让笔者打起了精神。

首先查看该 MySQL 的版本号是 5.6.36-x86_64，glibc 方式部署，是一个系统使用的应用性能监控（APM）数据库，无集群架构，操作系统是 RHEL 7.3 并且 SELinux 已关闭。

问题分析

首先是对 mysqld 进程进行重启，沿用当前的配置参数文件：

启动后没有错误状态返回，进程保持运行但没有开启监听，查看 log-error 也没有显示错误级别的日志，并且看日志显示 InnoDB 的快速缓冲池已经初始化完毕了。

但是这个日志是比较奇怪的，没有 socket created ... 的相关信息，仅在 InnoDB 的启动后结束了。

首先考虑是否因配置文件覆写或歧义的原因导致参数异常，而且检查配置文件也是大部分 MySQL 问题排查的第一步。这里查看了默认配置文件，发现 [mysqld] 节中并未有异常点，端口与目录配置都是正常。因为该数据库打开了 binlog，所以也查看 auto.cnf 文件配置，发现也是正常的 uuid 格式。并且没有修改过主机名。

下一步分析是否由于权限问题导致，但日志回显并未报错，这个的可能性已经不大。不过还是需要确定一下，发现数据库使用了 --user 指定 appuser 用户运行数据库进程，并且 basedir 与 datadir 下权限都是正常的。

后续申请了 root 用户查看 /var/log/message 等，也没有看到有关于端口冲突、服务异常等日志。

这个时候，选择直接分析 mysqld 运行的过程，使用 strace 查看程序栈，绕开 mysqld_safe 的干扰，直接追踪 mysqld。

strace ./bin/mysqld --defaults-file=./my.cnf

追踪到运行至系统函数 fcntl 时出现了诡异的停止，查看上下文，发现是打开了 InnoDB 的共享表空间文件后，对其进行加锁行为中挂起。

通过分析参数的结构体，发现是将 ibdata1 添加整个文件的排斥锁，为了明确判断该锁是否真的没有加上，使用 lsof 来判断。

文件描述符一栏中可见，ibdata1 是被 O_RDWR 的标志位打开（u），但是没有 F_WRLCK 的描述位（W，for a write lock on the entire file），因此可见 fcntl 的加锁出现了问题。

查看文件系统，发现该 MySLQ 的 datadir 是在挂载的 NFS v3 上，这个时候问题的原因差不多可以定位到与 NFS 有关了。NFS v2/v3 存在 NLM 的锁机制管理，所以很有可能是在这个环节出现了问题。

为了验证是 NFS 导致的，使用当前环境进行测试，重新指定一个本地存储作为 datadir，然后启动 MySQL。

避免影响原始数据，保证 id_logfile 等日志路径均在 datadir 下，以避免事务覆盖，将 NFS 卸载：

umount $MYSQL_DATADIR

然后重新初始化一个数据库目录，并且指向与系统本地存储：

mkdir /tmpdb

chown -R appuser: /tmpdb

mysql 版本为 5.6，还不能使用 mysqld 来初始化数据库目录，需使用自带脚本

scripts/mysql_install_db --user=mysql --basedir=/export/app/mysql --datadir=/tmpdb

cp -a ./my.cnf ./my.cnf.bak

sed -i 's/^datadir=.*/datadir=\/tmpdb/g' my.cnf

mysqld --defaults-file=./my.cnf --read-only=1

启动成功，并查看完整的启动日志如下：

至此，问题的关键似乎指向了存放了数据库目录的 NFS，而 mysql 软件目录、操作系统网络栈的问题都被排除在外了。

为了追究 NFS 问题的具体原因，查看与 NAS Server 的 rpc 检查。

发现其中 nlm 的端口 2052 通过 nc 测试无法连接，而 nlockmgr 是 NFS v2/v3 的加锁服务，那么问题极有可能就是由这个网络权限引起。

回想起最近网络组同事有调整过这个区的网络防火墙，而 NFS 的 rpc 类端口仅在初次 mount 或需要 portmap 时才调用，不具有网络是否可达的实时验证。例如挂载成功后，111 端口的断开不会影响挂载保持，但下次重新挂载会无法 mount 上。

为了支撑此结论，尝试分析系统日志回溯，首先查看 dmesg：

得知是在 lockd 模块上的处理出现了请求超时，于是在 message 上查看 lockd 的日志信息：

先从 kernel 的 nlm_bind_host 发送 rpc 任务进行通信。

但是尝试加锁出现 fatal。

512 的 ErrorCode 在头文件查找到是 ERESTARTSYS ，属于一种重试机制的退出，因此会在 60000 节拍后在此尝试。

问题处理

因为该 NFS 目录仅 export 给该服务器，则考虑到尽快恢复，先修改 /etc/fstab 将 NFS 的挂载参数修改为 nolock，重新启动 mysqld，启动正常，性能监控平台恢复数据库可用。使用 lsof 查看表空间数据文件的句柄标志位已成功加上锁（W）。

后续通知网络组同事，开启 rpcinfo 返回的端口访问权限，并排查挂载该 NAS 的主机的网络策略是否有这方面的缺失。

问题复盘

知道了此次故障的原因后，大概的解决方案也就清晰了，但这里选择再次深入分析，了解此次造成问题的深层次原因。于是笔者在电脑上重建一个类似的环境，通过抓包的方式进行复盘分析。选择的环境是两台 RHEL 7.3，MySQL 也是 mysql-5.6 的 glibc 版，nfs 服务由 nfs-utils 提供（通过 vers 指定为版本3）。

注意，这里并非完全模拟问题中的 NAS 服务器，而且部分端口号并不一致。

在服务端配置完 rpc 和 nfs 并正常提供服务后，rpc 的的转发信息如下。