一场持续两秒的超时
2024年4月11日上午10:22,监控报警:支付回调接口的P99耗时从稳定期的120ms飙升到1.8s,超时率从0.02%升到0.3%。我第一反应是上游接口出问题了,但压测上游接口,响应都在50ms内。接着查Nginx访问日志、PHP-FPM slow log,CPU、MySQL负载也全部正常。
直到我随手执行了dig查了一下回调接口的域名:
dig @10.10.1.2 api.example.com +time=5 +tries=2 +noall +answer +stats
输出里一行字让我愣住:
;; Query time: 2102 msec
绕了半小时业务层排查,问题就在DNS——一个域名解析要2.1秒。这篇文章记下从dig到tcpdump的完整排查过程,以及最后怎么用数据证明根因并解决的。
方案对比:dig还是tcpdump?
排查DNS问题,常用工具就几个。我分别试过nslookup、dig、tcpdump,它们的定位完全不同。
| 工具 | 视角 | 能看什么 | 不能看什么 | 适用阶段 |
|---|---|---|---|---|
| nslookup | 客户端 | A记录、NS记录、简单查询 | 耗时统计、伪随机ID、重传行为 | 偶尔查一个记录 |
| dig | 客户端 | Query time、DNS Server、短结果、TCP回退、trace | 网络里有没有丢包、重传、谁在重传 | 定位到“解析层” |
| tcpdump | 网络包 | 每一个DNS报文、时间戳、ID、源目的IP、端口、重传 | 解析逻辑,需要自己根据协议解读 | 定位到“网络层” |
我的经验是:先用dig确认“解析到底慢不慢”,再用tcpdump抓包确认“慢在网络哪一段”。不要一上来就抓包,否则会被大量无关报文淹没。
完整排查过程
第一步:dig确认解析慢
在应用服务器(10.10.1.5)上,直接查内网DNS服务器(10.10.1.2):
dig @10.10.1.2 api.example.com +time=5 +tries=2 +noall +answer +stats
结果:
;; ANSWER SECTION:
api.example.com. 300 IN A 1.2.3.4
;; Query time: 2102 msec
;; SERVER: 10.10.1.2#53(10.10.1.2)
;; WHEN: Thu Apr 11 10:22:33 CST 2024
;; MSG SIZE rcvd: 46
答案下来了,但花了2.1秒。为了排除偶发,我连续测10次:
for i in {1..10}; do
dig @10.10.1.2 api.example.com +time=3 +tries=1 +stats | grep "Query time"
done
统计结果:最小112ms,平均823ms,最大2102ms。抖动非常大,说明不是一次性网络尖峰。
接着执行dig +trace,想看看是不是某个权威服务器慢:
dig +trace +time=3 +tries=1 api.example.com | tail -30
输出显示从根服务器到权威服务器每跳都很快,没有超过30ms的。
这就奇怪了:直连根服务器迭代解析不到30ms,为什么用内网DNS解析要823ms?问题大概率在“应用服务器到内网DNS”或“内网DNS到上游”之间的网络。
第二步:tcpdump抓包,先看应用侧
在应用服务器上抓eth0的53端口包,同时再跑一次dig:
sudo tcpdump -i eth0 -n -vv -T domain -s 0 port 53 -c 10 -w /tmp/dns_client.pcap
另一个终端执行:
dig @10.10.1.2 api.example.com
等dig结束后,Ctrl+C停止tcpdump,读取包:
sudo tcpdump -r /tmp/dns_client.pcap -n -vv -T domain
关键输出:
10:22:31.501234 IP 10.10.1.5.45123 > 10.10.1.2.53: 37210+ A? api.example.com. (30)
10:22:33.612345 IP 10.10.1.2.53 > 10.10.1.5.45123: 37210 1/0/0 A 1.2.3.4 (46)
从客户端视角看,应用服务器只在31.5秒发了一次查询,然后在33.6秒收到响应,中间没有客户端重传。也就是说,应用服务器一直在等内网DNS返回。真正慢的环节在DNS服务器那一侧。
第三步:在内网DNS服务器上抓包
登录DNS服务器(10.10.1.2),抓它和上游之间的UDP 53包。先确认这台机器上跑的是什么DNS服务:
systemctl status dnsmasq | head -5
版本是dnsmasq 2.86。接着抓包:
sudo tcpdump -i eth0 -n -vv -T domain -s 0 'udp port 53' -w /tmp/dns_server.pcap
然后在应用服务器上再执行一次dig。抓完后看包:
sudo tcpdump -r /tmp/dns_server.pcap -n -vv -T domain
这一次看到了“幕后真相”:
10:22:31.512345 IP 10.10.1.2.56789 > 223.5.5.5.53: 37210+ A? api.example.com. (30)
10:22:31.738901 IP 10.10.1.2.56789 > 223.5.5.5.53: 37210+ A? api.example.com. (30)
10:22:31.964512 IP 10.10.1.2.56789 > 223.5.5.5.53: 37210+ A? api.example.com. (30)
10:22:33.609876 IP 223.5.5.5.53 > 10.10.1.2.56789: 37210 1/0/0 A 1.2.3.4 (46)
同样的DNS ID 37210,DNS服务器在31.5、31.7、31.9分别向上游223.5.5.5发了三次完全相同的查询,直到33.6才收到响应。间隔约220ms一次重传,最后耗时2.1秒。
结论很清晰:应用服务器到内网DNS没有问题,内网DNS到上游223.5.5.5这一段丢包,或者上游处理超时。内网DNS收不到响应,就一直重试,客户端只能干等。
第四步:用Python脚本从pcap里统计RTT
为了量化丢包率,我写了一个Python脚本,直接分析抓包文件,统计每个DNS请求的RTT和重传次数。需要先装依赖:
pip3 install dpkt
脚本内容:
#!/usr/bin/env python3
# extract_dns_rtt.py - 从pcap中提取DNS查询/响应对,计算RTT
# 用法: python3 extract_dns_rtt.py /tmp/dns_server.pcap
import sys
import dpkt
pcap = dpkt.pcap.Reader(open(sys.argv[1], 'rb'))
queries = {}
retransmit_count = 0
rtts = []
for ts, buf in pcap:
try:
eth = dpkt.ethernet.Ethernet(buf)
if not hasattr(eth, 'ip') or not hasattr(eth.ip, 'udp'):
continue
udp = eth.ip.udp
if udp.sport != 53 and udp.dport != 53:
continue
dns = dpkt.dns.DNS(udp.data)
except Exception:
continue
# 同一请求用 (dns.id, 源IP, 目标IP, 源端口) 区分
key = (dns.id, eth.ip.saddr, eth.ip.daddr, udp.sport)
if dns.qr == 0:
if key in queries:
retransmit_count += 1
queries[key] = ts
elif dns.qr == 1:
if key in queries:
rtt = (ts - queries[key]) * 1000
rtts.append(rtt)
print(f"DNS ID {dns.id} RTT {rtt:.1f} ms")
del queries[key]
if rtts:
print(f"\n总共 {len(rtts)} 个响应")
print(f"平均RTT: {sum(rtts)/len(rtts):.1f} ms")
print(f"最大RTT: {max(rtts):.1f} ms")
print(f"重传次数: {retransmit_count}")
else:
print("没有匹配到响应")
运行结果:
python3 extract_dns_rtt.py /tmp/dns_server.pcap
DNS ID 37210 RTT 2097.5 ms
总共 1 个响应
平均RTT: 2097.5 ms
最大RTT: 2097.5 ms
重传次数: 2
一次查询重传了2次,最终RTT 2.1秒。
第五步:验证修复,换掉上游
根因是内网DNS上游223.5.5.5不稳定。我在应用服务器上临时把resolv.conf指到223.5.5.5做对比测试:
sudo bash -c 'echo "nameserver 223.5.5.5" > /etc/resolv.conf'
然后再次循环查询10次:
for i in {1..10}; do
dig @223.5.5.5 api.example.com +time=3 +tries=1 +stats | grep "Query time"
done
结果全部在20ms以内。说明应用服务器本身到223.5.5.5的网络是通的。
最终修复方案是:在内网DNS服务器上把上游dnsmasq的resolver切换到集群内稳定的缓存节点,同时给dnsmasq开启--no-resolv并指定server=/example.com/10.10.1.10条件转发。业务无感,解析恢复正常。
效果数据
修复前后对比如下:
| 指标 | 修复前 | 修复后 |
|---|---|---|
| dns解析平均耗时(10次) | 823ms | 12ms |
| dns解析最大耗时 | 2102ms | 19ms |
| UDP重传次数 | 2次/请求 | 0次 |
| 支付回调接口P99 | 1.8s | 120ms |
| 接口超时率 | 0.3% | 0 |
连续观察24小时没有反弹。一次业务故障,最后通过改DNS配置解决。
原理:为什么DNS会耗时2秒?
DNS查询默认走UDP 53端口。请求报文里有一个16位的Transaction ID,响应必须携带相同ID。如果客户端没有在超时时间内收到响应,就会重发相同ID的请求。重传间隔由解析器决定:glibc默认超时5秒、重试2次;dnsmasq对上游的默认重试间隔更短。我们这次遇到的,是dnsmasq向上游223.5.5.5发的查询没有及时收到响应,于是220ms后重传,总共重传了2次,等了2.1秒。
抓包时需要注意:客户端重传和DNS服务器重传是两个不同层级。应用服务器上抓到的是“客户端到DNS服务器”的包,如果看到客户端没有重传,不代表网络没有问题。要登录DNS服务器继续抓“DNS服务器到上游”的包,才能看到真正的丢包点。
另外,如果DNS响应报文超过512字节,且UDP包里的TC标志被置为1,客户端会改用TCP 53端口重新查询,同样会增加一次RTT。排查时tcpdump过滤条件不要只写udp port 53,应该写port 53,把TCP也带上。
避坑指南
下面几个坑是我实际踩过的,写出来是希望你别再走一遍。
坑1:直接改/etc/resolv.conf,重启后会被还原
Ubuntu 22.04上,/etc/resolv.conf是软链到/run/systemd/resolve/stub-resolv.conf的。直接echo nameserver ... > /etc/resolv.conf虽然当时有效,但网络服务重启或被systemd-resolved接管后会被覆盖。先看一眼:
ls -l /etc/resolv.conf
正确做法是:
resolvectl dns eth0 223.5.5.5
resolvectl domain eth0 example.com
或者修改/etc/systemd/resolved.conf之后systemctl restart systemd-resolved。
坑2:tcpdump过滤条件写太宽,抓了一堆ARP
一开始我用tcpdump -i eth0 -n -s 0 -vv port 53,结果抓了一大堆ARP包和DNS反向解析包,因为-n没加时,tcpdump会对IP做反向解析,自己又去发DNS查询,把你真正要抓的包冲散。正确姿势是:
sudo tcpdump -i eth0 -n -vv -T domain -s 0 port 53
加上-T domain可以自动解出DNS name。不要加-p(除非你想关闭混杂模式)。
坑3:dig +trace正常不代表系统解析正常
dig +trace从根服务器开始迭代查询,完全绕过了本机/etc/resolv.conf配置的DNS服务器。如果问题出在内网DNS缓存污染或转发链路,+trace会显示一切正常。判断系统解析慢,必须用dig @你配置的nameserver来验证。
坑4:Docker容器内抓包看不到全部DNS流量
Docker默认给容器一个内嵌DNS服务器(127.0.0.11),容器内应用发出的DNS查询会先到127.0.0.11,再由Docker的DNS模块转发到宿主机配置的DNS。在容器内tcpdump -i eth0 port 53只能看到和127.0.0.11的交互?不对,实际上容器内ets的port53看不到包,因为Docker的DNS是用户态进程,不经过容器eth0的TCP/IP栈?准确说,127.0.0.11是Docker内置的DNS server进程,容器内tcpdump看不到它。要抓Docker DNS转发出去的包,需要在宿主机上抓veth网卡,或者直接抓docker0。总之,容器内抓包结果会让你误判“没有DNS流量”。
坑5:抓包文件太大,磁盘打满
生产环境上抓包,不加限制可能一晚上写出几十GB。建议用-c限制包数量,或者用-G轮转:
sudo tcpdump -i eth0 -n -s 0 -G 60 -w /tmp/dns_%Y%m%d_%H%M%S.pcap port 53
上面的-G 60表示每60秒生成一个新文件。排查完成立刻删掉临时文件。
坑6:把公网DNS直接写死在业务机器上
临时验证时可以改resolv.conf为223.5.5.5,但长期这种做法会让内网域名解析失败。企业内网通常有私有域名,必须在DNS服务器上做条件转发。我最后的方案不是让应用直连公网DNS,而是把内网DNS的上游换掉,保持业务配置不动。
小结
这次排查从业务日志、Nginx、PHP-FPM一路翻到网络层,最后用dig锁定了“系统解析慢”,再用tcpdump定位到“DNS服务器到上游丢包”,整个过程不到半小时。工具不在多,关键是要知道每一层能回答什么问题。dig告诉你是什么,tcpdump告诉你为什么。
如果你也遇到类似偶发超时,先别急着调代码,先跑一个dig看Query time,超过100ms就要警惕了。