有一个两百多行的 access.log 分析脚本,我用了两年,最近才被人点醒:它统计出来的「平均响应时间」和 Nginx 自己算的对不上,而且随着日志变大,脚本越来越慢——从 3 秒变成 40 秒。查下去两个原因:一是它把整个日志 readlines() 进内存再遍历,二是它每次都用 .index() 在一个几十万元素的列表里做线性查找。
这类脚本在个人站长手里非常普遍:每天跑一次,看一下 PV、看一下 5xx 数量、看一下哪个 IP 请求最多。量小的时候什么都不出问题,量一上来就是灾难。这篇把几个真正有效的优化手段按「收益从大到小」讲一遍,都是能直接套用的。
先量化,再优化
不看数字就改代码是浪费生命。三个数字就够定位瓶颈在哪一层:
# 日志有多大、多少行
ls -lh /var/log/nginx/access.log
wc -l /var/log/nginx/access.log
# 脚本跑到哪里去了
time python3 analyze.py /var/log/nginx/access.log
# 热点在哪
python3 -m cProfile -s cumtime analyze.py /var/log/nginx/access.log | head -30cProfile 的 cumtime 是累计耗时(包含子调用),tottime 是函数自身耗时。经验上:如果 cumtime 前几名是 readlines、split、list.append 这类,问题在数据量;如果是 list.index、in、字符串拼接,问题在数据结构。两种问题的解法完全不同。
还有一个更原始但很有效的办法:先只读前 1 万行跑一遍,再读前 10 万行跑一遍。耗时如果基本不变,说明瓶颈不在解析而在后处理;如果线性增长,瓶颈在读取和解析。
第一层:别把整个文件读进内存
readlines() 和 f.readlines() 会把所有行变成字符串对象。一行 200 字节的日志,100 万行在 Python 里大约占 250MB 到 350MB(每个 str 对象本身有几十字节开销)。在只有 2G 内存的小机器上,这一下就能触发 OOM 或者大量 swap,脚本跑得比谁都慢。
正确写法是直接迭代文件对象,Python 会按行惰性读取,内存占用恒定:
with open(path, encoding='utf-8', errors='replace') as f:
for line in f:
parts = line.split(' ')
# 处理注意两个细节。errors='replace' 是必须的,因为 UA 里混进非法 UTF-8 字节是常态,不加的话整个脚本会在某一行崩掉,而且崩在一个你根本没法复现的位置。open 里不指定 newline,让它做通用换行处理,能兼容 Windows 上传的旧日志。
用 split(' ') 而不是不带参数的 split(),是因为日志字段之间是单个空格,而无参 split() 会把连续空格当分隔符并丢弃空字段,遇到 UA 里有连续空格时字段会错位。这一点在解析 combined 格式时特别致命。
第二层:把 .index() 和 in 换成字典
这是最常见的性能杀手,而且它的表现形式很像「代码没错只是慢」。例如要统计每个状态码的数量,很多人这么写:
codes = []
counts = []
for line in f:
status = line.split(' ')[8]
if status in codes: # O(n) 线性查找
i = codes.index(status) # 又一次 O(n)
counts[i] += 1
else:
codes.append(status)
counts.append(1)状态码只有几十种,所以这段代码看着还行。但如果统计的是 URL、是 IP、是 User-Agent,种类上万,复杂度立刻变成 O(n²)。写法换成 collections.Counter 或者 defaultdict(int),一次遍历搞定:
from collections import Counter, defaultdict
status_counter = Counter()
ip_counter = Counter()
ua_counter = Counter()
for line in f:
# combined: ip - - [time] "req" status bytes "ref" "ua"
head, _, ua = line.rpartition('" ')
fields = head.split(' ')
if len(fields) < 10:
continue
ip_counter[fields[0]] += 1
status_counter[fields[8]] += 1
ua_counter[ua.rstrip('"\n')] += 1Counter 底层是字典加 get,一次插入是摊销 O(1)。在 50 万行的日志上,这段代码通常比前面的写法快三到五倍,而且内存占用更低(不需要维护两个平行列表)。
顺带说一个容易被忽略的点:Counter.most_common(10) 需要排序全部键,键多的时候也是一笔开销。只要 top10 的话,用 heapq.nlargest 在字典上取更快,尤其在键有几十万个的时候差别明显。
第三层:用 re 拆字段,或者干脆不用 re
用正则解析日志是很多人第一反应,写起来清晰,但性能上是有代价的。一个复杂的正则在每行上跑一次,在几十万行上就是几秒。两个思路可以绕开:
思路一:用 split('"') 切分带引号的字段。 combined 格式里,请求行、Referer、UA 都带引号,其余字段不带。以引号切分能天然避开「UA 里有空格」这个坑:
parts = line.split('"')
# parts[0] = '1.2.3.4 - - [10/Oct/2026:13:55:36 +0800] '
# parts[1] = 'GET /path HTTP/1.1'
# parts[2] = ' 200 1234 '
# parts[3] = '-'
# parts[4] = ' Mozilla/5.0 ...'
# parts[5] = '\n'
status = parts[2].split()[0] if len(parts) > 2 else '-'思路二:只在需要时用正则,并把编译放到循环外。 如果一定要用正则,务必 re.compile 一次、循环里用 pattern.search,不要在循环里调用 re.match(pattern, ...)——后者每次都会走一遍正则编译缓存查找,虽然命中缓存不算慢,但累加起来很可观。另外把 ^ 锚定和字段顺序写死,别用 .*? 这种回溯炸弹。
思路三:如果日志是自定义格式,干脆换格式。 这一条收益最大。把 Nginx 的 log_format 改成用固定分隔符(比如 | 或 tab),并把 UA 里的分隔符替换掉,解析就变成一次 split():
log_format tsv '$remote_addr\t$time_iso8601\t$request_method\t'
'$uri\t$status\t$body_bytes_sent\t$request_time\t'
'$upstream_response_time\t$request_id';改成 tab 分隔之后,同一份日志的解析时间能砍掉一半以上。代价是改格式后旧日志和新日志字段数不一致,脚本里要么加判断,要么按日期分文件处理——这一点必须记住,否则会得到一堆字段错位的垃圾统计。
第四层:只算你真正要的指标
脚本慢往往不是因为解析慢,而是因为它算了一堆没人看的东西。我那个脚本每天算:每个 URL 的请求数、每个 IP 的请求数、每个 UA 的请求数、每个状态码的字节数、每个小时的平均耗时……听着很全面,但实际每天只看三行输出。
优化的办法是 单遍遍历,多指标同时累加。不要为了求平均响应时间把 request_time 全部存进列表再 sum()/len()——那是最占内存的写法。改成累加 sum 和 count 两个数,内存恒定。只有需要算分位数(P95、P99)时才不得不存样本,这时候可以用蓄水池抽样或者按整数毫秒做直方图:
from collections import Counter
# 按毫秒取整做直方图,最多几百个桶
hist = Counter()
total = 0
cnt = 0
for line in f:
rt = float(parts[6])
hist[int(rt * 1000)] += 1
total += rt
cnt += 1
# 从直方图里求 P95,不用存全部样本
target = cnt * 0.95
acc = 0
for ms in sorted(hist):
acc += hist[ms]
if acc >= target:
print('P95 =', ms, 'ms')
break直方图还有个额外好处:可以直接画分布,看是「整体慢」还是「长尾慢」。平均值 80ms、P95 是 3 秒,和平均值 200ms、P95 是 250ms,对站长来说是完全不同的两件事。
第五层:让 shell 干它擅长的事
如果只是「统计某个状态码有多少行」这种简单需求,别写 Python。grep 是 C 写的、多线程化得很成熟,速度通常比 Python 快一个数量级:
# 5xx 数量
grep -c ' 5[0-9][0-9] ' /var/log/nginx/access.log
# 访问最多的 20 个 IP
awk '{print $1}' access.log | sort | uniq -c | sort -rn | head -20
# 慢请求(request_time > 1s),前提是自定义格式把 rt 放在第 7 列
awk -F'\t' '$7 > 1 {print}' access.log | wc -l组合使用要注意一个坑:grep -c 在没有匹配时返回 1(退出码),如果脚本里有 set -e,整个脚本会静默中断,看起来像是「没输出」。正确做法是 grep -c ... || true,或者干脆不用 set -e,改为显式检查每个命令的返回值。
还有一个很实用的选择:如果日志量已经大到要每天处理几个 GB,或者需要交互式分析(按 IP 筛选、看时间分布、查某个 URL 的历史),那不该优化脚本,该换工具。GoAccess 能直接解析 combined 格式并生成 HTML 报告,配 --real-time-html 还能实时刷新;lnav 是终端里的日志浏览器,支持 SQL 查询;日志进了 journald 或 ClickHouse 之后更是另一套玩法。判断标准很简单:如果你发现自己在手写聚合逻辑,就说明该换工具了。
一个完整的改造实例
回到开头那个脚本。改造前后的对比,可以看成一个模板:
| 环节 | 改造前 | 改造后 | 耗时变化(50 万行) |
|---|---|---|---|
| 读文件 | readlines() 全部进内存 | 逐行迭代 | 3.2s → 0.9s |
| 拆字段 | 复杂正则 | split('"') + split() | 5.1s → 1.4s |
| 计数 | 两个 list + index() | Counter | 12.6s → 1.1s |
| P95 | 存全部样本再排序 | 毫秒直方图 | 0.8s → 0.05s |
| 内存峰值 | 310MB | 18MB | — |
| 总耗时 | 约 41s | 约 2.1s | 约 20 倍 |
其中贡献最大的不是任何「高级技巧」,而是那个 list.index()。这也说明一个规律:日志脚本的瓶颈九成在数据结构和 IO 模式上,跟 Python 本身快不快关系不大。 在没换语言、没上多进程的情况下,二十倍是能拿到的。
收尾:三个习惯
第一,脚本跑之前先看 wc -l 和 ls -lh,对量级有个概念。一百万行和一万行该用完全不同的写法。
第二,所有「读日志」的脚本都必须能处理已经被 logrotate 轮转过的文件。日志正在写的时候被压缩或者删除,脚本不会报错,只是安静地少读一段。gzip -dc access.log.1.gz 配合 zcat、或者读 .1 而不是当前文件,能避开这个问题——这也是为什么定时统计脚本一般放在凌晨、读已经轮转完的前一天文件。
第三,把统计结果落成 CSV,每天一行,而不是只看屏幕输出。日志分析的真正价值是趋势:今天 5xx 有 30 条不重要,三个月前是 0 条、现在每天 30 条才重要。没有历史数据的日志分析,等于每天都从零开始猜。