凌晨两点群里开始刷告警核心交易服务报错率异常。我 ssh 上服务器日志文件 4.7GB。这时候绝大多数后端同学的第一反应是什么cat app.log | grep ERROR。然后屏幕开始疯狂滚动SSH 窗口整个卡住等它滚完你又发现报错太多分不清主次。这还不算完因为你连续敲了几轮命令日志被反复读了好几遍磁盘 IO 也被拉满原本就紧张的生产环境雪上加霜。我见过太多人栽在这个无脑cat上。这篇我把自己压箱底的生产日志排查命令整理出来从查看、搜索、统计、时间窗口切割到异常堆栈提取再附上我在真实线上环境踩过的一堆坑后端开发、运维、SRE 都可以直接照着用。1. cat 读取 GB 级日志的代价一次事故复盘与三宗罪1.1 cat 的三宗罪全量读取、无差别输出、重复 IO先说最核心的问题cat这个命令的设计初衷是把文件内容原样输出到标准输出它不知道你后面接了什么。当你执行cat app.log | grep ERROR时cat必须把整个文件从头到尾读一遍把 4.7GB 数据全部写进管道grep再从管道里读一遍。同一份数据磁盘读一次、管道复制一次、grep再读一次等于跑了三遍。更坑的是如果你直接cat app.log没接管道终端会试图把几百万行文本全部渲染出来。SSH 窗口的渲染速度远低于磁盘读取速度于是你看到的就是光标闪烁、窗口卡死、键盘输入半天没反应。这时候你想 CtrlC 中断终端还得先把积压的输出队列处理完等于越着急越卡。第三宗罪是重复 IO。排查一轮问题你往往要试好几轮命令先 cat 看格式再 cat grep 找关键字再 cat awk 统计次数。每轮都是全量读一遍文件。4.7GB 的日志磁盘顺序读可能要 8 秒左右听起来不算太久。但生产环境的磁盘往往被多个应用共享日志文件本身也可能已经不在页缓存里加上管道复制和上下文切换的开销几轮下来一两分钟就没了而且磁盘 IO 飙升还会影响同机器上的其他服务。1.2 一笔算清楚的账为什么 catgrep 比直接 grep 慢那么多我拿一台普通服务器实测过。4GB 的日志文件磁盘顺序读速度大约 500MB/s直接grep ERROR app.log耗时大概 8 到 10 秒。而cat app.log | grep ERROR要 20 到 30 秒慢 2 到 3 倍。差距就在管道上。cat把数据写进管道grep从管道读数据管道默认 buffer 是 64KB。4GB 的数据意味着要经历大约 65000 次 read/write 系统调用再加上两个进程之间的调度切换。这还不算cat用户态到内核态、管道 buffer 到grep用户态的数据拷贝。而直接grep ERROR app.log只有一个进程数据从页缓存到grep用户态只读一次路径短得多。提示如果你只是想知道有没有 ERROR用grep -m 10 ERROR app.log。-m指定最大匹配行数找到 10 条就停止扫描错误多的时候这个命令几乎是秒回。而cat管道方案里即使grep提前退出cat还在傻乎乎地继续读文件直到收到 SIGPIPE 信号才停止前面的 IO 全白费了。1.3 什么情况下 cat 仍然是合理的也不是说cat就完全不能碰。小文件无所谓几 MB 的配置文件、启动脚本、测试输出随便 cat。还有两种场景我会用把日志的头部或尾部内容完整贴给同事看几十上百行用head -n 100配合cat。确认文件是否存在、是否能读取时cat file /dev/null可以用来测试磁盘和权限问题。但凡是 GB 级生产日志请把cat从你的习惯里划掉。2. 替代工具全景less、rg、awk 的角色分工与速查2.1 查看文件用 less 不用 catless是按需加载的打开 4GB 文件不会把全部内容读进内存页缓存里放多少读多少。它的定位是浏览器你只需要上下翻页找内容而不是把整个文件灌到屏幕上。我常用的打开姿势less -G -N app.log-G关闭高亮-N显示行号。打开后G跳到文件末尾gg回到开头/ERROR向下搜索n跳下一个N跳上一个q退出线上日志动辄百万行less -N G app.log直接到末尾然后往上翻看最近的报错这是最舒服的查看方式。配合行号回头再单独定位就会方便很多。提示如果你的环境配置了LESSOPEN和lesspipeless打开大文件时可能会调用额外脚本处理语法高亮反而变慢。遇到这种情况用less -G显式关掉。2.2 全文搜索rg 和 grep 的正确用法搜索是排查日志的主战场。grep是系统标配但有几个参数必须记住grep -a ERROR app.log # -a 把二进制文件当文本处理日志里常有不可见字符 grep -n ERROR app.log # 显示行号 grep -C 5 ERROR app.log # 匹配行前后各 5 行上下文 grep -F ERROR app.log # 把模式当固定字符串不用正则更快更稳如果条件允许我强烈建议装ripgreprg。它的速度比grep快好几倍原因是多线程并行扫描、用了 SIMD 指令加速字符串匹配而且默认跳过.gitignore里的文件和二进制文件。虽然我们排查日志时经常需要-a强制读二进制但rg在普通文本日志上的优势是实打实的rg -n -a -C 5 ERROR app.logrg还有一个好处它的正则引擎基于 Rust 的regex库不存在灾难性回溯问题遇到超长单行 JSON 日志也不会把 CPU 跑满。这一点后面展开讲。2.3 字段提取与统计awk、sort、uniq 的黄金组合日志本质是文本表格用awk提取字段再统计是排查问题的核心手段。三段式经典管道awk {print $9} access.log | sort | uniq -c | sort -rn拆开看awk {print $9}按空白切分每行取第 9 个字段Nginx 默认格式里这是状态码sort让相同状态码相邻uniq -c去重并统计出现次数sort -rn按次数倒序排列一眼看到最多的这套组合能回答很多问题哪些 IP 请求最多、哪些接口 5xx 最多、哪些异常类出现频率最高。只要把取字段的部分改一下其他环节不用动。2.4 边界工具速查下面这些工具在特定场景下能救命建议记到笔记里工具典型命令解决什么问题tailtail -F app.log实时跟踪日志输出且支持 logrotate 轮转后自动切换新文件headhead -n 200 app.log看文件开头不用读全量splitsplit -l 1000000 app.log part_把 4GB 文件切成 1GB 的小块方便并行处理zcat/zless/zgrepzcat app.log.20240601.gz | grep ERROR直接读 gzip 压缩的历史日志不用先解压journalctljournalctl -u myservice --since today --no-pagersystemd 服务日志查询支持按时间过滤lnavlnav /var/log/app.log交互式日志浏览器自动识别常见格式支持 SQL 查询goaccessgoaccess access.log -o report.html --log-formatCOMBINED快速生成 Nginx 访问日志的 HTML 报告3. 六个高频排查场景的真实命令与执行细节3.1 场景一定位某个订单号的完整日志链路假设订单号是TD20240601001要追踪它在服务里的完整处理过程。先看它大概出现在哪些位置grep -a TD20240601001 app.log | head -n 30如果日志里没有 traceId只有订单号那就用上下文把它周围的内容捞出来grep -a -A 5 -B 5 TD20240601001 app.log order_trace.txt less order_trace.txt-A 5是匹配行后 5 行-B 5是前 5 行。把结果重定向到文件再看比直接输出到终端更安全尤其匹配特别多的时候终端不会卡。有一种情况要小心同一个订单号在并发场景下可能被多个线程同时处理日志行在文件里是交错排列的。只靠grep -A/-B可能把别的请求日志也带进来。这时候要抓行号grep -a -n TD20240601001 app.log | head拿到关键行的行号后用sed -n 3450,3480p app.log精确切片段再配合less精读才能理出真正的调用链。3.2 场景二Nginx 访问日志统计 5xx、TOP IP 与慢请求Nginx 默认的 access log 格式第 9 个字段是状态码第 7 个是请求路径。先看整体状态码分布awk {print $9} access.log | sort | uniq -c | sort -rn | head -20只看 5xx 请求数量awk $9 500 access.log | wc -l5xx 按请求路径聚合找出哪些接口在报错awk $9 500 {print $7} access.log | sort | uniq -c | sort -rn | headTOP 来源 IPawk {print $1} access.log | sort | uniq -c | sort -rn | head如果要统计慢请求Nginx 默认格式里没有 request_time需要自定义 log_format。我常用的格式会在最末尾加$request_timelog_format main $remote_addr - $remote_user [$time_local] $request $status $body_bytes_sent $http_referer $http_user_agent $request_time;这样$NF最后一个字段就是请求耗时秒数。取耗时超过 3 秒的请求awk $NF 3 {print $4, $7, $NF} access.log | head注意如果改了 log_format记得nginx -t且/reload之后新日志才会生效旧的 access.log 字段数不一致直接采$NF会取错。3.3 场景三从错误日志中抽取 Java 异常堆栈后端 Java 服务的日志里最烦的是堆栈跨多行光grep一个Exception出来看不到全貌。先统计哪些异常类最高频grep -a -oE java\.lang\.[A-Za-z]Exception|java\.lang\.[A-Za-z]Error app.log | sort | uniq -c | sort -rn | head-o只输出匹配的部分而不是整行这样统计出来的是异常类名而不是整行日志。定位某个具体异常第一次出现的位置grep -a -n -m 1 NullPointerException app.log把异常堆栈完整导出grep -a -A 30 Caused by: java.lang.NullPointerException app.log | head -n 80 npe_stack.txt less npe_stack.txt这里-A 30是因为 Java 堆栈通常 10 到 20 行30 行足够覆盖大部分情况多出来的行会截断堆栈。建议先导成文件再慢慢看不要反复在大文件上跑grep -A。3.4 场景四按时间窗口切出排查区间告警往往发生在某个时间点附近比如 18:00 到 18:10。很多人的第一反应是sed -n /2024-06-01 18:00/,/2024-06-01 18:10/p app.log但sed的区间匹配有个坑当它在文件里找不到合适的结束模式时会一直输出到文件末尾如果开始和结束模式在同一行也可能只输出一行。我更推荐用awk做范围比较。前提是日志行的时间戳是标准格式且位于行首比如2024-06-01 10:23:45.123 INFO ...awk {ts$1 $2} ts2024-06-01 10:00:00 ts2024-06-01 10:10:00 app.log window.log如果时间戳带方括号比如[2024-06-01 10:23:45]用 match 提取awk match($0, /\[[0-9-] [0-9:]/){tssubstr($0, RSTART1, RLENGTH-1)} ts2024-06-01 10:00:00 ts2024-06-01 10:10:00 app.log window.log切出来的window.log往往就几十 MB 了后续所有grep、awk都在这个子集上跑速度快一个数量级。这是排查大日志最值得养成的好习惯先收敛范围再深度分析。3.5 场景五压缩日志处理与多文件并行扫描生产环境的历史日志通常是 gzip 压缩的几百个压缩包堆在目录里。直接解压再 grep 会占用大量磁盘和 IO正确做法是用zcat管道zcat app.log.20240601.gz | grep ERROR或者直接zgrep -a ERROR app.log.20240601.gz。要查看压缩日志直接zless app.log.20240601.gz翻页方式和less一样。多文件并行扫描是另一个效率大杀器。假设一周 7 个日志文件都要统计 ERROR 数ls app.log.2024* | xargs -P 4 -I{} sh -c grep -c ERROR {} | xargs echo {}-P 4表示 4 个进程并行-I{}把每个文件名替换进命令。如果文件特别多超过 shell 参数上限用 find 配合 xargs 的-0find /var/log/ -name app.log.* -print0 | xargs -0 -P 4 grep -a -l ERROR-l只输出包含匹配的文件名先锁定嫌疑文件再精读避免每个文件都全量过一遍。注意-P并行度不是越高越好机械硬盘并行读反而会争抢磁盘头SSD 上可以放开到 8 甚至 16。4. 线上踩坑实录编码、管道、正则回溯与 inode 陷阱4.1 Binary file matches乱码和二进制数据grep ERROR app.log忽然冒出Binary file app.log matches很多人第一反应是文件坏了。其实这只是扫描时发现了\0空字节或不可见控制字符通常来自异常堆栈里打印的二进制内容、序列化对象、或者终端控制序列被写进了日志。解决办法是加-agrep -a ERROR app.log-a把输入当文本处理。但它也意味着输出里可能有乱码这不影响日志管道统计因为grep匹配的只是文本内容乱码只影响肉眼阅读。提示遇到这种文件先file app.log看文件类型和编码再决定是否需要转码。日志采集端最好过滤掉\0字节治标治本。4.2 正则回溯导致 CPU 飙满有一次排查线上延迟我写了一条grep -E (timeout|refused|reset)$ app.log结果 CPU 直接飙到 500%。原因是日志里恰好有一条几十 MB 的单行 JSON正则引擎在那个超长行上反复尝试回溯陷入了指数级匹配路径。对策三条能用-F固定字符串搜索就别用正则。grep -a -F Connection refused在长文本上的性能远好于正则。避免嵌套量词和连续.*比如(a)、.*.*.*这类是回溯重灾区。直接上rg。Rust 的 regex 引擎基于有限自动机对超长行和复杂模式都稳得多不会出现灾难性回溯。排查时如果命令几秒还没返回先CtrlC不要让它无限跑。生产环境日志那么大慢命令对服务器负载是雪上加霜。4.3 tail -f 与日志切割的 inode 陷阱tail -f app.log盯着看结果 logrotate 按天轮转之后日志不再输出排查了半天发现根本没看到新报错。问题出在tail -f默认跟踪的是文件描述符inode。logrotate 会把旧文件改名再在原名位置创建新文件tail -f还跟着旧的 inode 走新内容写到新文件里自然看不到。解决办法是用大写-Ftail -F app.log-F等于--followname --retry按文件名跟踪文件被轮转后会自动重新打开新文件。生产环境实时看日志请无条件使用tail -F这也是我至今没找到例外的一条规则。再补充一句journalctl -u myservice -f也是实时看日志的好方式systemd 管着的服务直接走 journald不用关心轮转问题。4.4 编码问题GBK 日志搜中文搜不到grep 订单创建成功 app.log搜不到肉眼却能在日志里看到同样的字。大概率是日志文件是 GBK 或 GB18030 编码而终端和 grep 默认按 UTF-8 解析。排查办法先确认编码file -i app.log如果确实不是 UTF-8转码再搜iconv -f GBK -t UTF-8 app.log | grep 订单创建成功更实用的建议是搜索时尽量用 ASCII 关键字错误码、订单号、IP不要依赖中文一方面避免编码问题另一方面日志规范化之后中文关键字往往不是稳定的筛选条件。如果是自己负责的应用最好在日志框架层面统一输出 UTF-8从源头解决。4.5 Argument list too long 与 awk 分隔符细节日志文件多了直接grep ERROR app.log.*可能报Argument list too long。这是 shell 的 glob 展开超过了 ARG_MAX 限制。正确做法是find /var/log -name app.log.* -print0 | xargs -0 grep -a ERROR另一个常见坑是awk取字段取错。Nginx 日志里时间带方括号状态码在引号后面默认按空格分隔时字段顺序容易偏移。如果要解析[10/Oct/2023:13:55:36 0000]里的日期可以用多个分隔符awk -F[/:] {print $3} access.log | head-F[/:]表示同时用斜杠和冒号做分隔符一行里能直接把日期和时刻拆开。日志格式不统一的时候先head -n 1看清字段结构再写awk能省很多返工时间。5. 一套完整的 502 排查思路从全局统计到根因定位5.1 一次 502 排查的完整链路用一个真实场景把前面所有命令串起来。假设傍晚 18:00 收到告警网关 502 比例上升到 3%服务 A 的日志目录里有一堆 GB 级文件。第 1 步全局评估。先看磁盘和文件大小df -h ls -lhS /var/log/app/再确认 502 到底集中在哪个入口awk {print $9} gateway_access.log | sort | uniq -c | sort -rn | head第 2 步切时间窗口。告警 18:00 到 18:10那就把服务 A 的日志先切出来awk {ts$1 $2} ts2024-06-03 17:55:00 ts2024-06-03 18:10:00 app.log window.log第 3 步在窗口内做异常类统计grep -a -oE java\.lang\.[A-Za-z]Exception|java\.lang\.[A-Za-z]Error window.log | sort | uniq -c | sort -rn | head第 4 步定位最高频异常的第一个堆栈。假设统计出来Connection refused最多grep -a -n -m 1 Connection refused window.log拿到行号后用sed -n 1230,1280p window.log精读堆栈。第 5 步关联上下游。Connection refused往往发生在服务 A 调用下游 Redis 或数据库时结合堆栈里的类名进一步搜索连接池相关日志grep -a -E jedis|getConnection|pool window.log | head第 6 步验证。重启下游服务后tail -F实时观察 A 的报错tail -F app.log每隔一段时间用grep -c Connection refused app.log对比计数看趋势是否下降。5.2 每个阶段的命令解读与判断逻辑这套流程的本质是缩小范围、收敛变量。直接对 4GB 文件跑grep不是不行但每次全量扫描都浪费 IO而且没有统计结果的指引你只是在盲找。先看全貌再挑重点时间窗口切到告警区间子集文件通常在几十 MB 量级之后的每条命令都秒回。统计异常类的时候用-oE而不是直接-E保证输出的是类名而不是整行日志uniq -c才有意义。定位堆栈用-m 1只看第一次出现避免刷屏。验证阶段用tail -F实时观察用grep -c做趋势对比不要凭感觉判断好像好了。5.3 排查日志的个人习惯总结工具齐了还得靠习惯。我自己的三条铁律先ls -lhS看文件大小和数量评估工作量。所有复杂命令先跑一个小窗口head -n 1000或awk切时间窗口验证格式再跑全量。每个阶段的结果重定向到临时文件用less精读而不是反复在终端翻屏。另外我会在~/.bashrc里常驻几个简化别名alias lgless -G alias ggrep -a --colornever自用的话再加一个小函数压缩日志里搜关键字并限制输出条数gzlog() { zgrep -a $1 $2 | head -n ${3:-50} }工具都是死的真正值钱的是先收敛再精读的思路。GB 级日志不是用来硬刚的你要做的是把它缩小到能用肉眼读完的规模再让每一行日志都为你说话。
