標籤：

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

01-31

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

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

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

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

debug.sethook簡介

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

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

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

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

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

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

如果需要

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

例如：

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

debug.sethook(print, "l")n

顯示結果如下：

linet136nlinet113nlinet76nlinet77nlinet113nlinet118n

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

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

顯示結果如下：

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

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

debug.sethook()n

profiler性能分析器的實現

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

-- 開始記錄nprofiler.start()nn-- TODOn-- ...nn-- 結束記錄nprofiler.stop()n

相關實現代碼如下：

-- start profilingnfunction profiler:start(mode)nn -- 初始化報告n self._REPORTS = {}n self._REPORTS_BY_TITLE = {}nn -- 記錄開始時間n self._STARTIME = os.clock()nn -- 開始hook，註冊handler，記錄call和return事件n debug.sethook(profiler._profiling_handler, cr, 0)nendnn-- stop profilingnfunction profiler:stop(mode)nn -- 記錄結束時間n self._STOPTIME = os.clock()nn -- 停止hookn debug.sethook()nn -- 記錄總耗時n local totaltime = self._STOPTIME - self._STARTIMEnn -- 排序報告n table.sort(self._REPORTS, function(a, b)n return a.totaltime > b.totaltimen end)nn -- 格式化報告輸出n for _, report in ipairs(self._REPORTS) don n -- calculate percentn local percent = (report.totaltime / totaltime) * 100n if percent < 1 thenn breakn endnn -- tracen utils.print("%6.3f, %6.2f%%, %7d, %s", report.totaltime, percent, report.callcount, report.title)n endnendn

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

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

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

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

-- profiling callnfunction profiler:_profiling_call(funcinfo)nn -- 獲取當前函數對應的報告，如果不存在則初始化下n local report = self:_func_report(funcinfo)n assert(report)nn -- 記錄這個函數的起始調用事件n report.calltime = os.clock()nn -- 累加這個函數的調用次數n report.callcount = report.callcount + 1nnendnn-- profiling returnnfunction profiler:_profiling_return(funcinfo)nn -- 記錄這個函數的返回時間n local stoptime = os.clock()nn -- 獲取當前函數的報告n local report = self:_func_report(funcinfo)n assert(report)nn -- 計算和累加當前函數的調用總時間n if report.calltime and report.calltime > 0 thennttreport.totaltime = report.totaltime + (stoptime - report.calltime)n report.calltime = 0ntendnendnn-- the profiling handlernfunction profiler._profiling_handler(hooktype)nn -- 獲取當前函數信息n local funcinfo = debug.getinfo(2, nS)nn -- 根據事件類型，分別處理 n if hooktype == "call" thenn profiler:_profiling_call(funcinfo)n elseif hooktype == "return" thenn profiler:_profiling_return(funcinfo)n endnendn

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

-- get the function titlenfunction profiler:_func_title(funcinfo)nn -- checkn assert(funcinfo)nn -- the function namen local name = funcinfo.name or anonymousnn -- the function linen local line = string.format("%d", funcinfo.linedefined or 0)nn -- the function sourcen local source = funcinfo.short_src or C_FUNCn if os.isfile(source) thenn source = path.relative(source, xmake._PROGRAM_DIR)n endnn -- make titlen return string.format("%-30s: %s: %s", name, source, line)nendnn-- get the function reportnfunction profiler:_func_report(funcinfo)nn -- get the function titlen local title = self:_func_title(funcinfo)nn -- get the function reportn local report = self._REPORTS_BY_TITLE[title]n if not report thenn n -- init reportn report = n {n title = self:_func_title(funcinfo)n , callcount = 0n , totaltime = 0n }nn -- save itn self._REPORTS_BY_TITLE[title] = reportn table.insert(self._REPORTS, report)n endnn -- ok?n return reportnendn

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

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

結語

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

完整代碼，可以到xmake的源碼中翻看：profiler代碼

裡面除了性能分析，trace調用也有實現。

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

xmake --profilen

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

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

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

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

------------------------------------

個人主頁：TBOOX開源工程

原文出處：tboox.org/cn/2017/01/12


推薦閱讀：

※Makefile 與 IDE 相比效率高在哪？
※makefile中的通配符使用？
※make makefile cmake qmake都是什麼，有什麼區別？

TAG:Lua | 性能分析 | Makefile |