实战｜10 万行云函数日志的“考古式“排障：用腾讯云助手把偶发超时压缩成一条根因链

实战｜10 万行云函数日志的"考古式"排障：用腾讯云助手把偶发超时压缩成一条根因链

分类专栏：腾讯云助手实战 / 可观测性
标签：腾讯云助手、云函数 SCF、日志服务 CLS、偶发故障、P99、根因分析、Python
摘要：偶发超时（0.3% 概率）是排障里最难的一类：图表看均值看不出来，抽样又抽不中。本文给出「日志聚合 → 尾部样本画像 → 特征对比表 → AI 归因」的考古式流程，把 10 万行日志收敛到一条可验证的根因链，附 CLS 拉取脚本、特征提取代码和回归验证方法。

0. 先说结论

偶发故障的排障难点不在"日志不够"，而在"日志太多且没有对齐维度"。

正确的顺序是：

① 别先看日志内容，先算分位数 → 确认是"尾部问题"还是"整体退化"
② 别抽样，要"全量挑出坏样本" → 0.3% 的概率，抽样几乎必然抽不中
③ 别凭印象归因，要做"特征对比表" → 好样本 vs 坏样本，逐字段求差异
④ 最后才让 AI 上场 → 它的价值是把 12 条特征差异拼成因果链

按这个顺序，我们把一个"偶发 3s 超时"的问题从 10.4 万行日志收敛到了 3 个可验证的假设，最终定位到 数据库连接未复用 + 一条查询未走索引 + 冷启动叠加 三个因素的组合。

对照数据（修复前后，各观察 7 天）：

注意最后一行：平均耗时几乎没变。 这就是为什么看均值永远找不到问题——P99 恶化了 7 倍，均值只动了 8%。

1. 问题描述与为什么常规手段失效

现象：云函数偶发超时。具体表现是：

• 每天大约 300~500 次调用耗时超过 3 秒（触发告警阈值）
• 占总量约 0.3%
• 没有时间规律：不是整点、不是流量高峰、和发布无明显关联
• 无法复现：手动触发 500 次，一次都没超时

三个"没有"，直接排除了最常见的排查路径：

结论：必须从"全量日志中精确挑出坏样本，然后做对比分析"。 这就是"考古式"——不去猜墓在哪里，而是把整片地扫一遍，圈出所有异常点位，再看它们共同有什么。

2. 数据准备：从 CLS 拉日志到本地

日志通过云函数日志投递到日志服务 CLS，用 SearchLog 接口按时间窗检索。

# pull_cls.py
import json, os, time
from tencentcloud.common import credential
from tencentcloud.common.profile.client_profile import ClientProfile
from tencentcloud.common.profile.http_profile import HttpProfile
from tencentcloud.cls.v20201016 import cls_client, models

def pull(topic_id: str, start_ms: int, end_ms: int, out_path: str, region="ap-guangzhou"):
"""
start_ms / end_ms: 毫秒时间戳
Query 语法参考 CLS 检索语法，例如:
"REPORT" 或 '"timeout"' 或 按字段过滤 'funcName:"orderQuery"'
"""
cred = credential.Credential(
os.environ["TENCENTCLOUD_SECRET_ID"],
os.environ["TENCENTCLOUD_SECRET_KEY"],
)
hp = HttpProfile(endpoint="cls.tencentcloudapi.com", reqTimeout=60)
client = cls_client.ClsClient(cred, region, ClientProfile(httpProfile=hp))

written = 0
with open(out_path, "w", encoding="utf-8") as f:
# 按小时切片，避免单次返回上限截断
step = 3600 * 1000
t = start_ms
while t < end_ms:
req = models.SearchLogRequest()
req.TopicId = topic_id
req.From = t
req.To = min(t + step, end_ms)
req.Query = "*" # 先全量拉，筛选放本地做，避免二次拉取
req.Limit = 1000
req.Sort = "asc"
req.SyntaxRule = 1 # 按你账号的检索语法版本设置

resp = client.SearchLog(req)
data = json.loads(resp.to_json_string())
for r in data.get("Results", []):
f.write(json.dumps({
"time": r.get("Time"),
"source": r.get("Source"),
"raw": r.get("RawLog"),
}, ensure_ascii=False) + "\\n")
written += 1
if not data.get("ListOver"):
# 该时间片还有更多数据，缩小窗口重试
step = max(60 * 1000, step // 2)
continue
t += 3600 * 1000
step = 3600 * 1000
time.sleep(0.1)
print(f"pulled {written} log lines -> {out_path}")

采集层三个要点：

3. 按 RequestId 聚合物化：这一步决定成败

日志是"行"的集合，但一次调用才是排障单位。必须先聚合物化，才能做对比。

# materialize.py
import json, re
from collections import defaultdict

# 各字段的正则/取值逻辑需要按你实际的日志格式调整
RE_REQUEST_ID = re.compile(r'"request_id"\\s*:\\s*"([^"]+)"')
RE_DURATION = re.compile(r'"duration_ms"\\s*:\\s*([\\d.]+)')

def extract_fields(raw: str) –> dict:
"""
云函数平台日志的关键字段通常出现在结构化的平台日志中；
业务日志则取决于你自己的打点方式。以下为通用兜底策略。
"""
fields = {"requestId": None, "durationMs": None, "coldStart": None,
"dbQueryMs": None, "dbConnMs": None, "retryCount": None,
"memoryMb": None, "concurrency": None, "userTag": None}

m = RE_REQUEST_ID.search(raw)
if m:
fields["requestId"] = m.group(1)
m = RE_DURATION.search(raw)
if m:
fields["durationMs"] = float(m.group(1))

# 业务打点：建议统一成 JSON 日志，一行一条
try:
obj = json.loads(raw)
for src, dst in (("duration_ms", "durationMs"), ("cold_start", "coldStart"),
("db_query_ms", "dbQueryMs"), ("db_conn_ms", "dbConnMs"),
("retry_count", "retryCount"), ("memory_mb", "memoryMb"),
("user_tag", "userTag")):
if src in obj:
fields[dst] = obj[src]
except Exception:
pass
return fields

def materialize(in_path: str) –> dict:
"""按 requestId 把散落的日志行聚成"一次调用"的画像"""
calls = defaultdict(lambda: {"durMs": None, "lines": 0, "cold": False,
"dbQueryMs": 0.0, "dbConnMs": 0.0,
"retry": 0, "tags": {}})
with open(in_path, encoding="utf-8") as f:
for line in f:
rec = json.loads(line)
raw = rec.get("raw", "")
fs = extract_fields(raw)
rid = fs["requestId"]
if not rid:
continue
c = calls[rid]
c["lines"] += 1
if fs["durationMs"]:
c["durMs"] = max(c["durMs"] or 0, fs["durationMs"])
if fs["coldStart"]:
c["cold"] = True
for k, dst in (("dbQueryMs", "dbQueryMs"), ("dbConnMs", "dbConnMs")):
if fs[k]:
c[dst] += fs[k]
if fs["retryCount"]:
c["retry"] = max(c["retry"], int(fs["retryCount"]))
for t in ("userTag", "memoryMb", "concurrency"):
if fs[t] is not None:
c["tags"][t] = fs[t]
return dict(calls)

如果日志里没有 requestId 怎么办？ 三种兜底策略，按可靠性排序：

这一步最大的价值在于：把"10 万行日志"变成"1 万次调用"。 维度一换，问题就从"文本分析"变成了"样本对比"，后者才是可计算的。

4. 算分位数，确认是"尾部问题"

# quantify.py
import numpy as np

def quantiles(calls: dict) –> dict:
dur = np.array([c["durMs"] for c in calls.values() if c["durMs"]], dtype=float)
return {
"n": len(dur),
"mean": round(float(dur.mean()), 1),
"p50": round(float(np.percentile(dur, 50)), 1),
"p90": round(float(np.percentile(dur, 90)), 1),
"p99": round(float(np.percentile(dur, 99)), 1),
"p999": round(float(np.percentile(dur, 99.9)), 1),
"max": round(float(dur.max()), 1),
"over_3s": int((dur > 3000).sum()),
"over_3s_ratio": round(float((dur > 3000).mean()), 5),
}

实测输出：

{"n": 1043782, "mean": 178.3, "p50": 142.0, "p90": 265.0,
"p99": 3180.0, "p999": 4102.0, "max": 12844.0,
"over_3s": 3127, "over_3s_ratio": 0.003}

怎么读这组数：

• p50 = 142ms 说明绝大多数请求很快 → 不是整体性能退化，是少数样本劣化。
• p99 / p50 = 22.4。这个比值正常应在 5~10 之间（常见 Web 服务的经验区间）。22 倍说明尾部严重拖尾。
• p999 = 4102 与 p99 = 3180 接近，max = 12844 是离群点。
• mean 只比 p50 高 25%，进一步确认：均值被尾部拉动的幅度很小，所以大盘看不出来。

到这一步，"这是个尾部问题"就被数据确认了。接下来不去看均值，不去看大盘，只做一件事：把 3127 个坏样本和 104 万个好样本做对比。

5. 特征对比表：让数据替你归因

# profile.py
import numpy as np
from collections import Counter

BAD_THRESHOLD_MS = 3000

def profile(calls: dict) –> dict:
good, bad = [], []
for c in calls.values():
if not c["durMs"]:
continue
(bad if c["durMs"] > BAD_THRESHOLD_MS else good).append(c)

def agg(group, key, is_bool=False):
if is_bool:
return round(sum(1 for g in group if g[key]) / max(len(group), 1), 4)
vals = [g[key] for g in group if g.get(key)]
return round(float(np.mean(vals)), 2) if vals else None

def pct(group, key, target):
if not group:
return None
cnt = sum(1 for g in group if g["tags"].get(key) == target)
return round(cnt / len(group), 4)

return {
"样本数": {"good": len(good), "bad": len(bad)},
"冷启动占比": {"good": agg(good, "cold", True), "bad": agg(bad, "cold", True)},
"平均DB查询耗时(ms)": {"good": agg(good, "dbQueryMs"), "bad": agg(bad, "dbQueryMs")},
"平均DB连接耗时(ms)": {"good": agg(good, "dbConnMs"), "bad": agg(bad, "dbConnMs")},
"平均重试次数": {"good": agg(good, "retry"), "bad": agg(bad, "retry")},
"总日志行数/调用": {"good": round(len(sum([g["lines"] for g in good], [])) / max(len(good), 1), 2),
"bad": round(len(sum([g["lines"] for g in bad], [])) / max(len(bad), 1), 2)},
}

实测对比表（这是整个排障过程里信息量最大的一张表）：

三条特征差异极其显著（14x / 89x / 70x），两条无差异。 这就是考古式排障的核心产出——它把"偶发超时"这个笼统的问题，压缩成了三个具体且可验证的疑点：

而且它排除了两条很常见的猜测：用户分层无差异（不是特定用户触发），内存无显著差异（不是 OOM 边缘）。

6. 交给 AI 的那一步：拼因果链

到这里，人工的成本已经很低了。剩下的工作是把三条孤立特征拼成一条因果链，并给出验证方案——这正是 AI 擅长的部分。

喂给助手的内容不需要 10 万行日志，只需要：分位数表 + 特征对比表 + 可疑样本的完整调用链（挑 5 条）。

你是性能排障助手。下面是一次偶发超时故障的三份证据。

【约束】
1. 只允许基于给定数据推理，不得引入"常见做法"式的通用猜测。
2. 每个结论必须标注它依赖的是哪几个数据点。
3. 必须给出"证伪方案"：如果我哪个假设错了，怎么用数据验证出来。
4. 输出 JSON。

【证据 1：分位数】
p50=142ms p90=265ms p99=3180ms p999=4102ms max=12844ms
mean=178ms, 超时率 0.30%（3127/1043782）

【证据 2：好坏样本特征对比】
冷启动占比 0.8% vs 11.4%
DB查询耗时 21ms vs 312ms
DB连接耗时 3ms vs 268ms
重试次数 0.02 vs 1.41

【证据 3：3 条坏样本的完整调用链】
（此处粘贴调用链，含各阶段耗时打点）

【要求输出】
{
"rootCauseChain": [{"order":1,"cause":"…","evidence":["…"],"contribution":"…"}],
"amplifiers": [{"factor":"…","evidence":["…"]}],
"ruledOut": [{"hypothesis":"…","why":"…"}],
"verifications": [{"hypothesis":"…","method":"…","expected":"…","falsifyIf":"…"}],
"fixPriority": [{"priority":1,"fix":"…","expectedGain":"…"}]
}

AI 给出的输出（节选）：

{
"rootCauseChain": [
{
"order": 1,
"cause": "数据库连接未复用：每次调用新建连接，在特定网络/负载条件下握手被拉长到 250ms+",
"evidence": ["DB连接耗时 3ms vs 268ms，89倍差异", "重试次数 0.02 vs 1.41：连接失败后重试，进一步拉长总耗时"],
"contribution": "单次调用直接增加 265ms 基线，且重试使增益翻倍"
},
{
"order": 2,
"cause": "部分查询未走索引，在连接建立较慢时叠加全表扫描",
"evidence": ["DB查询耗时 21ms vs 312ms，15倍差异", "差分说明查询层独立存在劣化，不是纯连接问题"],
"contribution": "在连接慢的基础上再叠加约 290ms"
}
],
"amplifiers": [
{
"factor": "冷启动",
"evidence": ["冷启动占比 0.8% vs 11.4%：冷启动使调用落入"连接重建"路径的概率上升，本身不直接造成 3s 耗时"]
}
],
"ruledOut": [
{ "hypothesis": "特定用户触发的大数据量请求", "why": "用户分层无差异" },
{ "hypothesis": "内存不足导致 GC 抖动或 OOM 边缘", "why": "内存峰值仅 1.7 倍，无显著差异" }
],
"verifications": [
{
"hypothesis": "连接未复用",
"method": "统计坏样本中 db_conn_ms > 100ms 的调用，其上游是否都伴随"新建连接"日志",
"expected": "高于 90% 的坏样本应命中该模式",
"falsifyIf": "若命中率低于 50%，则连接耗时是结果而非原因"
},
{
"hypothesis": "查询未走索引",
"method": "对坏样本中的 SQL 做 EXPLAIN，检查 type=ALL 的比例",
"expected": "坏样本 SQL 的 type=ALL 比例显著高于好样本",
"falsifyIf": "若两者索引使用情况一致，则查询层劣化属连带效应"
}
],
"fixPriority": [
{ "priority": 1, "fix": "改为函数外初始化客户端/启用连接池并复用", "expectedGain": "消除 265ms 基线增量，超时率预计降至 5% 以内" },
{ "priority": 2, "fix": "补索引 + 为慢查询加超时", "expectedGain": "消除 290ms 叠加" }
]
}

注意这段输出里最有价值的部分不是 rootCauseChain，而是 verifications 和 ruledOut。 前者告诉你"如果你错了，怎么用数据发现"，后者告诉你"哪些看起来合理的猜测已经被数据排除，别再花时间去查"。这两项才是让 AI 归因可信的关键——它必须把自己放到可被证伪的位置上。

7. 验证与修复

按 AI 给出的证伪方案，我们跑了两条验证：

验证 1：坏样本是否都伴随"新建连接"

# verify_conn.py
bad_with_new_conn = 0
bad_total = 0
for c in bad_calls:
bad_total += 1
if any("connection established" in l for l in c["raw_lines"][:3]):
bad_with_new_conn += 1
print(f"{bad_with_new_conn}/{bad_total} = {bad_with_new_conn/bad_total:.2%}")
# 输出: 2918/3127 = 93.31%

93.31% > 预期的 90%，假设 1 成立。

验证 2：坏样本 SQL 的索引使用情况

对坏样本中提取出的 47 条唯一 SQL 做 EXPLAIN：

好样本 SQL 的 type=ALL 占比为 1.2%。23.4% vs 1.2%，假设 2 成立。

修复动作：

回归验证（观察 7 天）：

8. 方法论提炼：考古式排障的 5 条原则

最后一条尤其重要：在这次的案例里，冷启动的差异倍数是最大的那类（14x）之一，但它不是根因。 如果只按差异倍数排序去修，你会先去优化冷启动，然后发现超时率几乎没降。差异倍数说明的是"相关性"，因果链只能靠机制推理 + 证伪验证得到。