人机协同定位一个越用越慢的疑难杂症

说明：本文主要介绍了一次异常问题的排查经历，和以往不同的是，本次的排查有 AI 介入，且结果是积极的，整个的协同工作流程大致是这样

• 我发现线上异常，并开始排查
• 排查一段时间后无果，试探性的让AI介入排查
• AI 进行第一次排查，虽然确定结果有误，但也发现了有价值的信息
• 我给出了更具体的现象，以及一些日志数据
• 查到真正的原因
• 修复，并提供预防措施

我觉得这个经验值得总结和分享，于是有了此文

一、背景

我们新开发的一个线上申报系统最近在测试中发现「修改基本信息」环节偶发失败，浏览器控制台报：

timeout of 5000ms exceeded

但本地开发环境反复操作都不复现，服务器 CPU、内存、数据库都看不出异常。

这类疑难杂症的排查就很挠头，要真是偶发无害的还好，就怕是什么隐藏在深处的问题暴露的一个小症状，真爆发的时候就会被打个措手不及。

实际上本地复现不了，就是因为请求量小看不出来。

二、可疑线索

当时的我第一反应是「表单校验太慢」，毕竟我们这个项目里，这块的业务写的确实复杂。（具体的业务背景可以看这篇：mp.weixin.qq.com/s/P_TWdxa4h…）

前端提交的是一个动态表单请求，字段由后台配置驱动，不是一个固定 DTO：

// 请求体（节选）：一个项目详情提交
public class DynamicFormForProjectDetail
{
    public long DecProjectId { get; set; }          // 哪个申报项目
    public long DynamicRoleId { get; set; }         // 用哪套动态表单模板
    public long? DecProjectDetailId { get; set; }   // 已有详情 Id（新增时为空）
    public Dictionary<string, object?> FormData { get; set; }   // 实际字段：身份证、姓名、照片……
}

后端入口（节选，去掉了业务细节）：

[HttpPut]
[Route(nameof(UpdateProjectDetail))]
[ServiceFilter(typeof(ValidateProjectEditFilter))]
public async Task<IActionResult> UpdateProjectDetail([FromBody] DynamicFormForProjectDetail dynamicForm)
{
    // 动态表单校验：读表单模板 → 读已保存数据 → 提前批量查唯一性 → 逐字段规则;
    // （可疑点就在这个ValidateProjectDetailV2Async里）
    var validationResult = await _dynamicFormValidator.ValidateProjectDeteilV2Async(dynamicForm);
    if (!validationResult.IsSuccess)
        return Accepted(ResultExtensions.ToApiResult(validationResult));   // 202：业务拒绝

    // 业务判定 + 写库 + 清缓存 + 发 MQ
    _logger.LogWarning("修改项目详情，参数：{0}", JsonHelper.Serialize(dynamicForm));
    var result = await _decProjectDetailRepo.UpdateDetailAsync(dynamicForm);
    if (result.IsSuccess)
    {
        await HandleDetailMetaData(dynamicForm);
        return Ok(ApiResult.Success(result.Value.Id));
    }
    return Accepted(ResultExtensions.ToApiResult(result));
}

为了快速排查出问题，也想试试 DeepSeek 最新的 v4.1-flash-1017 版本的模型能力怎么样，从这里开始，AI 介入了问题排查的流程。

它最初的判断方向和我想到的点是一致的，可疑的点基本就在下面这两个地方：

• 校验器逻辑：这是这条链上最重的业务读表单模板（有哪些字段、什么规则）、读已保存数据、逐字段跑规则、唯一性校验……字段越多越慢，它看起来最可疑。（动态表单的校验可行的方法只能是逐字段校验，但可以利用各种手段来提高性能，具体可以看我上面给出的博客）
• 业务拒绝：正是因为动态表单的设计，审查时对提交表单的验证过于严格，有很多的逻辑会被判定为验证不通过，有的业务判断还要查库或者缓存，所以这里也是一个可疑的性能瓶颈点，排查时必须把慢和业务拒绝分开看。

需要说明的是，我们的项目有配置可观测性组件，对这次任务的定位提供了数据支撑，为了进一步确认问题，我这里也查看了链路追踪的数据。

数据显示ValidateProjectDetailV2这个方法执行稳定在 3.2–5.9 秒，请求总耗时 4.4–8.9 秒，看起来就是它。但把每个步骤拆开看，校验器内部也没有热点：

• 校验器的 SQL 查询、字段循环都只有毫秒级；
• SQL Server 侧 CPU 占用 0–1 ms，没有慢查询、没有锁等待；
• 耗时是均匀地摊在每一次通过 FreeSql 的读写上，不是某一个查询特别慢。

这个「分段都正常、整体被拉长」的形状很反常。真正的线索是另一个现象：重启 WebAPI 之后，接口立刻恢复毫秒级，然后随着访问量增加又慢慢变慢。

关于可观测性的内容之前也写过一篇，👉：mp.weixin.qq.com/s/3eMZG0tug…），

三、浮出水面

接下来继续排查日志，这两个日志的渠道我也同步给AI一并分析了。

排查用到的两条通道：

ES（Elasticsearch）日志：数据显示，每条请求完成时会记一行，耗时和状态码在 remark 行尾：

{
  "time": "14:10:14",
  "path": "/api/DecProjectDetail/UpdateProjectDetail",
  "method": "PUT",
  "level": "Information",
  "remark": "Request finished ... - 200 ... 'application/json; charset=utf-8' 41.4297ms"
}

Jaeger：可以看到同一接口、同一操作，修复前后的链路形状完全不同：

# 修复前（链路 49490fa，09:45）
PUT api/DecProjectDetail/UpdateProjectDetail       8.1 s
└─ ValidateProjectDetailV2                         5.9 s     ← 只有 2 个步骤

# 修复后（链路 5a0db56，14:10）
PUT api/DecProjectDetail/UpdateProjectDetail       41.4 ms
└─ ValidateProjectDetailV2                         15.4 ms   ← 14 个步骤
   ├─ validator.schema_load                         13.3 ms
   ├─ validator.saved_metadata_load                  2.0 ms
   ├─ validator.unique_check                         0.01 ms
   └─ validator.field × 8                            0.00–0.01 ms

修复前的实测汇总：

观测项	修复前
UpdateProjectDetail 端到端（ES）	4,446–8,978 ms
UpdateMemberAsync（ES）	2,100–7,500 ms
ValidateProjectDetailV2（Jaeger）	3,242–5,891 ms
SQL Server 侧 CPU	0–1 ms
重启 WebAPI 后	恢复毫秒级，随后继续变慢

根据日志和链路追踪的数据显示，我们怀疑的长验证方法（ValidateProjectDetailV2）慢，还算在预料之中，它本来就是重业务；但两个更新数据库的方法也慢，就反常了，而且数据库本身并不繁忙。再结合前面我发现的现象，每次webapi重启，响应就会变快，所以问题就有可能发生在数据库的写方法里。

缩小排查范围后，AI 也给出了进一步的判断，就是应用程序内有一个随着请求量的增加而增长的东西，拖慢了系统响应时间。

四、确定原因

再把这条写接口从入口到落库摊开：

PUT /api/DecProjectDetail/UpdateProjectDetail
└─ DecProjectDetailController.UpdateProjectDetail          Controller：202 / 200 出口
   ├─ DynamicFormValidator.ValidateProjectDeteilV2Async    Jaeger: ValidateProjectDetailV2
   │  ├─ validator.schema_load          读表单模板
   │  ├─ validator.saved_metadata_load  读已保存表单
   │  ├─ validator.field × N            逐字段规则
   │  ├─ validator.unique_check         唯一性校验
   │  └─ validator.id_type_fields       证件类型相关字段
   └─ DecProjectDetailRepo.UpdateDetailAsync
      ├─ VerifyDetail                    业务闸门（项目状态 / 归属 / 流程）
      └─ detailRepo.UpdateAsync          写库（每次 FreeSql 读写都会把所有已注册的事件回调走一遍）

校验器只做「读表单模板 → 读已保存数据 → 提前批量查唯一性 → 逐字段校验」，每一步各开一个子节点：

public async Task<Result> ValidateProjectDeteilV2Async(DynamicFormForProjectDetail submissionDetail)
{
    using var activity = ValidatorSource.StartActivity("ValidateProjectDetailV2");
    activity?.SetTag("dec_project_id", submissionDetail.DecProjectId);
    activity?.SetTag("field_count", submissionDetail.FormData?.Count ?? 0);

    var result = await ValidateAsyncV2(submission);

    activity?.SetTag("validation_result", result.IsSuccess ? "pass" : "fail");
    return result;
}

数据仓储层 Repo 这一层先过业务闸门，再写库。闸门之一就是「项目流程走到后面步骤后，不允许再改申报详情」，这条链路每一层只有几十行、逻辑也很直白。所以慢的病根，不在业务代码里。

再继续向下挖，终于挖到了真正的病根。范围压到「仓储基类 + 单例」之后，真正的问题在最底下的仓储基类：

public DeclarationBaseRepo(IdleBus<IFreeSql> freeSql)
{
    fsql = freeSql.Get(ConnConsts.DECLARATIONCONN);

    fsql.UseJsonMap();   // 每次构造：挂 2 个回调
    fsql.Aop.AuditValue += (_, e) => { /* 业务代码略，补 UpdatedAt / 雪花 Id */ };   // 每次构造：+1
    fsql.Aop.AuditDataReader += (_, e) => { /* NULL 字符串 → "" */ };  // 每次构造：+1
}

这里看起来像每次创建仓储时顺手配置一下数据库访问，实际上踩了 FreeSql 的两个机制：

1. 是进程内单例（由 IdleBus 持有），而仓储是每个请求创建一个（Autofac 的 InstancePerLifetimeScope，对应内置 DI 的 Scoped）；
2. FreeSql 的 AOP（它提供的「事件钩子」机制，官方文档见 freesql.net/guide/aop.h…）里对 Aop.AuditValue 介绍，+= 的写法是往上追加委托，不是覆盖；UseJsonMap() 内部也一样，每调用一次就往两个事件上各挂一个回调。

于是每一次创建仓储，就往同一个 IFreeSql 上多挂 4 个回调：请求越多、进程跑得越久，挂在事件上的回调就越长；此后每一次 FreeSql 读写都要把所有回调走一遍，读写一起变慢。业务量大了以后，很快就能把进程拖垮。

AI也写了一段离线探针（直接反射数 IFreeSql 事件上的委托个数）来探测验证，测出的对应关系如下：

IFreeSql 事件上挂的回调数	单条表单模板查询耗时
51	25.9 ms
871	29.4 ms
4,891	89.0 ms
20,911	390.5 ms

耗时随回调数线性增长，和数据量无关——这也解释了为什么「本地快、线上慢」「重启快、越跑越慢」。

五、修复&预防

找到了病因，修复方向就明确了：把「往单例上挂回调」的动作从「每次构造」挪到「每个 IFreeSql 实例一次」。

public DeclarationBaseRepo(IdleBus<IFreeSql> freeSql)
{
    fsql = freeSql.Get(ConnConsts.DECLARATIONCONN);

    // 审计事件与 JsonMap 只注册一次：repo 是每请求作用域实例，
    // 反复注册会让单例 IFreeSql 的事件链随请求数无限增长
    // 启动期 IdleBus 工厂已对新实例注册过，此处是兜底，幂等。
    FreeSqlAopInitializer.EnsureRegistered(fsql);
}

对应的服务注册处代码

ib.Register(item.DbKey, () =>
{
    var fsql = new FreeSqlBuilder()
        .UseConnectionString(DataType.SqlServer, item.ConnectionString)
        .UseAutoSyncStructure(true) // 开发环境自动同步结构，只有在curd时才生成
        .UseMonitorCommand(cmd => ConsoleHelper.Write(cmd.CommandText + "\n", ConsoleColor.DarkYellow))
        .Build();
    // IdleBus 空闲释放实例后会经 Register 工厂重建，实例级配置必须在这里补上
    FreeSqlAopInitializer.EnsureRegistered(fsql);
    return fsql;
});

初始化器用一个「已注册清单」记下哪些 IFreeSql 已经注册过（ConditionalWeakTable，可以理解为弱引用的字典，普通 Dictionary<IFreeSql, object> 会强引用 IFreeSql 导致 IdleBus 释放的实例无法回收），保证每个实例只走一次，行为与原实现保持一致

public static class FreeSqlAopInitializer
{
    private static readonly ConditionalWeakTable<IFreeSql, object> Registered = new();
    private static readonly object RegisterGate = new();

    public static void EnsureRegistered(IFreeSql fsql)
    {
        if (Registered.TryGetValue(fsql, out _))
            return;

        lock (RegisterGate)
        {
            if (Registered.TryGetValue(fsql, out _))
                return;

            // UseJsonMap 每调一次就往 Aop.ParseExpression 与 Aop.ConfigEntityProperty
            // 各挂一个回调，和下面的审计事件一样只允许注册一次
            fsql.UseJsonMap();

            fsql.Aop.AuditValue += (_, e) =>
            {
                if (e.Property.Name.Equals("UpdatedAt", StringComparison.InvariantCultureIgnoreCase))
                    e.Value = DateTimeOffset.UtcNow;

                if (e.Property.Name.Equals("Id", StringComparison.InvariantCultureIgnoreCase)
                    && long.TryParse(e.Value?.ToString(), out var id) && id == 0)
                    e.Value = YitIdHelper.NextId();
            };

            fsql.Aop.AuditDataReader += (_, e) =>
            {
                if (e.DataReader.GetFieldType(e.Index) == typeof(string) && e.Value == DBNull.Value)
                    e.Value = "";
            };

            Registered.Add(fsql, new object());
        }
    }
}

到这，问题基本就修复好了。但是AI还多给了一个预防措施，我觉得还挺好的。

它说这类问题最容易在一次重构后「重新长回来」。所以同时补了两道守卫测试（也就是「哨兵」：不检查业务结果，只盯着「有没有人再犯这个错」）。

第一道盯行为：反复创建多种仓储后，事件上挂的回调总数必须保持不变。

第二道盯源码：扫描五个项目，除了基类，任何文件出现** Aop.* += 或 **UseJsonMap( 就测试失败。

以下是两个单元测试的关键代码

[Fact]
public void RepoConstruction_ShouldNotAccumulateAopHandlers()
{
    var fsql = BuildOfflineFreeSql();
    var ib = new IdleBus<IFreeSql>(TimeSpan.FromMinutes(1));
    ib.Register(ConnConsts.DECLARATIONCONN, () => fsql);

    _ = new ProbeRepo<DecMain>(ib);
    var afterFirst = CountAopHandlers(fsql);       // 首次构造必须完成注册

    for (var i = 0; i < 5; i++)
    {
        _ = new ProbeRepo<DecMain>(ib);
        _ = new ProbeRepo<DecProject>(ib);
        _ = new ProbeRepo<DecProjectDetail>(ib);
        _ = new ProbeRepo<DictMetaConfig>(ib);
    }

    Assert.Equal(afterFirst, CountAopHandlers(fsql));   // 之后再构造不得增长
}

/// <summary>
/// 哨兵：AOP 事件与 UseJsonMap 只允许在 DeclarationBaseRepo 的统一注册入口里出现。
/// 任何仓储/Provider 构造函数里再 `+=` 或再调 `UseJsonMap()`，都会重新引入随请求增长的事件链。
/// </summary>
[Fact]
public void SourceScan_ShouldRejectFreeSqlRegistrationOutsideBaseRepo()
{
    var projectRoots = new[]
    {
        "*省略，项目的名称*"
    };
    var baseRepo = Path.Combine("Magic.Declaration.Application", "Methods", "DeclarationBaseRepo.cs");
    var offenders = new List<string>();

    foreach (var projectRoot in projectRoots)
    {
        var rootPath = Path.Combine(RepoRoot, projectRoot);
        if (!Directory.Exists(rootPath))
        {
            continue;
        }

        foreach (var file in Directory.EnumerateFiles(rootPath, "*.cs", SearchOption.AllDirectories))
        {
            var relative = Path.GetRelativePath(RepoRoot, file);
            if (relative.Split(Path.DirectorySeparatorChar).Any(segment =>
                    segment.Equals("bin", StringComparison.OrdinalIgnoreCase)
                    || segment.Equals("obj", StringComparison.OrdinalIgnoreCase)))
            {
                continue;
            }

            if (relative.Equals(baseRepo, StringComparison.OrdinalIgnoreCase))
            {
                continue;
            }

            var lines = File.ReadAllLines(file);
            for (var i = 0; i < lines.Length; i++)
            {
                var code = StripLineComment(lines[i]);
                if ((code.Contains("Aop.", StringComparison.Ordinal) && code.Contains("+=", StringComparison.Ordinal))
                    || code.Contains("UseJsonMap(", StringComparison.Ordinal))
                {
                    offenders.Add($"{relative}:{i + 1}: {lines[i].Trim()}");
                }
            }
        }
    }

    Assert.True(offenders.Count == 0,
        "以下位置绕过统一注册入口重复注册 FreeSql 事件（会随请求数增长 AOP 事件链，导致读写接口越用越慢）：\n"
        + string.Join("\n", offenders));
}

测试执行：

dotnet test Magic.Declaration.xUnitTest/Magic.Declaration.xUnitTest.csproj \
      --filter "FullyQualifiedName~AopEventChainSentinels" --logger "console;verbosity=normal"

效果如下

AI最大的特点就是你只要1，他却能给到10，这是优点也是缺点，分场景吧，而且这个特点我觉得多数时候是需要加以约束的。我这里倒是个正向的例子，也说明模型本身的能力的确是强大。

六、修复效果

后端发版后，在同一生产环境、同一接口复测：

观测项	修复前	修复后（第一轮）	后续全流程复测
UpdateProjectDetail 端到端	4,446–8,978 ms	88.19 ms	41–42 ms
UpdateMemberAsync	2,100–7,500 ms	65.3 ms	76.3 ms
ValidateProjectDetailV2	3,242–5,891 ms	23.47 ms	14.0–15.4 ms

随后又完整跑了一遍业务系统的全流程（279 条链路记录）：

• 窗口内 level=Error 0 条；
• 最慢的业务接口是 PDF 生成，和附件上传两个链路在 500ms 左右，其余写接口全部毫秒级；
• 同一接口连续调用 19 次，耗时稳定在个位数到 30 多毫秒，没有再出现「越用越慢」；

七、复盘总结

好了，到此问题就全部修复完成了，这次的协同本质，也不完全是体现 DeepSeek 的新模型有多厉害（当然他的确很厉害），更多的是总结出了一套可以高效复现的协作机制：模型负责干，人负责判，项目本身则负责让这两件事可以复现，三者是相辅相成的。所以，相同的模型，相同的人，不同的项目，协作干活的机制可能就得调整。

回到这次的经历，我觉得这个项目真正立功的的点是集成了可观测组件（ES，Jaeger），为人和AI都提供了强力的日志和链路追踪数据，否则 人和AI 再强也只能是分析静态的代码以及编译后运行时输出的日志，搞不好还要自己打点，当然这也不是问题，但效率肯定就慢了许多。所以项目本身的底子，是实现高效协同的一个充分条件。

此外，在传统的开发模式下，我们在开发过程中可能天然的知道这个项目的某个特征或者特殊设计，比如某个缓存不能更新，某个配置必须得用某某方式加密等等，甚至是有些坑，这些都是我们日常开发时的长期记忆，每次打开项目都会想起来，即便是忘了，等发生冲突的时候也能快速想起来。而 AI 是没有这种高效的工作方式的（不是说它没记忆），或者说它每次进场介入的时候，都需要从零重建对项目的事实模型，而这只是能来自上下文，文档，和代码本身，一些短而关键的信息可能会在上下文里被稀释，导致判断产生偏差，后面的分析、修改、验证就可能会叠加成一串错误结论。更严重的是，它还会自信的把错误写进注释和文档。所以不是"AI 不够聪明"，而是协同的价值之一，是可以把人脑里的一些前提信息显式化，让 AI 少犯错，而有效的手段就是规范的项目文档和跟随项目建立起来的项目记忆和一些全局记忆（比如claude.md，agents.md等）。

总的来说，工具永远是杠杆，人类架构师的直觉、验证能力、工程防范意识以及项目本身的情况才是决定AI和人协作能力上限的关键，起码目前是这样。

---