文章

游戏服务器工程实践六:lua cpu 和 heap profiling

游戏服务器工程实践六:lua cpu 和 heap profiling

游戏服务器时常需要做一些 profiling 工作,c/c++ 部分可以使用 gperftools(Google Performance Tools)进行 profiling,而 lua 并没有一个业界权威的工具,在 github 找到的也都不能满足我的要求。

于是我自己做了一个项目 https://github.com/antsmallant/luaprof,实现了想要的效果:开销低,又能相对精确地捕捉到较大的热点。

本文主要介绍 profiling 的机制,以及 luaprof 的功能和设计。luaprof 虽然大部分是 ai coding 出来的,但其思想是经过比较长期的摸索和实践才得来的,也在生产项目上得到了实践。对于大热点的采样挺准的,并且开销很低,远低于那种基于 tracing 机制的 profiling 库。

我们这里说 heap profiling,是比较精确的说法,因为我们确实只是对堆(heap)内存进行 profiling 而已,并不涉及栈内存。


1. profiling 有哪几种机制?

首先说一说 profiling 的机制,对 CPU profiling 而言,常见的数据采集方式有两类:sampling(采样)与 tracing,后者在有些地方也称为基于事件的插桩(instrumentation-based profiling)。
GNU 的官方 gprofng 手册直接有一节叫 “Sampling versus Tracing”:它把 sampling 的对立技术称为 tracing,并定义为“向目标程序插入特定调用来采集信息”。

sampling:周期性记录当前 PC 或调用栈,结果是统计意义上的热点分布。

tracing:通常是利用插桩(instrumentation)方式,在函数调用、返回等事件发生时执行 hook,精确记录调用次数和持续时间。

tracing 和 instrumentation 的关系可以这样理解:

词它描述什么
instrumentation(插桩)怎么取得事件:在函数入口/退出、系统调用、业务点插入或启用 probe/hook。可静态编译插桩、动态二进制插桩、VM hook 等。
tracing(追踪)怎样记录和观察事件:通常保留带时间戳、顺序、参数的事件流。它常由 instrumentation 产生。

相关资料:


2. github 上若干 lua profiling 项目

github 上有不少做 lua profiling 的项目,但研究下来,都有一些局限,不能满足我的要求。

2.1 plua

项目地址:https://github.com/esrrhs/pLua 。

局限1:抓不到 c 栈帧

见这个issue:无法抓到 c 栈帧 #9。

它是使用 LUA_MASKCOUNT 去 sethook 的,采样时钟到的时候,在下一个 vm 指令去抓栈,此时抓到的只是 lua 栈。像 tonumber / print 这种简短的 c 函数抓不到,问题还不是特别大,但一些执行时间长的 c 函数没抓到,对于整个结果的影响就很大了。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
static void SignalHandlerHook(lua_State *L, lua_Debug *par) {
    lua_sethook(L, 0, 0, 0);

    LLOG("Hook...");

    if (gRunning == 0 || (gSampleCount != 0 && gSampleCount <= gProfileData.total)) {
        LLOG("lrealstop...");
        lrealstopsafe(L);
        return;
    }

    CallStack cs;
    get_cur_callstack(L, cs);

    gProfileData.callstack[cs]++;
    gProfileData.total++;
}

static void SignalHandler(int sig, siginfo_t *sinfo, void *ucontext) {
    lua_sethook(gL, SignalHandlerHook, LUA_MASKCOUNT, 1);
}

局限2:不支持多线程

见这个 issue:接入到lua 服务器,崩溃 #8。

它的实现是:

  • 全局只有一个 gL、一个 gRunning、一个 SIGPROF handler。
  • ITIMER_PROF 统计整个进程的 CPU 时间,不是某个 Lua VM 所在线程。
  • 信号可能在别的线程到达,但它仍对那个全局 gL 设置 hook。

pLua 使用 ITIMER_PROF 作为周期 CPU 定时器;该定时器每次到期时,内核向进程投递 SIGPROF,pLua 注册的 SIGPROF handler 再为 Lua VM 设置 LUA_MASKCOUNT hook。

也就是说:

1
2
ITIMER_PROF       定时器的种类/计时依据
SIGPROF           该定时器到期时投递的信号

Linux 的 setitimer(2) 明确规定:ITIMER_PROF 统计进程的用户态与内核态 CPU 时间,每次到期产生 SIGPROF。man7 setitimer(2)

pLua 源码确实同时出现两者:它用 sigaction(SIGPROF, ...) 注册 handler,再用 setitimer(ITIMER_PROF, ...) 启动定时器;handler 中设置 LUA_MASKCOUNT hook。pLua 源码

另外,源码中报错字符串写的是 sigaction(SIGALRM) failed,但实际调用参数是 SIGPROF;这是日志文案的笔误,不是它真的注册了 SIGALRM。

2.2 lsg2020/luaprofile

项目地址:https://github.com/lsg2020/luaprofile 。

这个更早是追溯到 https://github.com/lvzixun/luaprofile 。

lsg2020 另外有个项目: https://github.com/lsg2020/swt ,也是基于 https://github.com/lsg2020/luaprofile 去做的一个火焰图。

局限:使用 tracing 机制

tracing 方式,对于每个调用都做了 profiling,profiling 这个动作本身就特别耗时,对结果干扰很大。

2.3 spin6lock/skynet_systemtap_set

项目地址:https://github.com/spin6lock/skynet_systemtap_set。

局限:可能出现较大统计偏差

当前这个实现只是采样对于 c lua api 的调用,如果一个运行1秒的纯lua函数只调用了几次 api,而1个运行100毫秒的lua函数调用了几百次api,则统计结果完全不准。

理论上,用 stp 或 ebpf 也能做到接近我这次做的 luaprof 的统计精度,但工程实现难度会很高,完整实现下来比 luaprof 费劲得多。

ebpf 能提供按 cpu 时间触发的采样,用 perf_event_open 指定线程的 tid、设 cpu = -1,事件会跟随线程在不同 cpu 上运行;可设置采样频率,再把 ebpf 程序挂到这个 perf event 上。ebpf 也能读取用户态数。难点在于把采样正确还原成 lua 调用栈,并在 skynet 的 worker 之间持续识别目标 service。


3. 为什么 sampling 机制能够 work?

sampling 就是用少量观测估计整体分布,背后是概率论和统计学中的抽样估计和大数定律。样本越多,随机误差通常越小。

能解决什么问题

  1. 发现稳定的大热点。

不能解决什么问题

  1. 锁相问题。如果采样频率是固定的,则可能遇到锁相的问题,比如某个周期执行的函数,刚好不在采样频率上,那么即使它频繁发生,也不会被采样到。样本多只能压低随机误差,不能自动消除系统偏差。
  2. 稀有事件。如果某状态只占0.1%的时间,那么采样1000次,那么它仍有37%的概率不被看到。

4. luaprof 介绍

4.1 接入与使用

详细的说明: luaprof 项目接入指南 ,里面已经包含了接入和使用说明了。

需要指出的是,为了实现安全的采样,对 lua 源码做了一些小修改,luaprof 对于 lua 近期的各个版本都做了相应的 patch,可以直接使用,如果是旧一些的版本,就需要参照新版本的 patch 进行相应的修改。

skynet 的 lua 源码也同样需要做类似的修改,luaprof 也有相应的 patch。

使用很简单,就几个 api:start , stop, write,比如 cpu profile 就这样:

启动

1
local cpu_recorder = profile.cpu.start()

停止并写结果

1
2
3
local cpu_result = cpu_recorder:stop()
local save_path = "xxx_cpu.pb.gz"
cpu_result:write(save_path)

具体可以参考上面提到的 luaprof 项目接入指南 ,或这个 example 代码: luaprof/blob/master/examples/thread_vm/profile.lua 。

4.2 核心功能

核心功能能回答的问题主要能力
CPU 采样CPU 主要消耗在哪里?按线程 CPU 时间采样,区分 Lua、CFunction、GC 和 host 状态,保留 Lua 调用栈与行号
内存分配采样哪些调用路径产生了大量分配?估算累计分配字节数 alloc_space 和分配次数 alloc_objects
存活内存统计本次采集期间分配的内存,哪些在停止时仍未释放?开启 track_free 后,统计 inuse_space 和 inuse_objects
Skynet service 分析指定 service 的热点是什么?跟随 service handle 跨 worker 迁移,排除其他 service、排队和 sleep 时间
结果分析与质量检查如何查看热点、判断结果可信度?导出 pprof、folded stacks,生成火焰图,并提供丢样、溢出、截断等统计

CPU 和 memory recorder 可以同时运行,也可以独立启动、停止。停止后得到冻结的 result,再通过 stats() 查看统计、通过 write() 导出。


1、cpu 采样支持传统的每线程一个 lua vm 的

1
2
make example-thread-vm
go tool pprof -top build/thread-vm-cpu.pb.gz
图1:thread-per-vm cpu 采样(by function)


也可以按行去归因,但这会显得过细了:

1
go tool pprof -lines -top build/thread-vm-cpu.pb.gz
图2:thread-per-vm cpu 采样(by lines)


说明:如果是每线程多 lua vm(skynet 除外),则目前不支持,直接使用会出现统计不准的问题,主要是暂时还没遇到有传统项目是每线程多 vm 的,遇到了再说吧,改造难度中等。


2、cpu 采样也支持 skynet 按 service 采样

运行示例:

1
2
make example-skynet 
go tool pprof -top build/skynet-cpu.pb.gz

skynet example 是这个 service : luaprof/examples/skynet/luaprof_demo.lua 跑了采样。

图3:skynet cpu 采样(by function)


同样也可以按行去归因,只需要改一下 pprof 的参数就行,这里不展开了。


3、内存采样支持传统的每线程一个 lua vm 的

运行示例:

1
2
make example-thread-vm
go tool pprof -sample_index=alloc_space -top build/thread-vm-heap.pb.gz
图4:thread-per-vm heap 采样(by function)


也可以按行去归因,不过同样会显得过细:

1
go tool pprof -sample_index=alloc_space -top -lines build/thread-vm-heap.pb.gz
图5:thread-per-vm heap 采样(by line)


alloc_space 只是一个维度,我们也可以使用 alloc_objects 来观察分配的对象个数:

1
go tool pprof -sample_index=alloc_objects -top build/thread-vm-heap.pb.gz
图6:thread-per-vm heap 采样(by alloc_objects by function)


我们的 example 做内存打开了 heap_use 开关,

4、内存采样也支持 skynet 按 service 采样

运行示例:

1
2
make example-skynet 
go tool pprof -top build/skynet-cpu.pb.gz


4.3 主要设计

cpu 采样的原理

heap/memory 采样的原理

线程级 timer

使用实际 cpu 时间消耗来计时,而不是墙钟(wall time),避免 sleep 也被采样。

cfunction 延迟

安全点写入

skynet 支持按 service 做 profiling

skynet 底层起了若干个 worker 线程,service 运行时可能在其中任一个 worker,所以实现上每个 worker 线程都设了 thread timer,timer 到期的时候会判断当前线程是否运行着需要采样的 service,如果不是,则跳过 handle。

pprof 格式

  • 结果保存为 pprof 格式,把采样的一些关键信息也附带上了,比如 overrun 之类的信息。
  • 结果可以直接用 pprof 查看,可以生成 txt 报告,也可以生成 svg 报告。

4.4 细节处理

关于 overrun

overrun 指 cpu timer 已经多次到期,但系统只送达了一次采样信号,其余到期次数没有独立的执行现场。

luaprof 的处理原则是:记录这些缺失次数,但不把它们补算到某个函数上。

Linux 的 POSIX timer 对每个 timer 最多保留一个待处理。这个信号尚未送达时,timer 再次到期,就累计 overrun;送达时通过 siginfo_t.si_overrun 告诉我们额外到期了多少次。即使使用实时信号,也有这个限制的。 linux timer 语义

例如,配置 1000HZ,即每消耗 1ms 线程 cpu 时间采样一次:

1
2
3
4
5
线程 CPU 时间   1ms       2ms       3ms       4ms
timer 到期       ↓         ↓         ↓         ↓
通知状态         信号待处理,后续到期累计 overrun
最终送达                                      一次信号
                                              si_overrun = 3

这里有4次到期,但只有一次信号送达。

常见成因包括:

  • 信号暂时被屏蔽:线程继续消耗 CPU,timer 继续到期,但无法进入 handler。
  • 内核到期检查和信号送达有延迟:CPU timer 的处理涉及内存 tick 等路径,配置间隔很短时,一次检查可能跨过多个周期。
  • 信号处理期间继续消耗 CPU:同一个信号通常在 handler 执行期间被屏蔽;频率过高或处理过慢会增加积压机会。

5. 其他

为什么不使用 ebpf 之类的来做?


6. 参考

  1. https://www.sourceware.org/binutils/docs/gprofng.html#Sampling-versus-Tracing