从 947 次重复输出开始整理游戏日志

排查一个线上问题时,日志本应提供线索,但大量高频输出也会让问题更难看清。后来我专门做了一次统计:从进入游戏开始,采样到帧率稳定后的五秒,查看每条日志分别打印了多少次。

结果排在第一的一条输出出现了 947 次,后面的几条则是几十次。删掉这条重复日志后,当时的主观流畅度已有明显改善。这让我开始系统整理日志频率、用途和开关。

先限定采样窗口

这里的 947 次不是“每秒 947 次”,也不是“仅在稳定后的五秒里打印 947 次”。采样覆盖了整个进入过程,并在帧率稳定后继续了五秒。

统计窗口必须写清楚,否则同一个数字很容易被解读成不同的性能结论。我当时关注的是:在一次常见进入流程里,哪些输出明显重复、值得优先检查。

同一次采样中,高频重复日志为947次,其余四类输出为49、40、40和35次

根据当时的统计截图重绘,保留计数,将内部函数与模块名称替换为用途描述。

聚合时最好按固定事件或日志模板计数。如果一条日志把时间、对象 ID 和位置全部拼进文本,每次生成的字符串都不同,按完整内容分组就可能掩盖重复调用。

高频不代表一定该删除

计数只是筛选线索。网络连接、关键资源加载和异常状态等信息,即使在进入阶段比较密集,也可能对线上问题有价值。

我逐条检查的是:这条输出用于确认什么、在正常流程里是否仍然需要、出现问题时能否按模块打开,以及有没有更简洁的表达方式。

对于早期开发留下的重复过程日志,可以移除或默认关闭;有诊断价值的细节则保留开关。一次状态变化打印一次,通常比每帧重复输出相同状态更容易阅读,但两者是否等价仍要看需要观察的内容。

屏幕上不显示,不等于没有开销

日志涉及的成本可能发生在多个位置:准备参数、格式化字符串、Lua 与 C# 之间的调用、堆栈采集,以及后面的输出与显示。

因此 Console 面板里的折叠或过滤,不能直接当作前面这些工作没有发生。尤其是字符串已经拼好才传入日志函数时,函数内部判断关闭也来不及消除拼接成本。

1
2
3
4
5
6
// 即使方法内部忽略 Debug,参数求值仍然会发生。
Log.Debug($"Preview objects: {BuildObjectDescription()}");

// 在准备昂贵诊断信息之前判断开关。
if (LogSettings.PreviewDebugEnabled)
Log.Debug($"Preview objects: {BuildObjectDescription()}");

Lua 的拼接表达式也有同样的问题。宏、条件方法或延迟构造可以作为另一种实现方式,但应该先确认项目的日志层到底在哪里过滤,避免只优化显示端。

分级与模块标签分别解决不同问题

日志等级表达重要性,模块标签表达来源,两者可以一起使用。例如只观察资源模块的 Debug,同时保留其他模块的 Warning 和 Error。

对经常排查的模块,默认关闭详细日志,保留可主动开启的入口。这样平时不会被无关信息淹没,需要联调时也不用到处临时加 print。

标签设计也应便于维护。如果每加一个模块都要手写大量重复包装,最后很容易出现同一模块多种拼写,或者调用者绕过统一入口。

2026 年 7 月补充:为日志标签生成代码

后来在另一个项目中,我又整理了日志标签的接入方式:在统一定义里新增条目,再通过编辑器菜单生成对应的模板代码。

这让增删标签有了固定入口,也便于按模块筛选高频输出。它解决的是日志入口的维护问题,并不会自动修复所有调用点上的参数求值开销;需要昂贵内容的地方仍然要检查调用方式。

这次记录能够说明什么

原始统计保留了输出次数,也保留了当时删除高频日志后的体验反馈,但没有完整的同设备、同场景帧时间对照数据。因此我不会把这次记录写成提升了某个百分比的性能结论。

如果需要量化收益,后续应固定进入流程和采样条件,对比日志开启与关闭时的 CPU 耗时、分配和帧时间分布。编辑器 Console 的表现也不能直接替代真机结果。

这次工作最有用的产出,是把“日志太多”变成可以逐项处理的问题:有明确的采样窗口,有高频来源,有需要保留的诊断信息,也有以后重新开启它们的入口。