关于profile.start,profile.stop性能监控问题

[253980289]

我在使用 profile.start/profile.stop 进行函数调用性能监控时，发现一个异常现象：一个本应简单的函数 gperiod_task.time_fun 偶尔会出现耗时超过 100 毫秒的情况。该函数核心逻辑仅为调用 skynet.time()。

关键排查点

1. 为监控需要，我对该函数设置了元表
2. 为排查 profile 统计误差，同时使用 skynet.hpc 辅助验证
3. 结果：两个工具的计时差值相当接近，证明：
   • 被监控函数执行期间确实是无阻塞的纯 CPU 操作
   • profile 统计机制本身没有问题

核心疑问

如果耗时是监控机制（包括元表和 <close> 机制）本身的开销：

• 为什么绝大多数调用耗时 <1 毫秒（理论正常值）？
• 为什么极少数情况耗时 >100 毫秒（异常值，且出现规律不明确）？

异常日志记录

（仅当耗时 >1 毫秒时输出日志）

[once][0][0][2025-06-23 21:17:19.86][0x73c01fc36288][ghome1][1][nnprofile][281][stop_:reset_new_task_time->close->_after_fun->stop->stop_(281)]gperiod_task.time_fun	cur_call_stack._start_hpc, stop_hpc, stop_hpc - cur_call_stack._start_hpc, cur_call_stack_total_elapsed_time:	39838112974080	39838223122025	0.110147945	0.110134711

• 最后两个值分别为：
  • 0.110147945 = skynet.hpc 统计值（已从纳秒转换为秒）
  • 0.110134711 = profile 统计值

相关代码

M.time_fun = time_fun or gdata.time_f -- or gdata.time or gdata.stable_time

function gdata.stable_time_f()
    -- skynet.time() 与 os.time() 不同的地方是 skynet.time() 不受系统时间更改的影响
    -- (只取决于 skynet 启动时间及启动后运行时长)
    -- 而 os.time() 会随系统改时间而同步改变
    return skynet.time() + gdata._time_offset
end

function M.time_f()
    -- skynet.time() 与 os.time() 不同的地方是 skynet.time() 不受系统时间更改的影响
    -- (只取决于 skynet 启动时间及启动后运行时长)
    -- 而 os.time() 会随系统改时间而同步改变
    return gdata.stable_time_f() + M.time_offset
end

[cloudwu]

profile 的区别仅在于调用的获取系统时间 api 不同，尤其是在监测的函数中没有让出时，它等价于调用两次获取时间的逻辑。

profile 获取时间的实现在 https://github.com/cloudwu/skynet/blob/master/service-src/service_snlua.c#L99-L121 ，你可以尝试修改成和 hpc 实现一致。

ps. 上面主贴的排版没编辑好，建议重新用 markdown 编辑一下。

[253980289]

相关源码我之前已经找到并简单排查过，没发现什么特别的问题。我咨询ai反馈说是否存在gc导致这种问题。

[cloudwu]

1. 可以把 profile 用的 get_time 换成和 hpc 完全一致的，排除系统 api 的差异。
2. lua gc 是由分配内存驱动的。如果代码没有分配新的内存块，就不会涉及任何 gc 的流程。如果不确定，也可以将 gc stop 掉。

[253980289]

我这边先换成hpc机制测试看下效果。

[253980289]

排查步骤(按云大思路)

1. 先用纯hpc代替profile(完全去掉)
	- 结果与之前基本一至，可以说明与profile的实现机制完全无关，也即并非profile自身占用了时间或其计算时间不对
2. 考虑gc影响
	- 增加监控前后的内存变化量来观察gc的执行情况

结论

问题基本确定了，就是gc的问题，所有调用时间大于1毫秒的调用前后，内存都是缩小的，而小于1毫秒的正常执行，内存都是有较小增长的，以下是相关日志(只记录了慢的)：

[once][0][0][2025-06-26 16:13:21.64][0x73d51b825a68][ghttp_debug1][0][nnprofile][297][stop_:close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:280800000613376, stop_hpc:280800001790392, stop_hpc - cur_call_stack._start_hpc:0.001177016, cur_call_stack._start_collectgarbage_count:1008.3466796875, collectgarbage('count'):498.1611328125, cur_call_stack_total_elapsed_time:0.001175402
[once][0][0][2025-06-26 16:15:26.84][0x73d51e44f048][ggateserver1][0][nnprofile][297][stop_:reset_new_task_time->close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:280925201920823, stop_hpc:280925203120202, stop_hpc - cur_call_stack._start_hpc:0.001199379, cur_call_stack._start_collectgarbage_count:2373.912109375, collectgarbage('count'):1973.2685546875, cur_call_stack_total_elapsed_time:0.001198327
[once][0][0][2025-06-26 16:20:26.84][0x73d51e44f048][ggateserver1][0][nnprofile][297][stop_:reset_new_task_time->close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:281225201118400, stop_hpc:281225203404178, stop_hpc - cur_call_stack._start_hpc:0.002285778, cur_call_stack._start_collectgarbage_count:2600.5556640625, collectgarbage('count'):1540.34765625, cur_call_stack_total_elapsed_time:0.002284816

根本原理：

当你使用 clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ti) 来测量一段 Lua 函数调用（或一段包含多个函数调用的业务逻辑）的耗时时，测量到的 CPU 时间不仅包含业务逻辑本身消耗的 CPU 时间，还包含了在这段代码执行期间，穿插在其中的所有 GC 步骤所消耗的 CPU 时间。

下一步研究方向：

如何避免lua的gc对业务层逻辑的影响，比如战斗卡顿、定时器错过执行周期等

感谢云大提供建议方案。

[firedtoad]

建议关闭GC 后续定期慢慢释放 fastfullstack.com ***@***.***> 于2025年6月26日周四 17:07写道：

…

排查步骤(按云大思路) 1. 先用纯hpc代替profile(完全去掉) - 结果与之前基本一至，可以说明与profile的实现机制完全无关，也即并非profile自身占用了时间或其计算时间不对 2. 考虑gc影响 - 增加监控前后的内存变化量来观察gc的执行情况 结论 问题基本确定了，就是gc的问题，所有调用时间大于1毫秒的调用前后，内存都是缩小的，而小于1毫秒的正常执行，内存都是有较小增长的，以下是相关日志(只记录了慢的)： [once][0][0][2025-06-26 16:13:21.64][0x73d51b825a68][ghttp_debug1][0][nnprofile][297][stop_:close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:280800000613376, stop_hpc:280800001790392, stop_hpc - cur_call_stack._start_hpc:0.001177016, cur_call_stack._start_collectgarbage_count:1008.3466796875, collectgarbage('count'):498.1611328125, cur_call_stack_total_elapsed_time:0.001175402 [once][0][0][2025-06-26 16:15:26.84][0x73d51e44f048][ggateserver1][0][nnprofile][297][stop_:reset_new_task_time->close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:280925201920823, stop_hpc:280925203120202, stop_hpc - cur_call_stack._start_hpc:0.001199379, cur_call_stack._start_collectgarbage_count:2373.912109375, collectgarbage('count'):1973.2685546875, cur_call_stack_total_elapsed_time:0.001198327 [once][0][0][2025-06-26 16:20:26.84][0x73d51e44f048][ggateserver1][0][nnprofile][297][stop_:reset_new_task_time->close->_after_fun->stop->stop_(297)]fun:gperiod_task.time_fun, cur_call_stack._start_hpc:281225201118400, stop_hpc:281225203404178, stop_hpc - cur_call_stack._start_hpc:0.002285778, cur_call_stack._start_collectgarbage_count:2600.5556640625, collectgarbage('count'):1540.34765625, cur_call_stack_total_elapsed_time:0.002284816 根本原理： 当你使用 clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ti) 来测量一段 Lua 函数调用（或一段包含多个函数调用的业务逻辑）的耗时时，测量到的 CPU 时间不仅包含业务逻辑本身消耗的 CPU 时间，还包含了在这段代码执行期间，穿插在其中的所有 GC 步骤所消耗的 CPU 时间。 下一步研究方向： 如何避免lua的gc对业务层逻辑的影响，比如战斗卡顿、定时器错过执行周期等 感谢云大提供建议方案。 — Reply to this email directly, view it on GitHub <#2063 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAK6QJUL5RPA5V2EUDYTA6L3FOZ5BAVCNFSM6AAAAACACQKDVCVHI2DSMVQWIX3LMV43URDJONRXK43TNFXW4Q3PNVWWK3TUHMYTGNJYGMZDEMA> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[253980289]

我后续优化的计划是这样的：
1、优化监控机制的准确性；
2、优化其他功能避免被gc影响；

对于第1步，受ai的启发，我的思路是尽可能优化监控机制中内存的使用，尽可能避免或减少内存分配，具体做法就是预分配数据结构和创建对象池，以及尽可能在监控前分配内存。但由于监控的动态性(目前我采用函数调用树的数据结构来监控)，不太可能完全预先创建好所有要用的数据结构。但是我想到有些数据结构，比如监控树，一般在程序执行过一次后，该结构即确定了，后续只是增加调用次数和调用时间，不会再分配内存了。然后想到你提的建议，之前不了解是什么意思，现在联想起来，大概是等程序运行一段时间待稳定了再放开gc，这样就能在一定程度上减小gc对程序运行的影响了，一般来说，服务启动和初始化阶段确定会内存波动较大。但现在问题是，最佳效果是能让程序所有代码在前期都跑一遍或执行到，不然后续未执行过的新代码运行时仍可能会有较大的内存波动。所以现在就是考虑有什么方案可以达到这个目标。

[253980289]

经研究(ai支持和测试验证)发现，gc可能在内存分配、函数调用边界、循环迭代等位置插入执行点，即使通过各种内存优化，包括对象池等的预分配策略优化后，也远无法达到性能监测的准确性，终级策略只能采用在监控前后临时关闭和打开gc的方案，但这样风险较大，所以我目前的策略是只在非生产环境使用此方案以统计系统性能参数，而线上环境则不使用gc方案。

[253980289]

触发点总结（Lua 5.4）

触发场景	源码位置	触发方式
内存分配	lmem.c	luaC_condGC
字节码创建对象	lvm.c	checkGC
API创建对象	lapi.c	luaC_checkGC
协程挂起	ldo.c	luaC_checkGC
元方法调用后	ltm.c	luaC_checkGC
手动GC操作	lgc.c	luaC_step

[253980289]

Lua 5.4
OP_FORLOOP 中 没有 直接调用 luaC_checkGC
函数调用本身不直接触发GC（luaD_call 中无GC检查）

[253980289]

根据这几个点，我再次进行优化和测试，发现我的监控机制主要是因为用到了__close元方法及同时创建了两三个临时表导致，我修改为普通前后调用机制，同时避免创建新表，比如函数调用结果我通过【local ok, ret1, ret2, ret3, ret4, ret5, ret6, ret7, ret8 = pcall(fun, ...)】形式，而之前是local ret = table.pack(fun(...))；
在优化后，我取消取之前对gc的stop和restart的控制，再次测试效果似乎与控制gc开关效果差不多了。不过目前仍在测试中。

[253980289]

目前好像没有找到完全完美的解决方案，因为即使关闭gc，在特定的时候，lua仍然会自己执行gc，所以我目前的终级方案是在监控前后统计一个内存值，通过这个差值对比执行时间来评估中间是否包含了gc操作。如果要减少统计偏差值，可以在监控前关闭gc，然后统计后再打开。
如果大家没有更好的建议和方案，我将把此结果作为最终解决方案。