MySQL日志系统执行详情一路查清你的SQL到底怎么跑的“MySQL日志系统执行详情”这个题目说白了就是解决一个问题一条SQL在MySQL里为什么快、为什么慢、到底怎么执行的你从哪儿能看到过程。干了这些年我排查线上数据库问题的突破口几乎都落在日志和执行计划上。错误日志告诉你数据库经历了什么启动失败和崩溃慢查询日志告诉你哪些SQL在拖后腿general log能记录每一条到达MySQL的原始语句binlog则留下了所有写操作的历史轨迹。而EXPLAIN和performance_schema又能把单条SQL的执行路径、真实耗时、等待事件拆得明明白白。这篇就把这套东西串起来从日志开关、参数配置到具体怎么分析执行详情再到我实际踩过的坑一整套梳理给你。适合刚告别增删改查、开始接触排查优化的开发也适合想建立完整排查思路的DBA入门。很多朋友一上来就背优化口诀什么“索引三原则”“避免SELECT *”其实不如先学会自己看执行详情。日志系统就是数据库的黑匣子执行详情就是黑匣子里记录的关键帧。这篇文章我会用一条排查流程串起全部内容先讲日志体系里每个成员的作用和打开方式再讲怎么通过慢查询日志圈出可疑SQL然后用EXPLAIN把执行计划逐字段拆开接着用profiling和performance_schema看到真实耗时分布最后说一下binlog在查看执行历史和数据恢复里的用法。所有命令我都在MySQL 5.7和8.0上实际跑过版本不同个别参数名有差异但思路是通的。1. 先认识MySQL日志系统每个日志都有自己的活儿1.1 日志家族全景与核心职责MySQL里的日志主要分几类错误日志error log、通用查询日志general log、慢查询日志slow query log、二进制日志binlog、中继日志relay log、重做日志redo log和回滚日志undo log。其中redo log和undo log属于InnoDB存储引擎内部实现虽然名字带日志但日常排查SQL性能时不会直接碰它们它们负责崩溃恢复和事务隔离。对“执行详情”有直接价值的是前四个错误日志记录服务异常通用查询日志记录全部到达MySQL的语句慢查询日志记录超过阈值的SQLbinlog记录所有导致数据变更的写操作。中继日志只在主从复制场景里出现本质是备库从主库拉取binlog后在本地生成的副本。我用一张表把核心信息整理清楚日志名称记录内容默认状态常见位置核心用途错误日志 error log启动、关闭、运行中错误开启/var/log/mysql/error.log看崩溃原因、启动失败通用查询日志 general log所有客户端连接与SQL关闭文件或mysql.general_log表审计、追踪执行详情慢查询日志 slow query log超过long_query_time的SQL关闭/var/lib/mysql/hostname-slow.log性能优化第一入口二进制日志 binlog所有写操作逻辑日志8.0默认开启/var/lib/mysql/bin.000001复制、恢复、审计有一个非常重要的认知通用查询日志和binlog都会持续写盘对性能有明显影响尤其是general log生产环境不建议长期开着需要排查时开一会儿完了马上关。binlog属于生产必开因为它承担主从复制和备份恢复的功能这个不能省。1.2 各日志的查看入口与动态开关错误日志最常用的查看方式是在MySQL命令行里执行SHOW VARIABLES LIKE log_error;拿到路径然后tail -f跟文件。很多启动失败比如端口被占用、数据目录权限不对、innodb损坏恢复都会在这个文件里留下明确线索。不看错误日志就重启数据库是新手最容易犯的错。通用查询日志可以用SET GLOBAL general_log ON;动态打开也可以把log_output设成TABLE日志就会写到mysql.general_log表里用SQL查询比翻文件方便得多适合短时间跟踪。但要注意即使是TABLE模式写入量大的时候也会对性能造成压力排查完记得SET GLOBAL general_log OFF;。慢查询日志动态配置同样简单SET GLOBAL slow_query_log ON; SET GLOBAL long_query_time 2; SET GLOBAL slow_query_log_file /var/log/mysql/slow.log;long_query_time的单位是秒支持小数0.5就是500毫秒。这里有个非常经典的坑long_query_time同时存在会话级和全局级变量已经建立的连接还沿用旧值你改了全局变量之后新开的连接才生效。很多人配置了半天当前连接测试还是不记录就是因为这个。解决方法是重开一个连接或者在当前会话里手动SET SESSION long_query_time 2;。再补充一个排查技巧SHOW VARIABLES返回的是当前会话变量SHOW GLOBAL VARIABLES返回的是全局变量两个经常不一致。排查“配置没生效”问题时两个都要看。2. 慢查询日志定位可疑SQL的第一入口2.1 生产环境推荐的慢日志配置慢查询日志是性能排查的第一站。生产环境我常用的配置写在my.cnf的[mysqld]段slow_query_log 1 slow_query_log_file /data/mysql/slow.log long_query_time 1 log_queries_not_using_indexes 1 min_examined_row_limit 100几个参数说明一下long_query_time 1超过1秒就记录这是比较通用的阈值业务性能好的数据库可以调到0.5甚至0.1。log_queries_not_using_indexes 1记录所有没走索引的查询。这个开关很有用但也很吵因为有些小表全表扫描其实很快不需要记录。min_examined_row_limit 100扫描行数低于100的不记录用来过滤掉那些“虽然没走索引但执行很快”的查询。我加这个参数就是受不了日志里全是小表全表扫描的噪音。2.2 慢日志每一行都代表什么真实的一条慢日志记录8.0格式长这样# Time: 2025-01-15T10:24:33.123456Z # UserHost: app_user[app_user] [192.168.10.101] Id: 12345 # Query_time: 2.345678 Lock_time: 0.000123 Rows_sent: 10 Rows_examined: 200003 SET timestamp1736915073; SELECT * FROM orders WHERE customer_id 10086 AND status 1 ORDER BY create_time DESC LIMIT 10;这几个字段是判断问题的核心Query_time整个语句执行总耗时从服务器收到语句到出结果的时间。Lock_time锁等待时间如果这里数值很大问题可能出在并发锁。Rows_sent返回给客户端的行数。Rows_examined实际扫描了多少行。Rows_examined和Rows_sent的差距越大说明扫描了大量行又扔掉基本可以确定索引设计有问题或者统计信息失真。比如上面的日志Rows_examined是20万只返回10行明显是全表扫描后过滤的结果。2.3 快速分析慢日志的两个工具手工看慢日志效率太低可以用MySQL自带的mysqldumpslow聚合mysqldumpslow -s t -t 10 /data/mysql/slow.log-s t表示按耗时排序-t 10取Top10。输出里数字参数会被抽象成N把一模一样的SQL归并统计适合快速看大头。更专业的是Percona Toolkit里的pt-query-digestpt-query-digest /data/mysql/slow.log它会输出按Query_time排名次的SQL Profile包含每条SQL的执行次数、平均耗时、最大耗时、总耗时占比。我实测下来线上几百MB的慢日志跑一遍几分钟就能拿到完整报告非常直观。安装方式一般是yum install percona-toolkit或者apt install percona-toolkit。工具只是辅助真正要落地的是读懂慢日志本身。我习惯先看Top5再针对每个问题SQL做EXPLAIN看执行计划到底是哪一步出了问题。3. EXPLAIN把一条SQL的执行计划拆开看3.1 慢日志定位了SQL然后呢慢日志只告诉你“这条SQL慢”但没告诉你为什么慢。同样一条SQL跑了3秒可能是因为没走索引也可能走了索引但额外做了文件排序还可能卡在锁等待上。这些信息慢日志里看不出来得上EXPLAINEXPLAIN SELECT * FROM orders WHERE customer_id 10086 AND status 1 ORDER BY create_time DESC LIMIT 10;MySQL 8.0.18之后还可以用EXPLAIN ANALYZE它会真正执行这条语句给出实际耗时和执行过程比EXPLAIN的预估信息更真实后面单独讲。3.2 核心字段逐个说清楚EXPLAIN输出里最重要的几个字段idSELECT标识符多表查询时执行顺序的参考。 select_typeSIMPLE普通查询PRIMARY最外层SUBQUERY子查询等。 table访问的表。 type访问类型这是优先级最高的判断依据。从好到差依次是system const eq_ref ref range index ALL出现ALL就是全表扫描性能问题的头号嫌疑index代表扫描了整棵索引树有时候也够呛range是范围扫描还能接受ref是普通非唯一索引等值匹配eq_ref是唯一索引等值匹配join里被驱动表能走到这个就比较理想const是主键或唯一索引等值匹配理论最快。possible_keys可能用到的索引。 key实际用到的索引。 key_len实际使用的索引长度字节可以用来判断联合索引用到第几列。 rows预估需要扫描的行数。 filtered经过条件过滤后剩余的比例越大越精确。 Extra额外信息这一列信息量很大先看这一列基本能判断问题大概出在哪。3.3 几个典型的Extra信息解读Using where存储引擎返回后Server层又做了条件过滤说明过滤条件没完全用上索引。Using index覆盖索引只在索引树上就拿到了所需字段不回表这是好现象。Using index conditionICP索引条件下推8.0里常见减少了回表数量也是好事。Using filesort文件排序。常见于ORDER BY没走索引数据量大时非常致命。Using temporary临时表。常见于GROUP BY、DISTINCT、子查询要警惕。Using join bufferjoin时使用了join buffer说明关联字段没索引驱动表数据被反复扫。我看Extra的习惯只要出现Using filesort和Using temporary基本就要回头审视SQL写法出现Using where且type是ALL基本确定没有可用的索引。3.4 实战一条慢SQL从定位到优化举一个实际例子。订单表orders字段有id、customer_id、status、create_time、amount数据量200万。慢日志里抓到这条SELECT * FROM orders WHERE customer_id 10086 AND status 1 ORDER BY create_time DESC LIMIT 10;EXPLAIN结果显示typeALLrows2000000ExtraUsing where; Using filesort。这说明两个问题customer_id和status没有组合索引导致全表扫了200万行排序无法使用索引只能filesort。慢就慢在这两个点叠加。优化方案是建一个联合索引ALTER TABLE orders ADD INDEX idx_cust_status_time (customer_id, status, create_time);为什么把create_time也放进去因为查询里customer_id和status是等值条件create_time是排序条件。联合索引遵循等值条件在前、排序条件在后的布局InnoDB的B树可以把相同customer_id、status的数据按create_time天然排好ORDER BY DESC直接反向扫描索引即可filesort就消失了。这是索引设计里非常经典的一类场景。3.5 EXPLAIN ANALYZE执行给看的真实数据MySQL 8.0.18以后可以用EXPLAIN ANALYZE SELECT ...;替代普通EXPLAIN做深度排查。它会真正执行SQL输出每一步的实际时间、实际行数、循环次数。输出大概长这样- Limit: 10 rows (actual time0.123..0.456 rows10 loops1) - Sort: t.create_time DESC (actual time0.401..0.456 rows10 loops1) - Index range scan on orders using idx_cust_status_time (actual time0.056..0.378 rows100 loops1)这里可以看到实际扫描行数只有100行和之前EXPLAIN预估的200万行完全不同说明优化生效了。如果遇到EXPLAIN预估rows和实际偏差特别大多半是统计信息过旧可以执行ANALYZE TABLE orders;刷新。我常用的工作流是先EXPLAIN看计划再EXPLAIN ANALYZE确认实际瓶颈最后根据结果调整索引或SQL。4. 拿到真实执行耗时profiling与performance_schema4.1 profiling把一条SQL拆成多个阶段有时候EXPLAIN看不出问题比如索引、类型都对但就是慢。这时候用profiling把一条SQL的执行拆成多个阶段看时间花在哪一步。SET profiling 1; -- 执行你的SQL SHOW PROFILES; SHOW PROFILE FOR QUERY 1;输出会包含类似这些阶段starting、checking permissions、Opening tables、System lock、optimizing、statistics、preparing、executing、Sending data、end。重点看几个statistics优化器计算统计信息如果这里很慢说明统计信息复杂或表很大。Sending data这个阶段包含实际的数据读取和返回如果时间占了绝大部分瓶颈在数据访问。System lock锁相关时间长了要考虑并发冲突。Opening tables表打开次数多可以检查table_open_cache。8.0里profiling默认关闭官方也更推荐用performance_schema替代因为SHOW PROFILE粒度有限。但快速定位单条SQL时它依然十分直观不需要写复杂查询。4.2 performance_schema里的执行详情performance_schema是MySQL内置的监控数据库保存了大量执行事件。和排查执行详情最相关的表events_statements_summary_by_digest按SQL指纹聚合的统计一条SQL所有执行情况汇总。events_statements_history_long历史上执行过的语句带上线程ID、耗时、扫描行数、锁等待。events_transactions_history_long事务级事件。比如我想查最近执行最慢的10条SQLSELECT EVENT_ID, THREAD_ID, SQL_TEXT, TIMER_WAIT/1000000000 AS query_ms, ROWS_EXAMINED, ROWS_SENT, LOCK_TIME/1000000000 AS lock_ms FROM performance_schema.events_statements_history_long ORDER BY TIMER_WAIT DESC LIMIT 10;这里有个坑TIMER_WAIT的单位是皮秒10的负12次方秒除以10的9次方才是毫秒。很多人第一次查出来数字巨大一脸懵就是这个原因。另外SQL_TEXT字段需要statement采集完整记录时才非空否则得去关联其他表拿。performance_schema默认是开启的但如果发现events_statements_history_long没有数据需要检查setup_consumers表SELECT * FROM performance_schema.setup_consumers WHERE NAME LIKE %statements%;如果状态是NO最简单的办法是在my.cnf里配置performance_schema_consumer_events_statements_history_long ON4.3 一个没走执行计划却依然慢的案例我调过一个凌晨批量UPDATE特别慢的问题。EXPLAIN显示走主键typeconst看起来无懈可击但实际执行要1.8秒。开profiling以后发现Sending data阶段占了1.2秒再查performance_schema的等待事件发现大量时间花在等待buffer pool空闲页上。原因是当时缓冲池脏页比例过高后台刷盘跟不上。最后调整了innodb_io_capacity和innodb_max_dirty_pages_pct_lwm才缓解。这个案例说明执行详情不能只看执行计划瓶颈也可能在存储引擎内部这时候performance_schema里的等待事件才是关键。遇到这类问题顺着等待事件类型能定位到是IO、锁还是内存压力比瞎猜效率高很多。5. binlog里的执行历史用逻辑日志看数据变更5.1 binlog的开启与查看binlog记录所有写操作是主从复制和数据恢复的基础。查看是否开启SHOW VARIABLES LIKE log_bin;生产环境推荐配置server-id 1 log-bin /data/mysql/binlog/bin.log binlog_format ROW expire_logs_days 7binlog_format有STATEMENT、ROW、MIXED三种。ROW格式记录每一行数据变更前后的值安全性最好8.0默认就是ROWSTATEMENT格式只记SQL原文日志量小但某些语句在复制场景下可能产生不一致MIXED是混合模式。生产环境强烈建议ROW虽然日志体量大一些但可追溯性最好恢复数据也最准。查看binlog文件列表和当前位置SHOW BINARY LOGS; SHOW MASTER STATUS;解析binlog内容用mysqlbinlogmysqlbinlog -v --base64-outputDECODE-ROWS /data/mysql/binlog/bin.000001频繁执行的高并发业务binlog文件会很大直接打开会卡住建议配合时间范围过滤查看。5.2 通过binlog定位一次误操作比如有人误删了订单数据可以把binlog拉出来按时间范围过滤再搜索mysqlbinlog --start-datetime2025-01-10 10:00:00 --stop-datetime2025-01-10 10:30:00 /data/mysql/binlog/bin.000001 | grep -A 10 DELETE FROM ordersROW格式下mysqlbinlog -v输出的内容里能看到每一行的字段值包括删除前的完整数据。有了这个你可以把误删除的数据拼成INSERT语句回补线上。binlog恢复的本质是重放回放前必须确认目标数据当前状态不然会产生主键冲突或数据重复。更稳妥的做法先把binlog拿到临时库回放把准备执行的SQL过滤出来人工确认再应用到线上。顺便提醒一句8.0里binlog过期策略默认参数是binlog_expire_logs_seconds不是5.7时代的expire_logs_days配置时别写错。5.3 主从场景里执行详情怎么看主从复制就是主库生成binlog备库用IO线程拉取到本地relay log再由SQL线程重放。所以看备库执行详情重点在relay log和复制状态。SHOW SLAVE STATUS\G重点看Relay_Log_File、Relay_Log_Pos、Last_SQL_Error。如果Last_SQL_Error有值说明有SQL在备库执行失败具体失败细节要去错误日志里找。备库延迟排查时除了看Seconds_Behind_Master更关键的是确认复制线程是否在跑、IO线程是否追上主库。6. 常见问题与排查技巧实录6.1 慢查询日志开了为什么一直没内容先跑三行确认状态SHOW VARIABLES LIKE slow_query_log; SHOW VARIABLES LIKE long_query_time; SHOW VARIABLES LIKE slow_query_log_file;确认是ON之后看当前会话的long_query_time有没有被单独改过改过就重新连接再测试。另外一个很容易忽视的long_query_time在my.cnf里如果写成了500实际是500秒而不是500毫秒那等于没开。还有个隐蔽问题slow_query_log_file指定的目录必须存在且有写权限。目录不存在时MySQL启动并不会报错但日志就一直写不进去。用lsof查文件是否被进程正常打开或者直接看文件有没有增长都能确认。6.2 general_log开完忘了关磁盘被写满这是经典事故。有人在生产环境为了排查问题开general_log然后忘了关几天后磁盘满数据库不可写。general_log记录量极大正常业务一秒钟几千条SQL每一条都是文本一天涨几个G到几十个G很正常。我的习惯是这样log_output设置成TABLE写进mysql.general_log表用SQL查询更灵活。开完后给自己设个提醒半小时内必须关掉。排查前先估算业务QPS。QPS高的情况下优先用performance_schema而不是general_log。6.3 怎么看SQL是卡在锁上还是卡在查询上先看慢日志的Lock_time如果Lock_time很长而Query_time也长很可能是等锁。进一步确认SHOW ENGINE INNODB STATUS\G看LATEST DETECTED DEADLOCK和TRANSACTIONS段落能看到当前事务的锁等待链条。也可以直接查information_schema下面的INNODB_TRX和INNODB_LOCK_WAITS把阻塞源头找出来。我处理过一个线上问题一条UPDATE每天下午准时卡十几秒查了锁等待才发现是另一个定时任务在批量UPDATE同一批数据两个业务互相抢锁。后来把定时任务错峰执行问题彻底消失。这类问题不靠锁等待详情根本定位不到。6.4 日志清理策略怎么定日志是无限增长的不清理早晚出事。错误日志不会自动rotate需要借助系统logrotate慢日志通常按天切分后压缩binlog靠expire_logs_days或binlog_expire_logs_seconds自动清理也可以手动执行PURGE BINARY LOGS BEFORE 2025-01-01 00:00:00;清理binlog前务必确认主从没有延迟否则会把备库还没来得及拉走的binlog删掉造成主从复制中断。我就干过这事手一抖把老binlog全清了备库瞬间报1236错误最后只能重新搭建备库教训很深。排查MySQL执行详情这么多年我的体会是先宏观判断后微观取证。宏观就是用慢查询日志和错误日志圈范围微观就是用EXPLAIN和performance_schema钻取细节。日志系统不是开得越多越好而是越精准越好生产环境下能不开的尽量不开能用performance_schema解决的就别开general_log。还有一条很实用的经验每次排查完把关键配置、日志截取、分析结论整理成简短笔记下次遇到类似问题直接搜索比翻各种文档快得多。这套方法在MySQL 5.7到8.0上都适用核心思路不变掌握之后你会发现数据库问题并不可怕可怕的是没有一套顺手的排查路径。
