ARTICLE DETAIL

资讯详情

深耕郑州网站建设与运营推广的一线实战洞察。

MySQL日志排查实战:从错误日志到binlog一次搞定

MySQL日志排查实战:从错误日志到binlog一次搞定 1. 一次线上事故日志差点让我从“背锅侠”变“救火队长”大概两年前的一天下午我正坐在工位上改需求运维同事突然在群里扔了一条消息“线上用户反馈页面打不开接口全部超时赶紧看下”。跟着就是监控面板里一片飘红的截图数据库连接数直接打到了上限。我第一反应是数据库挂了。但网站在跑、进程也在怎么连不上当时我连看都没看进程直接打开错误日志一路翻下去十几秒钟就定位到了问题业务侧开了太多长连接把MySQL的最大连接数吃满了。再往上看慢查询日志发现一条本来该走索引的SQL因为字段类型不一致把几百万行的表拖了个全表扫描持有锁的时间过长后续请求全部排队积压。那一刻我意识到MySQL日志这东西平时没人惦记出了事它就是唯一的救命稻草。但你不可能等出事了才去学怎么看日志那会儿你连日志文件放在哪儿、开了几个日志开关都不知道就只能剩下干瞪眼。这篇文章就是写给还没系统梳理过MySQL日志的同学。我不讲那些文档里能查到的标准介绍而是从实际排障的角度把错误日志、通用查询日志、慢查询日志、binlog这四类核心日志怎么开、怎么查、怎么用、怎么避坑一次说清楚。不管你是刚接手MySQL的DBA、要排查线上问题的后端开发还是正在自学数据库原理的运维新人看完都能直接上手。2. 日志家族全貌四种日志各管一段别再把它们搞混了很多新手一提到MySQL日志就笼统地问“日志在哪看”。其实MySQL的日志不是一个文件而是好几套互相独立、职责完全不同的记录体系。搞混它们排查方向就会从一开始就偏掉。我习惯把这四类日志比喻成一个团队里不同的角色错误日志像个值班员它只记录数据库从启动到运行过程中发生的严重事件——启动失败、磁盘满、崩溃重启、连接拒绝都记在这里。它不关心你每天执行了几万条SQL只记录“服务器本身出了什么问题”。通用查询日志像个审讯室的录音机你执行的每一条SQL包括连接建立、断开、提交事务都会被它一字不差地记下来。它能回答“这个SQL到底有没有被执行过”“执行了几次”这种问题但由于记录量巨大生产环境默认是关闭的否则磁盘会迅速被写爆。慢查询日志像个性能体检报告专门记录执行时间超过阈值的SQL语句。线上数据库变慢、接口超时、锁等待绝大多数都能从慢查询日志里找到肇事SQL。这也是生产环境最常用的排障日志。**二进制日志binlog**则像飞机上的黑匣子它记录的是数据库发生的每一笔数据变更操作。主从复制靠它同步数据误删靠它恢复增量备份靠它搭建。它记录的不是“查询”而是“变更”。常被忽略的还有两类和InnoDB存储引擎强相关的日志redo log记录物理页的修改用于崩溃恢复时找回未落盘的数据undo log记录事务发生前的数据镜像用于回滚事务和MVCC多版本控制。这两类日志由存储引擎内部管理普通排查基本碰不到理解它们的存在即可。四类日志的对比我用一张表说明白日志类型记录内容默认状态典型场景查看方式错误日志启动/运行时的错误事件开启连不上、启动失败直接读文件支持tail通用查询日志所有SQL和连接操作关闭排查“有没有执行过某条SQL”读文件慢查询日志超过阈值的SQL常配置开启性能分析、锁等待排查读文件 mysqldumpslow二进制日志数据变更操作取决于log_bin配置主从复制、数据恢复mysqlbinlog工具分清这四类日志你才知道在什么场景下去打开哪个文件。否则你在通用日志里翻半天慢SQL或者拿binlog去查“为什么连不上”方向就全反了。3. 日志文件到底在哪配置项、默认路径和常用查看Shell命令3.1 先找出当前生效的日志配置不同Linux发行版、不同MySQL安装方式源码编译、yum安装、Docker部署日志文件的默认路径可能完全不一样。最靠铺的做法不是去猜路径而是直接问MySQL自己。登录进MySQL执行下面的SQL当前实例的日志相关配置一目了然SHOW VARIABLES LIKE log_error; SHOW VARIABLES LIKE general_log%; SHOW VARIABLES LIKE slow_query_log%; SHOW VARIABLES LIKE log_bin%;你看到的结果大概是这样的--------------------------------------------------- | Variable_name | Value | --------------------------------------------------- | log_error | /var/log/mysql/error.log | --------------------------------------------------- | general_log | OFF | --------------------------------------------------- | slow_query_log_file | /var/lib/mysql/slow.log | ---------------------------------------------------逐个解读一下log_error的值是错误日志文件的绝对路径。如果值是空说明MySQL把错误信息输出到了stderr此时要看启动脚本里重定向到哪个文件。general_log是ON/OFF开关general_log_file是通用日志的保存位置。slow_query_log指向慢查询日志的路径。log_bin如果为ONlog_bin_basename是binlog文件所在目录和前缀。除了SQL查询还可以用命令行直接看。连接MySQL时加-e参数一行搞定不需要先进交互界面mysql -uroot -p -e SHOW VARIABLES LIKE slow_query_log%;3.2 查看日志文件内容的几条Shell命令定位到日志文件后最常用的查看命令无非这几条但细节上有些坑# 持续跟踪输出适合观察实时写入 tail -f /var/log/mysql/error.log # 查看最近200条 tail -200 /var/log/mysql/error.log # 按关键字过滤比如只找错误级别 grep -i error /var/log/mysql/error.log # 找回滚/死锁相关信息 grep -A 20 -i deadlock /var/lib/mysql/slow.log # 配合less实现分页查看还能用 / 搜索 less /var/log/mysql/error.log这里有个使用习惯想多说一句如果日志文件很大不要直接用cat整个文件既卡终端又占内存。先用ls -lh看文件大小再决定用tail还是less。超过几百MB的日志文件建议直接用less配合关键字搜索或者把需要排查的时间段用sed -n /2025-01-05 10:00/,/2025-01-05 10:30/p截出来再分析效率完全不同。3.3 一个最容易找错文件的情况Docker部署现在很多环境用Docker跑MySQL日志路径跟本机安装完全是两回事。容器内的/var/log/mysql/默认是虚拟文件系统直接进入容器可能连vi都没有更别提单文件了。正确的做法是把容器内日志目录挂载到宿主机比如docker run -d \ --name mysql8 \ -v /data/mysql/log:/var/log/mysql \ -v /data/mysql/lib:/var/lib/mysql \ -e MYSQL_ROOT_PASSWORDyour_password \ mysql:8.0挂载之后日志直接在宿主机/data/mysql/log下读人都不用进容器。如果你没挂载日志目录那就只能在宿主机上用docker logs mysql8看标准输出。这种方法能看到启动日志但慢查询日志、binlog这类文件化日志是拿不到的跟排查需求经常对不上。所以容器化部署MySQL一定要在规划阶段就把数据卷和日志卷挂出来不然后面排查成本成倍增加。4. 慢查询日志深度实战定位拖垮线上库的元凶SQL4.1 开启慢查询日志的两个途径慢查询日志的开关有三个关键参数slow_query_log决定开不开long_query_time决定阈值秒log_queries_not_using_indexes决定是否把没走索引的查询也记下来。临时开启用SQL设置即可SET GLOBAL slow_query_log ON; SET GLOBAL long_query_time 2; SET GLOBAL log_queries_not_using_indexes ON;注意两点。第一SET GLOBAL只对后建立的新连接生效当前这条连接如果不重新连接还是看不到效果。第二MySQL重启之后全局设置会丢失生产环境必须写进配置文件[mysqld] slow_query_log ON slow_query_log_file /var/log/mysql/slow.log long_query_time 2 log_queries_not_using_indexes ONlong_query_time的阈值设置要有度。设为1通常能覆盖大多数优化需求但如果线上本身压力大、慢SQL又多日志量会暴涨。建议先设到2秒观察一周再把阈值慢慢往下调。阈值单位是秒支持小数比如long_query_time 0.5表示记录超过500毫秒的查询。4.2 慢查询日志里每一行在说什么一条典型的慢查询记录长这样# Time: 2025-01-15T10:23:41.123456Z # UserHost: biz_user[biz_user] [10.0.3.18] Id: 88211 # Query_time: 8.541232 Lock_time: 0.001322 Rows_sent: 10 Rows_examined: 5407821 SET timestamp1736922221; SELECT id, order_no, amount FROM orders WHERE user_phone13800138000 ORDER BY created_at DESC LIMIT 10;关键信息全在Query_time这一行查询执行耗时8.5秒Lock_time表示锁等待时间Rows_examined表示扫描了540万行但Rows_sent只返回了10行。扫描行数和返回行数差距巨大基本可以断定没走索引或索引失效了。后面的SET timestamp1736922221是MySQL恢复这个查询在实际执行时的时间上下文用来配合binlog做时间对齐的排障时不用管它。4.3 用好自带工具和第三方神器MySQL自带的mysqldumpslow用来汇总慢查询日志特别方便它能把上千条相似的慢SQL聚合成几类输出执行次数、平均耗时、最大耗时# 按平均查询时间排序取前10名 mysqldumpslow -s at -t 10 /var/lib/mysql/slow.log参数说明-s指定排序方式at表示按平均查询时间排序c按计数排序t按总耗时排序-t取前N条。它还会自动把数字和字符串参数抽象成N和S所以WHERE user_phone13800138000和WHERE user_phone13900139000会被归并成一条这设计很实用。如果数据量更大、需要更精细的分析推荐用Percona Toolkit里的pt-query-digest。它能把慢查询日志按指纹分组输出每个查询的响应时间占比、统计直方图还能直接结合EXPLAIN结果给出优化建议。这是目前分析慢查询最专业的命令行工具没有之一。pt-query-digest /var/lib/mysql/slow.log如果你用Percona的MySQL发行版安装pt工具非常简单用官方MySQL也可以直接下载Percona Toolkit的rpm或deb包它不依赖具体MySQL发行版对官方版同样适用。4.4 一个真实的慢查询定位过程有次我接手一个电商后台运营反映商品列表页一到晚上8点就卡。我先看慢查询日志发现有大量记录都指向同一条SQL——查订单表orders时用了status字段做过滤然后按create_time排序。我执行了EXPLAIN发现typeALL走的是全表扫描因为status列的唯一性太低优化器算了一下代价觉得直接扫全表比走索引再回表更快。最终方案是新建联合索引(status, create_time)。这条SQL的执行时间从8秒降到了40毫秒。整个排查过程看日志、跑EXPLAIN、加索引、复测加起来不到半小时。没有慢查询日志我连往哪个方向查都不知道。5. binlog查查看数据恢复和主从同步都靠它5.1 三种记录格式的差异binlog是MySQL最特殊的一类日志它不像错误日志和慢查询日志那样直接用文本编辑器看而是以二进制格式存储必须借助工具解析。同时它又极其重要主从复制、时间点恢复、误删数据找回全依赖它。它有三种记录格式理解它们的区别能帮你少踩不少坑STATEMENT格式记录原始SQL语句。优点是日志体积小缺点是某些函数比如NOW()、UUID()在主库和从库执行时结果可能不一致导致主从数据不一致。ROW格式记录每一行数据的实际变更情况比如把某行从旧值改成新值。优点是复制最安全缺点是一条UPDATE更新一万行日志里就有一万行变更记录日志文件膨胀很快。MySQL 8.0默认使用ROW格式。MIXED格式MySQL自己判断碰到不安全函数自动切换成ROW格式其余用STATEMENT格式。兼顾体积和安全性但实际维护起来理解成本略高。查看当前binlog格式很简单SHOW VARIABLES LIKE binlog_format;5.2 用mysqlbinlog解析并查看明文内容查看binlog最核心的工具就是mysqlbinlog。比如要看/var/lib/mysql/目录下的binlog.000023mysqlbinlog --base64-outputDECODE-ROWS -v /var/lib/mysql/binlog.000023解释一下两个关键参数--base64-outputDECODE-ROWS把ROW格式的二进制内容解码成可读的伪SQL。-v显示注释掉的每行数据的前置信息和变更明细。加两个-v即-vv能看到具体列的变更内容。如果日志文件本身按天轮转而你只关心某个时间段可以按时间范围过滤mysqlbinlog --start-datetime2025-01-15 09:00:00 --stop-datetime2025-01-15 10:00:00 /var/lib/mysql/binlog.000023也可以指定位置偏移mysqlbinlog --start-position12345 --stop-position22345 /var/lib/mysql/binlog.0000235.3 实战误删数据后的恢复思路假设某天凌晨你在测试环境误执行了一条DELETE FROM orders WHERE create_time 2024-01-01并且没有开启事务隔离级别的保护数据commit后回不去了。恢复的第一步是确认binlog打开且当前时间点之后没有大量写操作覆盖。然后# 查看binlog文件列表 SHOW BINARY LOGS; # 把指定binlog导出为SQL文本先拿到可读内容确认删除语句的位置 mysqlbinlog --base64-outputDECODE-ROWS -vv /var/lib/mysql/binlog.000078 /tmp/binlog.sql # 找到那条DELETE语句的事件位置用--stop-position定位到它之前 mysqlbinlog --start-datetime2025-01-14 23:59:00 --stop-datetime2025-01-15 00:01:00 /var/lib/mysql/binlog.000078 /tmp/recover_before_delete.sql # 将这段binlog重新执行到数据库相当于回放了删除之前的所有变更 mysql -uroot -p /tmp/recover_before_delete.sql这个还原过程只说思路实际落地还要结合备份策略。真正生产环境更推荐“全量备份binlog增量回放”的组合先把最近一次全量备份导入再回放备份时间点到出事时间点之间的binlog。这套思路是MySQL一切误删恢复、闪回方案的地基理解了它你才能用好市面上那些binlog闪回工具。5.4 binlog轮转和过期清理binlog文件会持续增长不及时处理会吃满磁盘。查看当前所有binlog及大小SHOW BINARY LOGS;设置自动过期时间SET GLOBAL binlog_expire_logs_seconds 604800;这里特别注意MySQL 8.0里expire_logs_days已经废弃改用binlog_expire_logs_seconds单位是秒604800就是7天。同时我还建议你保留至少两天的binlog用来做误删恢复再配合定时全量备份形成完整的可恢复链条。清理时也别手动删文件应该用SQL或PURGE BINARY LOGS TO binlog.000101这样的命令直接删物理文件会和MySQL的元数据不一致导致复制中断。6. 一次完整排障链路复盘从报错到定位的4个关键步骤这里我完整复盘一次线上故障看日志的排查链路是怎么一步步收敛的。场景是早上10点某应用的数据库连接池频繁报Too many connections用户登录超时。第1步看错误日志确认是不是数据库本身的问题。tail -200 /var/log/mysql/error.log关键输出[ERROR] [MY-000143] [Server] Too many connections [ERROR] [MY-000144] [Server] The number of connections exceeds the maximum limit这基本确认数据库进程还活着但连接数被打满了。错误日志还经常出现Cant create thread to handle new connection这种线程资源耗尽提示含义类似。第2步用SQL动态查看当前实时状态。SHOW STATUS LIKE Threads_connected; SHOW VARIABLES LIKE max_connections; SHOW PROCESSLIST;SHOW PROCESSLIST可以直接看到每个连接的来源IP、执行状态、当前SQL。实际中我遇到过某一条连接用State显示Waiting for table metadata lock这说明有一个长事务或者慢查询把表的元数据锁给占了后到的查询全部排队。第3步打开慢查询日志定位是哪种SQL在拖后腿。因为在故障期间新连接的慢查询日志可能还没刷新出来我先看全局配置确认慢查询日志是开的然后直接翻文件里故障点名前后10分钟的记录sed -n /2025-06-11 10:00:/,/2025-06-11 10:15:/p /var/log/mysql/slow.log很快发现某条统计SQL扫描了上千万行数据执行时间20秒而且它每10秒被调用一次多个进程并发执行直接把连接池撑爆了。第4步EXPLAIN验证并修复。EXPLAIN SELECT ... FROM statistics WHERE create_time NOW() - INTERVAL 1 DAY;查出key: NULL没走索引。原因是该表数据量增长后日期字段索引选择性不够优化器改选了全表扫描。最终加了联合索引连接数恢复错误日志里Too many connections也不再出现。这是我的排查顺序习惯先错误日志再看实时状态再慢查询最后EXPLAIN。顺序不能反如果一上来就翻慢查询很可能你盯着一条慢SQL分析半天最后发现根本原因是连接数被打满了方向就偏了。7. 日志管理的坑与建议轮转、清理、安全一个都别省7.1 为什么你的磁盘总是莫名其妙就满了日志文件最大的特点就是“无限增长”。错误日志还好一般量不大但慢查询日志开久了、通用查询日志误开了、binlog过期时间设得长磁盘迟早被吃满。磁盘满在MySQL里是个很吓人的故障写入失败、事务无法提交、Slave同步中断严重的还会触发数据库只读保护。所以日志的轮转和清理必须写入运维规范不能靠“想起来就删”。7.2 用logrotate管理日志轮转Linux系统自带logrotate是管理MySQL日志的标配。比如在/etc/logrotate.d/mysql里配置/var/log/mysql/*.log { daily rotate 14 compress delaycompress missingok notifempty create 0640 mysql mysql postrotate mysqladmin flush-logs -uroot -p 2 /dev/null || kill -USR1 $(cat /var/run/mysqld/mysqld.pid) endscript }这段配置含义是每天轮转一次保留14天历史压缩旧文件。postrotate里的mysqladmin flush-logs非常关键如果不主动通知MySQL刷新日志句柄MySQL还会继续往旧文件里写轮转等于白做。慢查询日志和通用日志用flush-logs没问题但binlog并不随着flush-logs直接切割它是按max_binlog_size和事务边界切割的。别指望logrotate帮你切binlogbinlog的过期靠的是binlog_expire_logs_seconds。7.3 日志安全别让数据结构泄露到不该看的人手里日志包含敏感数据尤其是binlog在ROW格式下会把完整行数据记录进去慢查询日志则是整条SQL都能看到。如果日志被拷贝到研发手里、传到第三方分析平台等于把客户手机号、身份证号这类数据直接暴露了。我给三点建议一是生产环境的通用查询日志默认保持关闭非必要不开二是慢查询日志和binlog的访问权限收紧到dba和运维组文件权限建议640三是如果平台有脱敏分析需求先用工具把日志中的敏感列去掉再分发。别觉得这是小题大做我见过不止一个团队因为日志管理不当被安全部门通报。7.4 最后分享一个小习惯我个人的习惯是给每台MySQL服务器的日志目录单独划分一个逻辑卷比如挂载到/data/mysql-logs容量至少预留50GB以上。这样即使某个日志异常膨胀也只是占满日志盘不会拖垮数据盘和系统盘。这个思路成本很低却能在关键时刻把故障隔离在很小的范围内。日志排障是个熟能生巧的活儿平时多翻翻、多看看正常情况下的日志长什么样等真正出事的时候你扫一眼就能发现哪里不对劲。
返回列表