纯lua实现统计函数运行时间和调用次数

lua没有专门查看cpu占用的工具，只能自己撸一个。得益于lua提供了debug.sethook函数，可以在函数调用和返回的时候调用一个设置好的hook函数。在hook函数可以进行数据的统计。
实现起来也极其简单，在函数调用的时候记录调用时间，在函数返回的时候进行时间差统计，这样就得到了一个函数的运行时间。

简单统计

原理是基于debug.sethook，下面写逻辑统计时间就可以了。

local function cc(i)
    if i <= 0 then
        return 0
    end
    cc(i-1)
end

local function aa()
    local j = 0
    for i=1, 100 do
        cc(10)
    end
end

local lst_item = {}
local map_record = {}
debug.sethook(function(hook_type)
        local func_info = debug.getinfo(2, 'nSl')
        local key = func_info.short_src ..":".. func_info.linedefined

        local now = os.clock()
        if hook_type == "call" then
            table.insert(lst_item,{
                call_time = now,
                key = key,
            })
        elseif hook_type == "return" then
            local item = table.remove(lst_item)
            if not item then return end

            local record = map_record[key]
            if record then
                record.call_count = record.call_count + 1
                record.total_time = record.total_time + (now - item.call_time)
            else
                map_record[key] = {
                    call_count = 1,
                    total_time = now - item.call_time,
                    name = func_info.name,
                    line = func_info.linedefined,
                    source = func_info.short_src,
                }
            end
        end
    end, 'cr', 0)

local start_time = os.clock()
aa()

local total_time = 0
for k,v in pairs(map_record) do
    total_time = total_time + v.total_time
    local use_time = string.format("%4.3f", v.total_time)
    print(string.format("%7s  %10d  %20s  %s", use_time, v.call_count, v.name, k))
end
print("-----------------------")
print("total_time: ", total_time)
print("real use time:", os.clock() - start_time)

output:

  0.016           1                    aa  test.lua:8
  0.062        1100                    cc  test.lua:1
-----------------------
total_time:     0.078125
real use time:  0.015625

总耗时0.15625秒，但是统计的函数总时间却是0.078125秒，与实际不相符。

递归重复统计

从上面的例子可以发现，只记录call和return进行插值统计时，当出现递归函数的时候，数据是有问题的，递归函数的时间会重叠，就会出现多余的情况。并且os.clock()函数的精度已经不够了，对于简单的函数内容，os.clock计算出来的差值是0，这样统计出来的结果也是有问题的。下面增加去除子函数运行的时间，并且把获取时间的函数替换成高精度时间函数。

local lst_item = {}
local map_record = {}
debug.sethook(function(hook_type)
        local func_info = debug.getinfo(2, 'nSl')
        local key = func_info.short_src ..":".. func_info.linedefined

        local now = gettime()
        if hook_type == "call" then
            table.insert(lst_item,{
                call_time = now,
                key = key,
                sub_cost = 0,
                name = func_info.name,
            })
        elseif hook_type == "return" then
            local item = table.remove(lst_item)
            if not item then return end

            local record = map_record[key]
            if record then
                record.call_count = record.call_count + 1
                record.total_time = record.total_time + (now - item.call_time - item.sub_cost)
            else
                map_record[key] = {
                    call_count = 1,
                    total_time = now - item.call_time - item.sub_cost,
                    name = item.name,
                    line = func_info.linedefined,
                    source = func_info.short_src,
                }
            end
            if #lst_item > 0 then
                lst_item[#lst_item].sub_cost = lst_item[#lst_item].sub_cost + (now - item.call_time)
            end
        end
    end, 'cr', 0)

output:

  0.0001655           1                    aa  test.lua:12
  0.0034916        1100                    cc  test.lua:5
-----------------------
total_time:     0.0039355754852295
real use time:  0.0062041282653809

尾递归问题

下面把cc函数改成尾递归，执行结果如下：

  0.0000079           5               gettime  [C]:-1
  0.0018032         100                    cc  test.lua:5
  0.0002387           1                    aa  test.lua:12
-----------------------
total_time:     0.0020496845245361
real use time:  0.0020508766174316

这里发现cc函数的调用次数统计也有1100次变成了100次。如果需要把尾递归调用也统计进去，那就需要监听hook_type为tail call类型的情况。因为尾递归只有一次return，所以需要在return的时候进行额外的处理。

local lst_item = {}
local map_record = {}
debug.sethook(function(hook_type)
        local func_info = debug.getinfo(2, 'nSl')
        local key = func_info.short_src ..":".. func_info.linedefined

        local now = gettime()
        if hook_type == "call" or hook_type == 'tail call' then
            table.insert(lst_item,{
                call_time = now,
                key = key,
                sub_cost = 0,
                name = func_info.name,
                is_tail = hook_type == 'tail call',
            })
        elseif hook_type == "return" then
            local is_tail = true
            while is_tail and #lst_item > 0 do
                local item = table.remove(lst_item)

                is_tail = item.is_tail
                local record = map_record[key]
                if record then
                    record.call_count = record.call_count + 1
                    record.total_time = record.total_time + (now - item.call_time - item.sub_cost)
                else
                    map_record[key] = {
                        call_count = 1,
                        total_time = now - item.call_time - item.sub_cost,
                        name = item.name,
                        line = func_info.linedefined,
                        source = func_info.short_src,
                    }
                end
                if #lst_item > 0 then
                    lst_item[#lst_item].sub_cost = lst_item[#lst_item].sub_cost + (now - item.call_time)
                end
            end
        end
    end, 'cr', 0)

output:

  0.0018744        1100                   nil  test.lua:5
  0.0004456           1                    aa  test.lua:12
  0.0010464          15               gettime  [C]:-1
-----------------------
total_time:     0.0033664703369141
real use time:  0.0023291110992432

这里发现cc的函数名是没有成功获取到的，这是因为尾递归的缘故。其实这里也不一定要改成要统计尾递归函数，真实的lua堆栈也没有新的函数堆栈的，所以获取如上不分尾递归统计的结果更符合实际。

缺点

由于是使用了hook，这也是运行一次函数就会调用两次hook函数，这意味着带来了额外的开销，对实际统计函数的运行时间带来了额外的影响，数据也不准确。这里可以改成c语言来实现统计效果，性能会提升非常多，甚至可以在生产环境轻度使用。

以上实现完整代码在：https://github.com/rondsny/lua-profile