TT Lab
开始
学习 学习路径 课程

从日志里找原因

收集端收到的行比发出的少

在 TT Lab 中继续学习

目标

把采集器收到的行与发送方的计数器进行比较来统计丢失,折叠重复,求出到达延迟的分布,并用数字查明在截止时间统计造成的少计,以及重启造成的错觉。

为什么重要

日志为空时,“没送到”和“没有事情发生”结论截然相反,却无法只靠文件区分。区分二者的只有发送方所附的单调递增序号。但这个序号在进程重启后也会从 1 重新开始,所以如果不与启动标识符绑在一起,重启前后就会被看成重复,而重启之后的丢失会被遮住。接收的顺序不是发生的顺序,这一点同样重要——在截止时间统计,还没到达的行就会漏掉,几天后同样的查询就会给出不同的数字。

步骤

  1. 创建并运行 /root/gap/gen_gap.py,在 /root/gap/raw/ 下生成 collector.ndjson 和 sender_state.json。
  2. 在 /root/gap/tally.json 中写下把收到的行和发送的行进行比较后统计出的结果。
  3. 在 /root/gap/missing.json 中把缺失的序号按区间归并后写下。
  4. 在 /root/gap/dedup.ndjson 中写下折叠重复之后的结果。
  5. 在 /root/gap/delay.json 中写下到达延迟的分布。
  6. 在 /root/gap/cutoff.json 中写下在截止时间统计造成的少计。
  7. 在 /root/gap/reboot.json 中写下重启对统计造成的影响。
  8. 在 /root/gap/gap_report.md 中分四节留下报告。

参考

把收到的和发送的一起拿到手

创建并运行 /root/gap/gen_gap.py,生成 /root/gap/raw/collector.ndjson(2311 行,其中含 61 条重复)和 /root/gap/raw/sender_state.json(4 个流,发送行数合计 2400)。

采集器文件按到达顺序(observed_ts)堆积。没有发送方的计数器,就永远不知道缺了什么,所以要把两者一起做出来。有一台主机在中途重启了,所以(host, boot_id)的组合数必须比主机数多一个。

比较收到的行与发送的行

在 /root/gap/tally.json 中写入 lines_in_file、unique_records、duplicate_lines、sent_total、missing_total、loss_rate。

文件的行数不是事件的数量。先折叠同一行到达两次的情况,才能得到“收到的”,再用发送方的计数器减去它,才得到“没到的”。是否同一行,要按(host, boot_id, seq)来判断。

把缺失的序号按区间归并

在 /root/gap/missing.json 中,为每个流把缺失的序号归并成连续的区间,以 host、boot_id、first、last、count 写下。按(host, boot_id, first)升序排列。

零星的一条条丢失,和 50 条成片缺失,原因是不同的。所以不要只统计个数,而要按区间归并。对每个流,从发送方告知的 first_seq 到 last_seq 扫描一遍,只要没有收到的序号连续出现,就不断延长区间。

折叠重传造成的重复

在 /root/gap/dedup.ndjson 中,把折叠重复之后的记录以 host、boot_id、seq、event_ts、observed_ts、msg 的形式,按(host, boot_id, seq)升序写下。同一行到达多次时,保留最先到达的那条。

在 at-least-once 采集器中同一行到达两次,不是故障而是设计。需要的是“把什么视为同一行”的定义。如果用内容指纹来折叠,连真正完全相同的两个事件也会变成一个,所以有序号时就用序号。

求出到达延迟的分布

在 /root/gap/delay.json 中写入 count、p50_sec、p95_sec、max_sec、over_60s、worst(host、boot_id、seq、delay_sec)。延迟是 observed_ts 减去 event_ts,向下取整为以秒为单位的整数。

接收的顺序不是发生的顺序。之所以要把两个时间分别留下,原因就在这里,而两者之差就是采集路径的健康状况。平均值用处不大——如果大多数是几秒,一部分是几分钟,平均值就什么也解释不了。

如果在截止时间统计,会漏掉多少

在 /root/gap/cutoff.json 中写入 cutoff_ts、event_before_cutoff、observed_before_cutoff、late_arrivals、undercount_rate。截止时间是 2026-05-20T03:20:00Z,比较用的是小于。

同样的查询,在午夜刚过和三天后运行,数字不同。这不是 bug,而是迟到。事件时间在截止之前、到达却在截止之后的记录,正是当时没能统计到的,而它们的比例说明了应该留出多少截止宽限。

重启让丢失和重复互相颠倒

在 /root/gap/reboot.json 中写入 hosts_with_multiple_boots、boots_by_host、false_duplicates、missing_with_boot、missing_without_boot。

进程重新启动后,序号会从 1 重新开始。如果去掉启动标识符来统计,重启前后的相同序号会被看成重复,而重启之后缺失的序号会被重启之前的记录遮住,看起来并没有丢失。把两个数字并排列出,展示它们的差别。

把要请求的内容写成文字

在 /root/gap/gap_report.md 中分四节书写:## 무엇이 얼마나 빠졌나、## 중복과 늦은 도착、## 왜 숫자가 달라지나、## 무엇을 요청할 것인가(韩文,依次意为“什么缺失了多少”“重复与迟到”“为什么数字会变”“要请求什么”)。必须以数字形式包含丢失数量、重复行数、延迟 p95、截止之前没收到的数量、忽略 boot_id 时的丢失数量。

这份报告的最后一节,实际上价值最大。因为从下一批起要求对方附上什么,决定了下一次调查的难度。请用前面的数字来支撑,为什么要同时要求发送序号和启动标识符、事件时间和观测时间。