MySQL与MongoDB日志体系实战：慢查询排查与故障恢复

运维数据库这些年，我有个很深的体会：MySQL和MongoDB放在一起讲日志，不是因为他们像，恰恰是因为他们太不一样了。很多团队两个库都在用，白天业务跑着没事，一到高峰期告警就炸锅，大家下意识去翻日志，结果MySQL的error log里干干净净，MongoDB的mongod.log倒是刷了一屏Slow query。方向没找对，排查自然绕远路。这篇文章不打算罗列官方文档，而是按我实际排查问题的顺序，把两类数据库的日志体系拆开讲清楚：每一类日志到底记录了什么、什么时候该看它、怎么从日志里一步步定位问题，以及最容易踩的几个坑。无论你是在做后端开发，还是专职DBA，只要手上有MySQL和MongoDB，这套思路都可以直接拿去用。

1. MySQL的日志入口：错误日志与慢查询日志怎么配合排查

1.1 错误日志：不是所有问题都会出现在这里

MySQL的error log是最容易被忽略的日志，因为大多数时候它确实没什么可看的。但它又是排查启动失败、权限拒绝、复制中断这类问题的第一现场。默认情况下，错误日志写在数据目录下，文件名一般是主机名.err，生产上我建议显式配置到独立路径：

[mysqld] log_error = /var/log/mysql/mysql-error.log log_error_verbosity = 3

log_error_verbosity在MySQL 5.7之后可以控制详细程度，3表示记录最多信息，相当于把Debug信息也写进去。日常运行时设成2就够了，否则日志量会有点冗余。需要注意的是，错误日志只记录MySQL认为的“异常”，像连接数被打满、慢SQL堆积这类问题，往往不会出现在这里——它们更像是一种“症状”，而不是“病因”。如果你发现error log一片安静，业务却在超时，别急着怀疑日志没开，往慢查询和连接状态方向查。

我遇到过最典型的例子：某订单查询服务在晚高峰突然大量超时，应用日志里全是连接获取失败，MySQL的错误日志只有一个“Aborted connection”的提示，真凶根本不在这里。后来看了SHOW PROCESSLIST，才发现几十条会话全部卡在“Sending data”状态，罪魁祸首是一条没走索引的统计SQL。所以我的习惯是：错误日志负责确定“有没有宕机、有没有复制断了、有没有权限问题”，至于性能类问题，得交给慢查询日志。

1.2 慢查询日志：定位慢SQL的关键路径

慢查询日志是MySQL排查性能问题最核心的工具，它记录的是实际执行时间超过阈值的SQL。配置如下：

[mysqld] slow_query_log = 1 slow_query_log_file = /var/log/mysql/mysql-slow.log long_query_time = 1 log_queries_not_using_indexes = 0

long_query_time是阈值，单位是秒。默认值是10秒，但对绝大多数业务来说这个阈值太宽松了，等日志真正记录到一条SQL时，问题早就影响用户了。我一般建议核心业务先设成1秒，如果日志量太大再逐步往上调；MySQL 5.7.8以后还支持微秒级别，比如0.05，适合压测环境观察。至于log_queries_not_using_indexes，我通常设为0，因为它会把所有没走索引的查询都记下来，哪怕查询本身只要几毫秒，日志量会非常吓人。

拿到慢日志之后，第一步是先按执行次数、总耗时排序，而不是盯着单条最大耗时看。工具上可以用自带的mysqldumpslow，也可以上Percona Toolkit的pt-query-digest。我的习惯是先看Top 10，再看是否有同一类型的SQL反复出现，比如都带了某个user_id条件但没命中索引，这种往往说明索引设计有缺口，而不是单纯一条SQL写得烂。

1.3 一个完整的慢SQL定位实录

说个具体的。某天同事反馈后台报表导出越来越慢，半小时都导不完。我查了慢查询日志，发现一条SQL频繁出现：

SELECT * FROM t_order WHERE user_id = 100234 AND status = 1 ORDER BY create_time DESC LIMIT 20;

慢日志里显示Query_time从2秒到35秒不等，Rows_examined稳定在480万。然后我用EXPLAIN看了一眼执行计划，type是ALL，也就是全表扫描，possible_keys是空的，说明连可选索引都没有。问题很清晰：这张表已经有400多万行，还在按user_id单点查询，但没有对应索引。

修复方式就是在(user_id, status, create_time)上建联合索引：

ALTER TABLE t_order ADD INDEX idx_user_status_time(user_id, status, create_time);

索引建完，这条SQL的执行时间直接掉到十几毫秒。这里有一个容易被忽略的细节：慢日志里除了Query_time，还要关注Rows_examined和Rows_sent的比例。如果Rows_examined很大但Rows_sent很小，说明MySQL扫描了大量数据只返回了少量结果，这种SQL即使执行时间没有超标，索引设计也是不合格的。养成习惯，不要只看一个指标。

2. binlog别只当复制工具：它是误操作后的后悔药

2.1 binlog有哪几种格式，怎么选

MySQL的binlog（二进制日志）很多人只把它当主从复制用，其实它还有一层更重要的作用：按时间点恢复数据。理解binlog，必须先搞清楚它的三种格式：

我个人的建议是：不用纠结，直接用ROW。因为从MySQL 5.7开始，ROW已经是默认推荐格式，而且它最大的优势是误操作恢复时可以精确看到每一行被改成了什么值。代价无非是binlog文件体积变大，但对磁盘来说，这点开销换来的数据安全性完全值得。

实际配置里还有两个关键参数值得盯：一个是sync_binlog，它控制binlog多久刷一次盘。sync_binlog=1表示每次事务提交都刷盘，安全性最高，但磁盘压力大；很多高并发场景会退而求其次，设成0或N。另一个是binlog_row_image，可以设为FULL、MINIMAL或NOBLOB，如果业务场景不太需要全字段恢复，MINIMAL能显著减少日志量。

2.2 binlog恢复误删数据的完整过程

有一类故障是每个DBA都不想遇到但迟早要遇到的：误DELETE或误UPDATE。某次一个定时任务写错了条件，把某张用户优惠券表里一大半数据给清了。幸好binlog是ROW格式，恢复思路分四步走：

1. 先找到误操作对应的binlog文件和position。用mysqlbinlog把日志解出来：

mysqlbinlog --base64-output=decode-rows -vv /var/lib/mysql/binlog.000012

在输出里搜DELETE FROM某个表名，找到误操作语句前后的位置标记。

2. 确认误操作时间点，或者更精确的start-position和stop-position。我的建议是能用position就用position，时间过滤容易受到时区干扰，踩过坑的人都懂。

3. 把误操作之前的binlog重放到一个临时库，先确认数据完整：

mysqlbinlog --start-position=100 --stop-position=2500 binlog.000012 | mysql -h127.0.0.1 -uroot -p temp_restore

4. 确认无误后，再把这部分binlog重放到线上库，或者直接导出需要恢复的行，生成INSERT语句回补。

整个过程里最怕的不是操作复杂，而是binlog被定期清掉了。所以binlog的保留策略我一定会配合全备周期来定，至少保证两个全备之间的binlog是完整的，否则出事之后连后悔药都没有。

2.3 binlog的日常运维参数

binlog的日常运维其实不复杂，但几个参数必须心里有数：

这里要注意版本差异：MySQL 8.4已经把expire_logs_days标记为废弃，改用binlog_expire_logs_seconds。不管用哪个，核心思路都一样——binlog保留时长必须大于全备间隔，否则“全备+增量恢复”这条链路就是断裂的。

3. MongoDB的日志体系：系统日志、profiler与oplog各管什么

3.1 mongod.log：怎么看懂那些结构化消息

MongoDB的系统日志和MySQL有个很大的区别：它的日志天然是JSON格式，字段非常结构化。配置文件里推荐这样开启：

systemLog: destination: file path: /var/log/mongodb/mongod.log logAppend: true verbosity: 0

logAppend必须设为true，否则重启后老日志会被覆盖。verbosity默认是0，也就是标准级别，只有关键操作和信息会记录；想调高可以到5，但生产环境不建议随便改，日志量会指数级增长。

mongod.log里最常见的几类信息包括：连接建立和断开、复制成员的同步进度、慢查询、以及各种存储引擎警告。看的时候不要从头到尾翻，而是先按关键字过滤，比如“Slow query”“connection accepted”“replica set”。

之前排查过一次MongoDB连接数告警，就是在mongod.log里看到了大量“connection refused because too many open connections”的记录，配合netstat、系统文件句柄数一起看，最终确认是ulimit设置和连接池配置不匹配。这类问题在MySQL上会有类似表现，但MongoDB的日志会直接告诉你当前连接数、等待队列长度，排查起来更直观。

3.2 profiler与system.profile：慢查询的完整画像

MongoDB里也有慢查询机制，但它的设计比MySQL更“立体”。默认情况下，超过100ms的查询会被记录到system.profile集合，不过这个集合是capped collection，默认只有1MB，容量很小，线上最好明确设置profiling级别和建议的慢查询阈值：

// 0关闭，1记录慢查询，2记录所有操作 db.setProfilingLevel(1, { slowms: 200 }) // 查看当前状态 db.getProfilingStatus()

MongoDB慢查询日志的价值在于：它记录的内容不止是耗时，还有planSummary、docsExamined、keysExamined、numYield等字段。拿一条典型的慢查询日志来看：

{ "msg": "Slow query", "attr": { "type": "command", "ns": "shop.warehouse", "command": { "find": "warehouse", "filter": { "sku_id": 123456 } }, "planSummary": "COLLSCAN", "docsExamined": 8200000, "keysExamined": 0, "executionTimeMillis": 8500 } }

看到planSummary是COLLSCAN、docsExamined是820万、keysExamined是0，基本可以断定这条查询在扫全表，和MySQL里explain看到type=ALL是完全一个意思。再配合执行计划确认：

db.warehouse.find({ sku_id: 123456 }).explain("executionStats")

如果stage后面还是COLLSCAN，修复方式就是建索引：

db.warehouse.createIndex({ sku_id: 1, region: 1 })

建完之后再explain，stage会变成IXSCAN加FETCH，执行时间能从秒级降到毫秒级。这套流程和MySQL慢查询排查高度相似，懂一个基本就能触类旁通。

3.3 oplog和journal：复制与恢复的底层机制

MongoDB还有两个容易被误解的日志概念：oplog和journal。oplog（Operations Log）是复制集的核心，它记录所有写操作，从节点通过拉取oplog来同步数据。它存储在local库的oplog.rs集合里，是一个定长的capped collection。我建议每季度都检查一次oplog的时间窗口是否足够覆盖主节点长时间不可用或网络中断的场景。

db.getReplicationInfo()

这条命令会输出oplog的时间范围、日志大小、以及预计可覆盖的时长。如果oplog窗口只有两三个小时，而你的网络抖动可能持续半天，那窗口期太短，从节点可能追不上主节点，最终只能重新做全量同步。这个比“日志太大”问题严重得多。

journal则是存储引擎层的预写日志，负责崩溃恢复。WiredTiger的journal在默认配置下，commitIntervalMs通常设为100ms左右，也就是说如果机器突然断电，未提交到journal的数据最多可能丢失最近100ms内的写入。如果你的业务对数据持久性要求极高，写入时应该使用writeConcern: { j: true }，强制要求journal确认，代价是每次写入多等一次刷盘。拿它来对应MySQL，journal有点像InnoDB的redo log，而oplog更像binlog加上复制订阅机制的结合体。

4. MySQL与MongoDB日志机制对照：三层结构、刷盘策略与慢查询判定

4.1 为什么MySQL的日志分层这么多

很多从MongoDB切到MySQL的同学会觉得莫名其妙：MySQL怎么那么多log？error log、slow log、binlog、redo log、undo log，到底哪个管哪个？其实这是由它的架构决定的。

MySQL分server层和存储引擎层：binlog是server层产生的逻辑日志，redo log和undo log是InnoDB存储引擎层的物理日志。redo log负责崩溃恢复时把没来得及落盘的数据重新应用，undo log负责事务回滚和MVCC。更关键的是，binlog和redo log之间通过两阶段提交来保证一致性——如果写完redo log还没写binlog就崩溃了，恢复时会按规则把事务丢弃；反过来binlog写了而redo log没提交，则会补完这个事务。

MongoDB的WiredTiger存储引擎也有checkpoint、journal和oplog，但整体结构比MySQL简单不少。journal保证崩溃恢复，checkpoint定期将数据刷到磁盘，oplog供复制使用。它没有像MySQL那样的server层逻辑日志和存储引擎物理日志的复杂协作关系，所以排障时需要看的文件类别天然更少。

4.2 慢查询判定：MySQL看时间，MongoDB看更多维度

这是两个数据库日志设计上差异很大的一点。MySQL的慢查询日志主要就是根据执行时间是否超过long_query_time来筛的，虽然日志里也会记录Rows_examined和Rows_sent，但筛选逻辑本身只认时间。这也意味着：一条扫描了500万行但恰好没超过阈值的SQL，可能不会被记录，直到数据量大到让它的执行时间也超了，你才发现隐藏的问题。

MongoDB的profiler除了按slowms筛时间，还会把计划摘要、扫描文档数等字段写进日志。所以即使某条查询没超过阈值，只要你在system.profile里翻，也能看到它的执行计划和扫描量，这对提前发现潜在问题很有帮助。我个人的习惯是，线上MongoDB把slowms设到200ms，同时每隔一段时间抽查docsExamined明显大于返回行数的查询，主动优化，而不是等问题先爆炸。

4.3 刷盘策略和持久性对照

持久性方面，两边都有可调参数，但逻辑不同。MySQL里影响崩溃数据丢失的有两个关键参数：innodb_flush_log_at_trx_commit控制redo log刷盘策略，值设0可能丢1秒内数据，设1最安全；sync_binlog控制binlog刷盘，同样有安全性和性能的取舍。MongoDB这边主要看journal的commitIntervalMs，以及写入时是否带j:true的writeConcern。

这张表总结下来，你可以把两个库的日志角色大致对应，但排障思路不能完全套用。MySQL的问题常常要多个日志交叉比对才能定位，MongoDB则更依赖单一日志里的结构字段做判断。

5. 两个实战复盘：都说“查日志”，到底怎么查

5.1 MySQL案例：Too many connections背后的慢SQL堆积

某天晚上告警群突然刷屏，某支付对账接口大量超时。登录MySQL之后，先是错误日志里看到了熟悉的提示：

ERROR 1040: Too many connections

这个是“果”，不是“因”。连接数被打满往往是因为某些连接长时间不释放，占住了连接池。看进程列表：

SHOW PROCESSLIST;

结果发现几十个连接长时间处于“Sending data”状态，Time在几十秒到上百秒不等。再去看慢查询日志，有一类SQL的Query_time从几秒到几十秒，模式和1.3节里那条报表SQL几乎一样——同一个代码分支里扫了一张大表。解决路径也很清晰：先挑出执行时间最长的几个连接，记录SQL和来源IP后kill掉，让连接池喘口气；随后根据慢日志里的SQL指纹，给对应的查询条件加联合索引。索引生效后再观察慢日志，同类SQL基本消失。整个过程的关键在于：错误日志给结论，慢日志给证据，processlist给现场，三者缺一不可。

5.2 MongoDB案例：COLLSCAN刷屏，一条范围查询带崩整体

另一个项目里，某库存查询接口在某次发版后响应时间从50ms直接涨到8秒，用户端反馈明显。我先用mongosh查看当前正在执行的慢操作：

db.currentOp({ "secs_running": { $gt: 1 } })

输出里能看到大量查询都在同一个集合上做COLLSCAN。再开profiling，并把mongod.log里的Slow query抓出来看，planSummary清一色是COLLSCAN，docsExamined都是百万级别。出错原因很快锁定：开发在代码里用了一个未加索引的字段做范围过滤，而该集合在测试环境只有几十万行，慢查询现象不明显，一上生产就暴露了。修复方式就是补索引，同时把profiling级别维持住，观察一段时间确认慢查询消失。这个案例提醒我，新接口上线前最好先在生产预发环境开一周的profiler，把耗时异常的查询在新代码灰度期间就揪出来。

5.3 排查中最容易被忽略的坑：时间不同步

很多人在日志排障时绕了半天，最后发现根子出在时间上。常见的情况是：应用服务器用的是CST（东八区），数据库服务器utc时间忘了改，或者某个实例的NTP同步失效，导致慢日志里记录的执行时间和应用日志里的时间戳对不上。

排查多系统问题时，我第一件事就是把所有时间基准对齐。MySQL里可以用：

SELECT NOW();

MongoDB里可以用：

new Date()

两边对完，再确认操作系统时间和NTP状态。如果对不上，先修时间，否则后面所有的日志比对都是白费力气。注意：MySQL的long_query_time记录的只是执行耗时，是相对值，本身不受时区影响；但你用binlog做数据恢复、或者用时间戳去过滤binlog日志时，时区问题会直接导致取错范围，这个坑我亲眼见过不止一次。

5.4 日志轮转：不改配置，磁盘迟早被写满

日志不轮转，是运维事故里非常低级但高频的一种。MySQL和MongoDB的轮转机制不太一样，处理不好会出现“日志文件被rename之后还在写旧文件”的情况。

比较稳妥的做法是用系统logrotate统一管理，再配合数据库自身的信号。MySQL一般可以在logrotate配置里加postrotate，执行mysqladmin flush-logs，让MySQL重新打开新的日志文件。MongoDB则更简单，可以直接在mongo shell里执行：

db.adminCommand({ logRotate: 1 })

或者给mongod进程发SIGUSR1信号：

kill -USR1 <mongod_pid>

这里有个细节：不要只是简单delete掉MongoDB的日志文件。因为mongod进程还持有旧文件的文件描述符，你把文件删了，进程还在往那个已删除的inode里写数据，磁盘空间根本不会释放。正确做法永远是先触发logRotate，再清理旧文件。MySQL的slow log同理，不flush-logs只做文件mv，一样会造成空间黑洞。

6. 日志落盘之外的事：轮转、保留周期与容量规划

6.1 日志保留周期怎么定

日志留多久，是个需要平衡的问题。留太短，出了问题没得查；留太长，磁盘撑不住，查起来也慢。我的实践是分三类考虑：

• 错误日志、慢查询日志：至少保留7~14天，滚动压缩存储；如果公司有合规日志平台，再把原始日志同步上去归档。
• binlog：保留时长必须大于全备周期，并且至少覆盖一次全量备份加增量恢复的业务验证时间。比如每天凌晨全备，binlog最少留48小时，我通常留7天。
• MongoDB oplog：它的容量限制和保留时长是线性关系，依据业务写入量监控oplog窗口。窗口小于6小时就该调大oplogSizeMB了。

保留周期还要和日志分析任务绑定：每周跑一次pt-query-digest，把慢日志的Top SQL汇总出来分发给相关开发；每月再对MongoDB的system.profile做一次抽样分析。这样日志不止用于事后复盘，也能提前看到性能劣化趋势。

6.2 用日志做容量规划，而不是只用它做故障复盘

很多人把日志工具定位成“出事了才翻”，其实日志最值钱的用法是提前预测。MySQL binlog每天增长多少，直接反映了业务写入量的变化；慢日志里Rows_examined总量如果以每周10%的速度增长，说明数据量增长和索引设计已经到了一个临界点，该考虑归档冷数据或者重新设计分表了。

MongoDB也是一样。oplog窗口缩水通常意味着写入量变大或从节点延迟增加；mongod.log里周期性出现的lock busy提示，则说明写入并发可能正在逼近存储引擎的上限。换句话说，日志是数据库健康状况的长期记录仪，养成周期性看日志指标的习惯，很多故障都可以提前几个小时甚至几天发现，比临时救火省心太多。

日志这件事，看起来是最基础的运维工作，但真正遇到故障时，手边有没有完整、干净、可回溯的日志，决定了你是花半小时定位问题，还是花一晚上“猜”问题。我自己经历过几次深夜救火之后，现在的习惯很简单：每个数据库实例都统一日志目录、统一轮转策略、每周固定看一次日志指标趋势。这套“笨办法”可能听起来不炫，但它确实让线上事故从“开盲盒”变成了“查记录”。

最后再分享一个小技巧：日志字段或格式的调整，尽量在测试环境先跑一段时间再上生产。比如MongoDB调高verbosity、MySQL开log_queries_not_using_indexes，都会明显增加日志量，如果直接在核心库上开，经常是问题没查出来，先把自己磁盘打满了。稳妥一点，永远没有坏处。