利用debug庫實現對lua的性能分析

AlbaMacghey 9年前發布 | 31K 次閱讀 Lua 性能分析 Lua開發 xmake

之前在給xmake做構建的效率優化的時候，需要對lua腳本的api調用性能進行分析，分析出最耗時一些lua調用api，找出性能瓶頸，來針對性地進行優化，那么問題來了，如果對lua腳本像c程序那樣進行profile呢？

我們現在看下最后實現完的最終效果：

4.681,  98.84%,       1, anonymous                     : actions/build/main.lua: 36
 3.314,  69.98%,       1, anonymous                     : actions/build/main.lua: 66
 3.314,  69.98%,       1, build                         : actions/build/builder.lua: 127
 3.298,  69.65%,       2, _build_target                 : actions/build/builder.lua: 41
 3.298,  69.65%,       2, script                        : actions/build/builder.lua: 30
 2.590,  54.70%,       2, buildall                      : actions/build/kinds/object.lua: 174
 2.239,  47.27%,     468, resume                        : core/sandbox/modules/coroutine.lua: 40
 2.226,  47.00%,     468, anonymous                     : actions/build/kinds/object.lua: 242
 2.073,  43.77%,       3, _build_target_and_deps        : actions/build/builder.lua: 64
 2.047,  43.22%,     468, _build                        : actions/build/kinds/object.lua: 79
 2.034,  42.96%,       1, build                         : actions/build/kinds/static.lua: 31
 1.190,  25.13%,       1, build                         : actions/build/kinds/binary.lua: 31
 0.806,  17.03%,       8, load                          : core/base/interpreter.lua: 527
 0.766,  16.18%,       2, run                           : core/project/task.lua: 393
 0.711,  15.01%,       1, anonymous                     : actions/config/main.lua: 132
 0.615,  12.99%,    2117, vformat                       : core/sandbox/modules/string.lua: 40
 0.593,  12.53%,      16, defaults                      : core/base/option.lua: 803
 0.593,  12.52%,       1, save                          : core/base/option.lua: 131
 0.475,  10.03%,       2, anonymous                     : /Users/ruki/projects/personal/tbox/xmake.lua: 0

其中第一列為當前調用的耗時（單位：cpu時鐘數），第二列為耗時占比，第三列為調用次數，然后是函數名和源代碼位置。

debug.sethook簡介

其實lua自帶的debug就可以做到：

debug庫提供了一種hook的方式，可以通過注冊一個handler函數，在lua腳本運行到某個調用時，會觸發這個handler，
獲取到相應的執行信息，并且給你一個記錄和數據維護的機會。

它主要有四種事件會觸發這個handler的調用：

當調用一個lua函數的時候，會觸發call事件
當函數返回的時候，會觸發一個return事件
當執行下一行代碼的時候，會觸發一個line事件
當運行指定數目的指令后，會觸發count事件

我們可以通過 debug.sethook 這個函數來注冊一個hook的handler，他有三個參數：

handler的處理函數，hook事件觸發后被調用
描述需要hook的事件類型，call、return和line事件分別對應：’c’, ‘r’, ‘l’，可以互相組合成一個字符串
獲取count事件的頻率（可選）

如果需要

要想關掉hooks，只需要不帶參數地調用sethook即可。

例如：

最簡單的trace，僅僅打印每條執行語句的行號：

debug.sethook(print, "l")

顯示結果如下：

line 136
line    113
line    76
line    77
line    113
line    118

我們也可以自定義一個handler，傳入第一個參數，通過debug庫的getinfo獲取正在執行的代碼文件路徑：

debug.sethook(function (event, line)
    print(debug.getinfo(2).short_src .. ":" .. line)
end, "l")

顯示結果如下：

/usr/local/share/xmake/core/base/path.lua:46
/usr/local/share/xmake/core/base/path.lua:47
/usr/local/share/xmake/core/base/path.lua:56
/usr/local/share/xmake/core/base/string.lua:32
/usr/local/share/xmake/core/base/string.lua:33
/usr/local/share/xmake/core/base/string.lua:34
/usr/local/share/xmake/core/base/string.lua:35
/usr/local/share/xmake/core/base/string.lua:36
/usr/local/share/xmake/core/base/string.lua:38
/usr/local/share/xmake/core/base/string.lua:33

如果需要禁用之前的hook，只需要調用：

debug.sethook()

profiler性能分析器的實現

實現一個profiler類，通過下面的方式進行記錄：

-- 開始記錄
profiler.start()

-- TODO
-- ...

-- 結束記錄
profiler.stop()

相關實現代碼如下：

-- start profiling
function profiler:start(mode)

    -- 初始化報告
    self._REPORTS           = {}
    self._REPORTS_BY_TITLE  = {}

    -- 記錄開始時間
    self._STARTIME = os.clock()

    -- 開始hook，注冊handler，記錄call和return事件
    debug.sethook(profiler._profiling_handler, 'cr', 0)
end

-- stop profiling
function profiler:stop(mode)

    -- 記錄結束時間
    self._STOPTIME = os.clock()

    -- 停止hook
    debug.sethook()

    -- 記錄總耗時
    local totaltime = self._STOPTIME - self._STARTIME

    -- 排序報告
    table.sort(self._REPORTS, function(a, b)
        return a.totaltime > b.totaltime
    end)

    -- 格式化報告輸出
    for _, report in ipairs(self._REPORTS) do

        -- calculate percent
        local percent = (report.totaltime / totaltime) * 100
        if percent < 1 then
            break
        end

        -- trace
        utils.print("%6.3f, %6.2f%%, %7d, %s", report.totaltime, percent, report.callcount, report.title)
    end
end

實現很簡單，主要就是記錄開始和結束時間，然后排序下最終的報表，進行格式化打印輸出。

其中，計時函數使用了 os.clock 接口，返回一個程序使用CPU時間的一個近似值，不是毫秒哦，我們這邊僅僅是為了分析性能瓶頸。

就算不獲取精確毫秒數，也是可以的（其實用毫秒也沒什么意義，這種debug.sethook的方式原本就不是很精確），只要通過耗時占比就可以分析。

接下來，就是handler函數中，對call和return事件，進行分別處理，累計每個函數的調用總時間，調用總次數。

-- profiling call
function profiler:_profiling_call(funcinfo)

    -- 獲取當前函數對應的報告，如果不存在則初始化下
    local report = self:_func_report(funcinfo)
    assert(report)

    -- 記錄這個函數的起始調用事件
    report.calltime    = os.clock()

    -- 累加這個函數的調用次數
    report.callcount   = report.callcount + 1

end

-- profiling return
function profiler:_profiling_return(funcinfo)

    -- 記錄這個函數的返回時間
    local stoptime = os.clock()

    -- 獲取當前函數的報告
    local report = self:_func_report(funcinfo)
    assert(report)

    -- 計算和累加當前函數的調用總時間
    if report.calltime and report.calltime > 0 then
        report.totaltime = report.totaltime + (stoptime - report.calltime)
        report.calltime = 0
    end
end

-- the profiling handler
function profiler._profiling_handler(hooktype)

    -- 獲取當前函數信息
    local funcinfo = debug.getinfo(2, 'nS')

    -- 根據事件類型，分別處理 
    if hooktype == "call" then
        profiler:_profiling_call(funcinfo)
    elseif hooktype == "return" then
        profiler:_profiling_return(funcinfo)
    end
end

簡單吧，最后就是通過函數，獲取指定的報告了，這個就不多說了，簡單貼下代碼吧：

-- get the function title
function profiler:_func_title(funcinfo)

    -- check
    assert(funcinfo)

    -- the function name
    local name = funcinfo.name or 'anonymous'

    -- the function line
    local line = string.format("%d", funcinfo.linedefined or 0)

    -- the function source
    local source = funcinfo.short_src or 'C_FUNC'
    if os.isfile(source) then
        source = path.relative(source, xmake._PROGRAM_DIR)
    end

    -- make title
    return string.format("%-30s: %s: %s", name, source, line)
end

-- get the function report
function profiler:_func_report(funcinfo)

    -- get the function title
    local title = self:_func_title(funcinfo)

    -- get the function report
    local report = self._REPORTS_BY_TITLE[title]
    if not report then

        -- init report
        report = 
        {
            title       = self:_func_title(funcinfo)
        ,   callcount   = 0
        ,   totaltime   = 0
        }

        -- save it
        self._REPORTS_BY_TITLE[title] = report
        table.insert(self._REPORTS, report)
    end

    -- ok?
    return report
end

需要注意的是，通過debug.sethook的方式，進行hook計時本身也是有性能損耗的，因此不可能完全精確，如果改用c實現也許會好些。

不過，對于平常的性能瓶頸分析，應該夠用了。。

結語

這里只是一個簡單的例子，稍微擴展下，還是可以實現lua腳本的api實時調用追蹤（也就是trace）。

最后，如果大家想快速體驗下這個profiler的效果，可以直接運行xmake：

xmake --profile

這個 --profile 是給xmake調試分析的時候使用，一般也就我自己用用，發現某些xmake操作很慢，想要查找問題原因的時候，不需要改代碼，只需要快速的加上這個參數，重跑下就行了。。

順帶的提下，xmake另外兩個調試相關的參數：

-v/--verbose ：顯示詳細輸出信息，編譯時還會顯示詳細警告信息。
--backtrace ：出錯的時候，顯示詳細棧信息，用于快速issues反饋，輔助定位問題。

lua的debug庫還是非常強大的，有興趣的同學可以進一步去挖掘debug的各種特性哦。

來自：http://www.tboox.org/cn/2017/01/12/lua-profiler/

本文由用戶 AlbaMacghey 自行上傳分享，僅供網友學習交流。所有權歸原作者，若您的權利被侵害，請聯系管理員。

轉載本站原創文章，請注明出處，并保留原始鏈接、圖片水印。

本站是一個以用戶分享為主的開源技術平臺，歡迎各類分享！

本文地址：http://www.baiduhome.net/lib/view/open1484537109086.html

Lua 性能分析 Lua開發 xmake

利用debug庫實現對lua的性能分析

相關經驗

相關資訊

相關文檔

目錄