ARTICLE DETAIL

资讯详情

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

MySQL通用日志general_log:从原理到实战,揭秘审计与排查利器

MySQL通用日志general_log:从原理到实战,揭秘审计与排查利器 凌晨两点被电话叫醒几乎是每个搞过数据库的人都经历过的“必修课”。那天业务方告诉我订单表里有一批数据被update了但排查了一圈代码没人动过脚本没人跑过binlog翻出来也只能看到具体SQL和事务序号根本看不出这条语句是从哪个客户端、哪台应用服务器发出来的。那一刻我最后悔的就是没有提前打开general_log。这就是MySQL的通用查询日志——它会记录每一个到达MySQL Server的请求不分好坏、不辨快慢、不管成功与否只要Server收到就落盘。它跟慢查询日志、binlog、错误日志最大的区别就一个字全。正因为全它在“事后审计、死锁分析、真实SQL流量摸底”这些场景里几乎是不可替代的存在。这篇文章就把general_log从原理、开启姿势、代价评估到实战排查、日志维护完整讲清楚。无论是DBA、后端开发还是运维朋友看完都能直接用上。1. general_log记录的本质它和慢查询、binlog、错误日志的分工1.1 一个“有记录癖”的日志所有到达Server的语句都别想逃general_log翻译过来是“通用查询日志”它做的事情特别简单粗暴客户端往MySQL发了任何东西Server收到之后在真正做权限校验、解析、优化、执行之前先把这条请求原样记下来。这句话里最关键的是“收到之后、执行之前”。它意味着几件事执行失败的SQL也会被记录。比如语法写错了、字段不存在应用可能只看到报错但general_log里已经有这条语句了。执行超时被kill的SQL也会被记录。你手动砍掉的慢查询日志里能看到它“来过”。连接和断开本身也会被记录。日志里有Connect、Quit这类command_type能看出谁在什么时候连了上来。事务控制语句也会被记录。BEGIN、COMMIT、ROLLBACK都跑不掉。这也解释了为什么它叫“通用”日志——它不挑食不筛选不判断。优化器最终执行成什么样它不管它只关心“请求长什么样”。1.2 四条日志的分工为什么general_log不可替代很多人习惯把MySQL的日志混在一起讲真到排查问题时会发现各自的盲区。我把四条日志放在一起对比大家感受一下。日志类型默认状态记录内容典型用途错误日志开启启动关闭信息、连接异常、复制错误、告警故障排查第一入口慢查询日志关闭超过long_query_time阈值的语句SQL性能优化binlog取决于配置数据变更的逻辑记录备份恢复、主从复制general_log关闭Server收到的所有语句审计、疑难问题定位、SQL流量分析binlog里看不到SELECT因为查询不产生数据变更慢查询日志里看不到“执行很快但反复刷屏”的语句因为每条都低于阈值错误日志里看不到正常请求。那问题来了如果业务方跑过一条SELECT但没人承认或者一段复杂的锁等待里到底谁先执行了哪条SQL你手里有binlog、有慢日志、有错误日志就是拼不出完整的时间线。这种时候只有general_log能回答“这条语句到底有没有发到过数据库、它是从哪来的、前后还执行了什么”。它是还原现场的最佳工具。1.3 一条日志记录长什么样先看文件输出模式一条日志大致是这样2025-01-18T09:32:12.456789Z 458 Query SELECT * FROM user WHERE id 1001 2025-01-18T09:32:13.001234Z 459 Connect root[root] localhost [127.0.0.1] on用制表符拆开看实际上就是四列时间戳、线程ID、命令类型、语句内容。这里面的Thread_id非常关键——它和SHOW PROCESSLIST里的Id是对应的。出问题的时候拿Thread_id去关联processlist就能看到这条连接当时的用户、来源IP、端口、当前状态一条线全串起来。切到表输出模式后记录落在mysql.general_log这张表里核心字段是event_time、user_host、thread_id、server_id、command_type、argument。其中user_host记录的是类似 root[root] localhost [127.0.0.1] 这样的客户端身份信息argument就是完整SQL文本。2. 开启general_log的正确姿势变量、落盘路径与输出模式2.1 三个核心变量一次说清开启general_log牵扯三个系统变量别看数量少弄混的人不少general_log开关ON或OFF动态变量可以SET GLOBAL直接改。log_output输出方式取值FILE、TABLE也可以写在一起变成FILE,TABLE。general_log_file当log_output包含FILE时日志写入的路径和文件名默认在数据目录下以主机名命名比如/var/lib/mysql/host.log。登上去看一眼当前状态SHOW VARIABLES LIKE general_log%; SHOW VARIABLES LIKE log_output;这两条命令是标配。多数情况下你会看到general_logOFF、log_outputFILE因为FILE是默认值。2.2 应急开启三步走以及“立即生效”的真相真实线上出问题的时候没有心思去改配置文件重启所以一定要掌握动态开启的方式。三步走-- 第1步确认输出模式 SET GLOBAL log_outputFILE; -- 第2步打开总开关 SET GLOBAL general_logON; -- 第3步验证 SHOW VARIABLES LIKE general_log;第3步还可以顺便去文件系统里看一眼用tail -f直接观察日志滚动tail -f /var/lib/mysql/host.log有个细节很多人不确定SET GLOBAL general_logON之后已经存在的旧连接会被记录吗答案是会。general_log是全局开关不是会话级变量一旦打开所有现存连接和新连接的请求都会立刻写入日志。这意味着应急排查时一条命令下去日志马上开始记录不需要中断业务也不需要等新连接建立这个特性在关键时刻真的救命。还有一个彩蛋因为日志记录发生在命令执行之前你执行SET GLOBAL general_logON这条命令本身并不会被记录但等你要关它的时候执行SET GLOBAL general_logOFF这条命令会被记录因为此刻日志还开着。所以关日志的人一不小心就会在日志末尾看到自己的“作案痕迹”。如果确认这次开启只是应急不需要持久化那操作到这里就结束了。如果希望以后重启实例也默认开启需要在my.cnf的[mysqld]段下面追加配置general_log1 log_outputFILE general_log_file/data/mysql/log/general.log这里有个坑general_log_file不是动态变量不能通过SET GLOBAL直接改。想改文件路径只能改配置文件再重启实例或者用操作系统层的软链接方案——但生产环境我不建议为了一条日志去做软链接改动风险大于收益。2.3 文件模式和表模式怎么选对比项FILETABLE查看方式tail/less/grep普通运维就能看用SQL查mysql.general_log分析能力靠文本工具统计需拼命令可以写SQL做复杂聚合统计性能开销每条语句一次文件写入每条语句多一次INSERT更重清理方式轮转文件、删除文件TRUNCATE表典型场景默认选择、应急排查需要快速统计高频SQL时我的建议很直白大部分场景选FILE。原因有三点。第一文件模式性能开销小顺序写比INSERT到表里要轻得多。第二文件格式简单任何能登录服务器的同事都能用less查看不需要额外的数据库权限。第三日志轮转容易mv一下就能归档。表模式唯一让我觉得值得用的场景是要对SQL做复杂统计的时候比如“过去半小时里执行次数Top 20的语句”直接SQL聚合比awk处理文本省事太多。这时候可以先SET GLOBAL log_outputTABLE再开general_log用完迅速关掉。顺便说一句log_output可以写成FILE,TABLE同时输出两份但生产里我几乎没见过这么干的。双倍写入开销收益却是零纯粹给自己找麻烦。2.4 开general_log前先确认performance_schema帮不上忙很多人不知道MySQL自带的performance_schema里有一张events_statements_history_long表会在内存里保存最近执行过的SQL历史。它不需要落盘不需要重启对性能影响也小得多适合做短时的问题定位。SELECT THREAD_ID, SQL_TEXT, TIMER_WAIT / 1000000000000 AS time_sec FROM performance_schema.events_statements_history_long ORDER BY EVENT_ID DESC LIMIT 20;这张表默认保留的行数有限通常只有几千到一万行左右重启实例会被清空。所以它不能替代general_log做审计但很适合回答“我刚才那条SQL到底有没有执行”。遇到这种短窗口的问题先查它不满足再开general_log这是最聪明的顺序。3. 开启之前必须想清楚的代价磁盘、性能与敏感信息的风险3.1 磁盘爆炸的速度一个公式和一次教训general_log是真的名副其实的“磁盘杀手”我见过太多人开完日志忘了关第二天早上磁盘100%报警。先给一个估算公式每天写入量 QPS × 平均日志行长度 × 86400秒一条日志行的长度SQL短的话150字节左右带复杂WHERE条件的生产SQL 300字节很正常。按200字节、QPS1000来算1000 × 200 × 86400 17.28GB/天也就是说一个不算高并发的实例开一天日志就是17GB。如果QPS到3000一天52GB。如果是业务高峰期的核心库QPS上万一天几百GB也不是开玩笑。我自己踩过一个大坑在一台8核16G的实例上做压测顺手开了general_log想看看驱动下发的SQL结果一顿饭的工夫日志文件从几百MB涨到40多GB直接顶爆了磁盘。事后复盘就是低估了压测工具那个“每分钟几十万条查询”的并发量。所以开之前一定先跑一句df -h /data然后按上面的公式估算一下磁盘够撑多久再决定日志开多长时间。宁可开两小时关掉也别一口气开一天。3.2 性能影响不是零文件模式和表模式各有代价有人觉得“日志嘛写写文件而已能有多大事”。如果业务QPS很低确实感受不到区别。但高并发场景下每条SQL都要多一次日志写入哪怕有buffer做缓冲也会带来额外的系统调用和IO压力。表模式就更夸张了。每条语句都要往mysql.general_log里INSERT一次等于是把数据库的写放大又提升了一个量级。我实测下来同样的并发表模式的额外开销明显高于文件模式而且mysql.general_log这张表本身还会膨胀清理不及时查询它都变慢。所以我的核心建议是OLTP高峰期不要开低峰期短时开。排查问题讲究的是窗口期不需要24小时持续记录。如果业务日活集中在白天那就夜里凌晨开两小时或者白天挑个流量最低的时间段开。3.3 敏感信息明文落盘开之前先想好合规这是最容易被忽略的一点。general_log记录的是原始请求也就是说客户端发的SQL里有什么日志里就有什么。举例来说如果应用代码里执行了CREATE USER、ALTER USER或SET PASSWORD日志文件里会原样保留SQL文本包括用户名字和密码字符串。GRANT语句里的权限细节同样暴露无遗。这种情况下一旦日志文件权限没收紧或者不小心被同步到了对象存储等于把密码本送给了别人。处理策略我给三条生产环境开general_log之前先和团队确认有没有合规约束文件权限一律收紧不要把日志放到/tmp、/home这类世界可读的目录。日志保留时间尽可能短拿到证据立刻清理不要想着“留着以后查”审计需求应该走专门的审计组件。重要实例做压测和验收时优先用脱敏过的测试库避免真实业务数据里的敏感SQL落盘。3.4 什么时候开、开多久我的实践原则经过几次惨痛教训我给自己定了一套规矩分享出来新业务上线后的头一两天挑低峰期开2到4小时看看框架和中间件实际下发的SQL是不是和开发提交的一致。出现诡异问题比如“数据莫名被改”“锁等待频繁”“连接异常”开日志窗口和复现窗口对齐拿到证据就关。压测环境随便开本来就是用来观察SQL流量的。极个别情况需要长时间审计优先考虑从库开启。从库没有业务写压力日志量相对小但要注意从库的SQL来源基本是主库的复制线程源IP定位能力会弱很多。4. 实战复盘三次靠general_log翻案的疑难问题4.1 案例一死锁复现与锁等待顺序有一次预发环境频繁报死锁业务方拍着胸脯说“我们代码是先查A再查B顺序绝对一致不可能死锁”。我用SHOW ENGINE INNODB STATUS确实能看到死锁的双方SQL问题是这两个事务在时间线上到底谁先启动的、各自的加锁顺序是什么死锁输出信息根本拼不出来。后来我在压测场景下加了general_log问题立刻现原形。排查链路是这样的打开general_log记录窗口和压测同步。复现死锁后去日志里过滤出窗口内的相关SQL。用thread_id关联SHOW PROCESSLIST确认两个事务分别来自哪台应用服务器的哪个连接。按event_time排序把两条连接各自执行的SQL序列重新摆出来。最终发现代码逻辑本身顺序没错但连接池复用导致两个请求在同一时刻交叉执行A请求走到一半需要B请求持有的锁B请求也在等A请求的锁死锁就这么产生了。general_log的价值在于把“谁先谁后”的铁证摆出来了没有它业务方还是会觉得是数据库抽风。4.2 案例二神秘UPDATE的来源审计这是文章开头那个故事的完整版。线上订单表凌晨被批量updatebinlog里有变更记录和事务ID但不知道是谁发的。当时恰好我已经在实例上保留了general_log于是排查变得非常快SELECT event_time, user_host, thread_id, argument FROM mysql.general_log WHERE argument LIKE %UPDATE order% AND event_time BETWEEN 2025-01-18 03:00:00 AND 2025-01-18 04:00:00 ORDER BY event_time;结果一出来真相大白一条UPDATE语句来源IP指向某个测试环境的跳板机执行时间精确到微秒。再拿thread_id去查SHOW PROCESSLIST历史定位到连接来自应用连接池的特定端口最后顺藤摸瓜找到了那个手动跑脚本的同事。这就是general_log在审计场景里的核心优势它对“账号密码”不敏感对“来源”非常敏感。binlog告诉你“什么事发生了”general_log告诉你“谁在哪台机器上发的、前后还干了什么”。4.3 案例三高频SQL刷屏监控却没报警有一阵子线上QPS指标正常但用户反馈接口变慢。开发说没加新功能监控也没报慢查询一时不知道从哪下手。我在低峰期开了general_log用tail观察了十分钟就发现一条奇葩语句在疯狂刷屏每几秒钟就会出现一次同样的SELECT而且字段名很冷门业务代码里根本搜不到。顺着thread_id和user_host追下去发现是一个中间件的心跳检测把连接“认为”空闲反复发探测SQL验证连接有效性。本身一条SQL执行只要零点几毫秒但架不住几千个连接同时这么干硬是把数据库的CPU和IO给挤满了。处理方案很简单调整连接池的验证查询频率或者改成直接用现有连接测试而不额外发SQL。这个案例提醒我监控指标正常不代表没有异常流量general_log往往能发现监控盲区里的傻SQL。5. 日志轮转、清理与格式化不能让救命日志变成事故本身5.1 文件模式轮转先关再移再开别踩文件句柄的坑文件模式清理的正确姿势特别像“关机再换轮胎”。完整的轮转步骤# 1. 关闭日志 mysql -e SET GLOBAL general_logOFF # 2. 确认关闭后再移动文件 mv /data/mysql/log/general.log /data/mysql/log/general.log.20250118 # 3. 重新开启 mysql -e SET GLOBAL general_logON # 4. 按需压缩归档 gzip /data/mysql/log/general.log.20250118这里必须强调一个极其常见的坑千万不要在general_log还开着的状态下直接mv文件。Linux下文件被进程打开后你mv走的其实只是目录项MySQL的文件描述符还指着原来的inode数据会继续写进那个“已移走”的文件里。结果就是你mv完了磁盘空间半点没释放日志还在你看不见的旧文件描述符里疯狂增长直到把磁盘打满。轮转时先执行SET GLOBAL general_logOFF静等一两秒确保写操作落定再mv再SET GLOBAL general_logON。顺序一步都不能乱。5.2 TABLE模式清理TRUNCATE而不是DROP如果用的是表模式清理就简单了SET GLOBAL general_logOFF; TRUNCATE TABLE mysql.general_log; SET GLOBAL general_logON;注意两点。第一不要DROP TABLE mysql.general_log。这张表是系统表删除之后MySQL不会自动给你重建再次开启general_log会直接报错。实在误删了得手动按官方表结构建回来非常麻烦。第二不要用DELETE FROM清理。这表底层存储方式特殊DELETE性能奇差无比高并发下能把你数据库拖死TRUNCATE是截断操作速度飞快而且是处理这表的正确姿势。5.3 格式化与统计从原始文件里提炼证据日志文件拿到手之后第一步是统计高频SQL。我用过一个比较实用的命令组合grep -E Query /data/mysql/log/general.log \ | sed -E s/^[^ ] [0-9] Query // \ | sort | uniq -c | sort -nr | head -20这条命令能快速排出Top 20的SQL。注意我特意把时间戳、线程ID、命令类型这些前缀剥掉再对SQL文本做uniq计数不然每一条都是唯一行统计出来全是一堆1。如果要按线程分析某条连接的完整操作序列可以用python按thread_id聚合思路很简单把每一行拆成“线程ID SQL”两个部分放进字典里按线程分组再按时间排序输出。还得多说一句如果SQL本身包含换行符日志文件里会出现一条SQL被拆成多行的情况这种时候按行处理会出错。处理多行SQL需要更细的逻辑比如按“时间戳 数字 关键字 Query”作为新记录的开头标志后续非匹配行都拼到上一条记录里。5.4 时区、多行SQL与文件权限容易被忽略的细节折腾general_log文件的人十有八九栽过时区的坑。MySQL里log_timestamps决定日志文件里的时间是UTC还是系统本地时间。如果你发现文件里的时间比业务时间慢了8小时别慌先查SELECT log_timestamps;默认值在不同版本里不一样有的版本是UTC有的是SYSTEM。排查的时候建议把两个时间放在同一个坐标系里对比别拿UTC时间去对业务日志否则时间线全错位。文件权限也要顺手收紧chown mysql:mysql /data/mysql/log/general.log chmod 640 /data/mysql/log/general.log日志里全是明文SQL权限越收紧越好。这几年折腾下来我对general_log的态度很简单平时不让它开但每台实例上都留好轮转脚本和足够的空闲磁盘。一旦遇到“这条SQL到底从哪来的、到底执行过没有”这类问题我一定是优先开general_log短则半小时长则两小时拿到证据立刻关。用得最多的时候反而是在新业务验收阶段开个半天对比一下实际SQL和开发预期之间的差异经常能发现框架或中间件偷偷塞进来的额外查询。最后再叮嘱一句开之前先df -h看一眼磁盘轮转脚本提前准备好——日志是来解决问题的别让它自己变成事故现场。
返回列表