ARTICLE DETAIL

资讯详情

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

通用查询日志general_log的完全解读:从原理到排障实战

通用查询日志general_log的完全解读:从原理到排障实战 接手过线上MySQL的人应该都经历过这种尴尬时刻数据库突然变慢连接数蹭蹭往上飙各种监控告警刷屏你盯着屏幕想知道数据库到底在跑哪些SQL结果手里全是一堆无关紧要的业务日志数据库内部发生了什么完全没有头绪。如果当时能提前打开general_log通用查询日志事情会简单很多——它会把你每一次连接、每一条SQL、每一个操作原原本本记下来。这篇文章就把general_log从里到外讲透它跟binlog、慢查询日志到底怎么分工什么时候该开开了以后怎么分析以及几个我踩过的坑。1. general_log到底记录了什么1.1 先分清MySQL的四种日志很多人一听说“日志”就以为都是同一个东西其实MySQL里的日志分工非常明确。general_log和另外几个兄弟经常被混淆先把它们捋清楚。日志类型记录内容默认状态主要用途general_log所有客户端发来的命令和SQL包括连接、断开、查询、修改、失败操作关闭全量审计、问题回溯binlog引起数据变更的操作UPDATE、DELETE、INSERT等视配置开启主从复制、按时间点恢复slow_query_log执行时间超过阈值的慢查询关闭慢SQL优化error_log启动、关闭、连接异常、错误信息开启故障诊断这里有个很容易误解的点binlog只记录“数据变更”类的操作你跑一条SELECT它压根不搭理所以你想用binlog排查“某个查询导致CPU飙高”这种问题是南辕北辙。而慢查询日志虽然会记录SELECT但它有门槛——只有超过long_query_time的SQL才会被记下来。如果你遇到的问题是接口偶发卡顿、并发量异常上升、或者某个客户端在反复尝试连接慢查询日志可能什么线索都没有因为问题根本不在“慢”上。greneral_log就不同了。它没有任何筛选条件不管SQL执行成功还是失败耗时1毫秒还是100秒有没有影响数据只要到了MySQL服务器都会被记录。你可以把它理解为数据库的“监控摄像头”24小时不眨眼睛记录流经数据库的所有指令。1.2 适用场景什么时候值得开general_log默认关闭是有道理的但以下场景确实值得打开一是线上出现了诡异问题业务日志和监控只能告诉你“某接口超时了”“数据库连接失败了”但没人知道数据库里真实发生了什么。这时候打开general_log相当于给数据库装了个黑匣子复现一次问题日志里就有答案。二是排查应用代码里隐藏的SQL问题。有些框架会自动拼接SQL、自动执行额外查询代码里根本看不出来。打开general_log抓一段实际执行的语句你会发现应用比你想象的“健谈”得多。三是安全审计。有人或程序在反复尝试登录、猜测密码、扫描数据库结构general_log里会留下完整的连接记录比如哪个IP、哪个用户名、什么时候连的、发了什么命令。这些信息对于定位异常访问非常关键。1.3 开启的代价每条SQL都留痕在开之前必须把代价讲清楚否则你会有“惊喜”。general_log每收到一条命令就要写一次日志意味着磁盘IO会明显增加尤其在高并发场景下性能损耗不可忽视。我曾经在一台QPS在3000左右的业务库上临时打开过general_log当排障工具短短10分钟数据库整体响应时间就上去了磁盘写IO从平时几乎为零飙到每秒几十MB。所以它更适合作为“短时诊断工具”而不是常驻功能。如果确实因为合规或审计需要长期开启一定要把日志目录放到独立的磁盘上并且做好日志轮转否则磁盘被写满是迟早的事。简单算一笔账平均一条日志记录大概200字节线上QPS如果是500那每秒就是100KB的写入一天下来约8.6GB。这还只是单机不是高QPS。实际生产环境中一条较长SQL的日志很容易超过1KB那磁盘增长就不是线性的事了。2. 参数怎么配日志写到哪里2.1 三个核心参数逐个说控制general_log的其实是一组变量最核心的有三个general_log总开关、general_log_file日志文件路径、log_output日志输出方式。它们在MySQL 5.7和8.0里都存在名字完全一致。可以用这条命令看当前状态SHOW VARIABLES LIKE general%;结果类似这样--------------------------------------------- | Variable_name | Value | --------------------------------------------- | general_log | OFF | | general_log_file | /var/lib/mysql/xx.log | | log_output | FILE | ---------------------------------------------general_log只有ON和OFF控制整个日志是否生效。general_log_file是文件输出时的路径注意不同系统上默认路径不一样以SHOW VARIABLES的结果为准。log_output则有两个值FILE和TABLE也可以写成FILE,TABLE同时输出两份但日常基本用其中一个就够了。这三个参数的修改方式有两种动态修改和配置文件持久化。动态修改用SET语句效果立即生效但服务重启后会恢复原样持久化配置需要写进my.cnf的[mysqld]段重启后依然生效。2.2 FILE和TABLE两种输出选哪个log_output选择直接决定了你后续怎么分析日志这一步别图省事。FILE方式是把日志以文本形式写入操作系统文件格式类似2024-01-15T10:22:33.123456Z 12345 Query SELECT * FROM user WHERE id 1这个方式的优点是可以直接用各种shell命令grep、awk、sort处理也可以配合logrotate做日志切割适合长期记录。缺点是你得管理文件磁盘满了要自己处理分析复杂问题时写长SQL查询不方便。TABLE方式是把日志写进MySQL自带的mysql.general_log表这张表的默认存储引擎是CSV每一条记录是一个文本行。它的优点太明显了可以直接用SQL查询比如我想看某段时间内执行了哪些SELECT直接SELECT event_time, user_host, thread_id, command_type, argument FROM mysql.general_log WHERE event_time BETWEEN 2024-01-15 10:00:00 AND 2024-01-15 10:30:00 AND command_type Query ORDER BY event_time;缺点也明显表会不断膨胀而且CSV引擎不支持索引数据量大了查询会全表扫描。另外日志表本身也是MySQL里的表清理不当会引发额外问题。所以我的经验是短时间排障用TABLE持续审计用FILE。2.3 第一次完整开启的流程以一个典型的临时排查为例完整走一遍流程。先确认当前状态SHOW VARIABLES LIKE log_output; SHOW VARIABLES LIKE general_log%;决定日志写到TABLESET GLOBAL log_output TABLE;打开开关SET GLOBAL general_log ON;验证是否生效SELECT global.general_log;这时候去应用侧复现一次问题然后在表里查刚才的记录SELECT event_time, user_host, command_type, argument FROM mysql.general_log ORDER BY event_time DESC LIMIT 10;这里有一个很容易被忽略的细节如果你用TABLE方式查询mysql.general_log表本身也会被记录进日志里所以你永远能在最后看到你自己的SELECT语句。这不是什么异常别被吓到。排障结束后记得关闭SET GLOBAL general_log OFF;如果不需要保留数据顺手清空这张表TRUNCATE TABLE mysql.general_log;注意TRUNCATE这张表需要至少DROP权限普通开发账号通常没有切到管理员账号操作就行。如果要保存为文件长期开启配置文件写法如下[mysqld] general_log 1 general_log_file /data/mysql/logs/general.log log_output FILE在my.cnf里general_log可以直接用1/0表达ON/OFF。同时要保证general_log_file指定的目录存在且mysql进程有写权限我一般会先手动建好目录并把属主改成mysqlmkdir -p /data/mysql/logs chown mysql:mysql /data/mysql/logs如果目录没权限MySQL启动时会报错或者日志写不进去这个坑我踩过不止一次。3. 日志字段拆解记录里每一列都是线索3.1 mysql.general_log表结构和含义采用TABLE方式时日志落在mysql.general_log表。这张表虽然属于系统库但结构很容易理解字段含义示例值event_time事件发生时间精确到微秒2024-01-15 10:22:33.123456user_host客户端用户名、主机、端口root[root] localhost [127.0.0.1]thread_id线程ID可关联SHOW PROCESSLIST123456server_id服务器ID多实例环境区分来源1command_type命令类型Query / Connect / Quitargument具体内容SQL或命令文本SELECT * FROM user WHERE id 1event_time带微秒是个好设计同一秒内执行的SQL可以用它排序还原现场。thread_id特别有用当你看到一个线程突然消失、或者反复连接断开时可以用它去对应应用层的连接池状态。command_type更是判断问题性质的关键常见的有Query查询/修改、Connect建立连接、Quit断开连接、Change user切换用户、Init DB切换数据库等。3.2 命令行日志文本长什么样用FILE方式时日志文件里一条记录长这样MySQL 8.0示例2024-01-15T10:22:33.123456Z 12345 Connect app_userapp_host[app_user] on dbname 2024-01-15T10:22:33.223456Z 12345 Query SELECT * FROM orders WHERE order_no A123456 2024-01-15T10:22:33.523456Z 12345 Quit看懂这串格式有两个关键点第一段是时间第二段是线程ID第三段是命令类型后面是具体内容。“Connect”后面能看到谁连的、哪个库查询类命令则直接显示完整的SQL。不同版本之间的文本格式可能有细微差异比如5.7的时间格式跟8.0就不太一样分析时先手动看两行确认字段在第几列再做自动化解析不要拿一个老脚本直接套新环境。3.3 快速统计高频SQL和来源IP拿到日志以后最常用的两个分析路径一个是“谁在频繁执行”一个是“都在执行什么”。用TABLE方式最省事因为直接SQL分组统计即可。找出Top 10来源SELECT user_host, COUNT(*) AS cnt FROM mysql.general_log GROUP BY user_host ORDER BY cnt DESC LIMIT 10;找出执行次数最多的SQL注意GROUP BY argument时字符串中空格、大小写不一致会导致分组过细可以先用LEFT截断一部分再统计SELECT LEFT(argument, 200) AS sql_prefix, COUNT(*) AS cnt FROM mysql.general_log WHERE command_type Query GROUP BY sql_prefix ORDER BY cnt DESC LIMIT 20;FILE方式则用命令行工具组合拳。比如统计每条SQL出现的次数grep Query /data/mysql/logs/general.log | awk {print $(NF)}真实统计时awk的字段位置你要根据前面手动观察的结果来确定我上面的例子依赖默认空格分割实际生产环境SQL中间有大量空格直接按空格分割会乱。更稳妥的方式是取出整行后去掉日期和线程ID前缀剩下部分即为SQL内容。你可以这么操作sed -E s/^[0-9T:.Z-] [0-9] Query[[:space:]]// /data/mysql/logs/general.log | sort | uniq -c | sort -rn | head -20这类命令的关键在于先用head看几行验证切割规则再全量跑别上来就硬套。4. 实战案例三次用general_log救场的经过4.1 接口偶发超时靠日志锁定可疑SQL有一次线上一个分页查询接口时不时超时业务日志只能看到调用超时监控面板上数据库CPU确实会突然跳高但持续时间非常短慢查询日志里什么都没记录。怀疑是某些SQL执行慢但慢查询日志里连一条几千行的SELECT都没有因为它的执行时间没有达到阈值。我临时开了general_log把log_output切到TABLE然后在应用侧用脚本按固定频率调用接口触发超时。几分钟后查mysql.general_log发现在超时发生的那一秒应用额外执行了一条SQLSELECT * FROM products ORDER BY RAND() LIMIT 6一看这写法就明白了——每次随机排序都要把整张表读出来做全排序数据量一上来偶发超时必然发生。这条SQL出现在代码里的某个“猜你喜欢”逻辑中正常业务大多命中缓存但缓存一冷启动就会触发全表排序。如果没有general_log我真的很难从业务日志和数据监控里定位到这条躲在里层的查询。4.2 连接数尖峰回溯应用到底在干嘛另一次是某天下午数据库连接数突然从200飙升到3000连接堆积严重应用基本不可用。事后看监控只能看到连接数曲线像一座山完全不知道那些连接在做什么。因为多数连接建立后甚至还没来得及执行第一条SQL慢查询日志和binlog都用不上。我打开general_log后按线程ID统计连接次数发现异常时间段里某一个应用IP的Connect记录占了90%以上而且线程ID变化极快说明连接在短时间内不断创建和销毁。再去翻应用的连接池日志发现代码里在某个异常分支写了一个new Connection的逻辑每次调用接口都会新建连接而没有复用一个流量小高峰就把连接池打爆了。general_log在这里的价值不在于SQL分析而在于精确还原“连接生命周期异常”的全过程。4.3 疑似爆破登录从user_host看出端倪还有一个来自安全侧的案例。某天发现mysql.error_log里出现了大量“Access denied”一看就是有人在试探密码。但error_log只记录了失败信息缺少完整的时间线、来源IP和尝试频率。开启general_log后我看到某个陌生IP在短时间内不断发出Connect命令连接失败后立即重试特征非常明显。配合user_host字段和操作系统访问日志很快定位到恶意来源并做了屏蔽。同时我将这个时间段的general_log导出留存作为攻击行为的证据。如果你维护的数据库有公网访问入口哪怕只是测试环境也建议偶尔开一下general_log检查有没有类似异常尝试。5. 高频问题与避坑清单5.1 磁盘被日志撑爆的紧急处理general_log日志增长太快导致磁盘满这是最典型的故障。处理顺序非常重要先关闭日志避免继续写入SET GLOBAL general_log OFF;然后确认日志文件大小du -sh /data/mysql/logs/general.log如果是FILE方式直接把旧的日志文件移走或删除腾出磁盘空间。如果是TABLE方式清理mysql.general_log表TRUNCATE TABLE mysql.general_log;注意TRUNCATE之前在磁盘满的情况下要小心因为数据库可能已经因为磁盘满而处于只读状态需要先腾出一点空间让MySQL恢复可写再执行清理。更保险的流程是先删掉其他无用文件比如临时文件、备份文件挤出空间再关闭general_log最后清理日志。事后必须找根因是忘了关是QPS远超预期还是日志切割没配否则历史还会重演。5.2 重启后就失效的参数持久化有次我帮同事排查问题动态打开了general_log测试完关机下班第二天早上来发现日志没记录了。原因很简单SET GLOBAL只改内存中的值MySQL重启后就恢复默认OFF。如果你需要长期记录必须写进my.cnf也就是前面提到的三行配置。还有一种更隐蔽的情况你同时配置了log_outputTABLE和log_outputFILE服务重启后日志输出模式被配置覆盖回原值排障时你在表里没查到记录误以为general_log没打开。所以重启后第一件事永远是确认这三个变量当前值别只看其中一个。5.3 mysql.general_log表膨胀清理TABLE方式的日志表默认引擎是CSV没有索引查询效率不高表文件一直增大。如果长期开启这张表会变成一个大文件。清理方式很简单但时机有讲究先关闭general_log再TRUNCATE最后重新开启。顺序不对的话TRUNCATE期间新写入的记录会被清掉一部分或者因为表被占用导致锁等待。SET GLOBAL general_log OFF; TRUNCATE TABLE mysql.general_log; SET GLOBAL general_log ON;如果你需要在清理后保留历史数据可以先把旧数据导出再清空CREATE TABLE tmp_general_log_backup AS SELECT * FROM mysql.general_log;但注意这张备份表同样会长大记得导出成文件后及时清理。5.4 长期使用心得与安全提醒最后分享几个我从实际使用中总结的习惯希望能帮你少走弯路。第一不要把general_log当成监控工具常开。真正的监控应该依赖performance_schema、sys库和慢查询日志general_log解决的是“未知问题定位”不是“日常巡检”。第二需要排障时最好写一个带自动关闭的脚本。比如mysql -e SET GLOBAL general_logON; sleep 600 mysql -e SET GLOBAL general_logOFF;这样即使你排查完忘了手动关10分钟后它也会自己关闭避免日志无限增长。我习惯把这个脚本直接塞进跟应用问题的联调流程里问题复现完脚本自动收尾很省心。第三注意日志安全。general_log会记录明文SQLSQL里经常带着用户ID、手机号、地址这类敏感信息甚至偶尔会有人把密码明文写在SQL里虽然极不规范但真发生过。日志文件的系统权限一定要收紧建议600不要放在Nginx目录或其他可被Web访问的位置。TABLE方式下mysql.general_log表的SELECT权限也要限制不能让所有开发账号随意读。第四清理和切割。用FILE方式时配合logrotate做日志轮转基本是必备操作。一个可用的配置参考/data/mysql/logs/general.log { daily rotate 7 compress dateext missingok notifempty copytruncate }copytruncate会直接复制日志内容并清空原文件不需要MySQL配合。它有极小概率丢失切换瞬间的少量日志但对于排障用途完全够用。根据我的个人经验general_log是那种“平时想不起来关键时刻能救命”的工具。它在运维工具箱里的地位很特殊大部分日志都在回答“发生了什么问题”而它回答的是“数据库从头到尾经历了什么”。下次遇到查不出原因的线上怪问题时不妨先打开它给工作留一份真正完整的现场记录。
返回列表