注:本文例子使用的是luajit2.0.5版本,原生lua版本可能有差异,但差异不大。
写在前面:
lua性能分析PepperfishProfiler挺好用的,主要灵活,分析的数据也清晰,有嵌套调用的耗时信息。
其他lua分析工具也可见。
本脚本的基于PepperfishProfiler做修改的。
为什么需要修改:
复杂的lua逻辑导致PepperfishProfiler分析结果不准确,
原因:lua的debug.sethook(hook_call, "cr" )的call和return没对应导致。而PepperfishProfiler没对这些情况做处理。
具体如图
注意FunD函数返回一个函数,导致debug信息中line:797函数名与代码中不一致,且return时只有一个FunD:797,其实是return了FunC,丢失的return FunD。
正文:
本工具的所有修改都是为了解决这个问题0.0。
本工具只适用于Call模式的分析。
对原工具的输出数据做了优化。
先上代码
--[[
Example usage:
profiler = newProfiler(false)
profiler:start()
< call some functions that take time >
profiler:stop()
local outfile = io.open( "profile.txt", "w+" )
profiler:report( outfile )
outfile:close()
--]]
--
-- All profiler related stuff is stored in the top level table '_profiler'
--
_profiler = {}
--
-- newProfiler() creates a new profiler object for managing
-- the profiler and storing state. Note that only one profiler
-- object can be executing at one time.
--
function newProfiler(bRecordCFun)
if _profiler.running then
print("Profiler already running.")
return
end
local newprof = {}
for k,v in pairs(_profiler) do
newprof[k] = v
end
newprof.variant = "call"
newprof.bRecordCFun = bRecordCFun==nil and true or false; --记录C方法
return newprof
end
--
-- This function starts the profiler. It will do nothing
-- if this (or any other) profiler is already running.
--
function _profiler.start(self)
if _profiler.running then
return
end
-- Start the profiler. This begins by setting up internal profiler state
_profiler.running = self
self.rawstats = {}
self.callstack = {}
self.currPos_ar = nil; --定位当前执行函数
self.cache_lineInfo = {};
self.cache_startTime = os.clock();
self.lineProfiler_cost_time = 0;
debug.sethook( _profiler_hook_wrapper_by_call, "crl" )
end
--
-- This function stops the profiler. It will do nothing
-- if a profiler is not running, and nothing if it isn't
-- the currently running profiler.
--
function _profiler.stop(self)
if _profiler.running ~= self then
return
end
-- Stop the profiler.
debug.sethook( nil )
_profiler.running = nil
CppLog("[all profiler time]"..os.clock()-self.cache_startTime.."ms")
-- CppLog("[lineProfiler_cost_time]"..self.lineProfiler_cost_time.."ms")
end
--
-- Simple wrapper to handle the hook. You should not
-- be calling this directly. Duplicated to reduce overhead.
--
function _profiler_hook_wrapper_by_call(action)
if _profiler.running == nil then
debug.sethook( nil )
end
_profiler.running:_internal_profile_by_call(action)
end
--
-- This is the main by-function-call function of the profiler and should not
-- be called except by the hook wrapper
--
function _profiler._internal_profile_by_call(self,action)
-- Since we can obtain the 'function' for the item we've had call us, we
-- can use that...
local caller_info = debug.getinfo( 3 )
if caller_info == nil then
print "No caller_info"
return
end
if self.bRecordCFun == false and caller_info.what == "C" then
return;
end
self.profile_start_Time = os.clock();
--[[
caller_info:
table: 0x00472a38 = {
["linedefined"] = 797,
["currentline"] = 797,
["func"] = function: 0x0013dd50,
["isvararg"] = false,
["namewhat"] = "global"
["lastlinedefined"] = 799,
["source"] = "@GamePlay\ServerEntry.lua"
["nups"] = 0,
["what"] = "Lua"
["nparams"] = 0,
["name"] = "zxjFunD"
["short_src"] = "GamePlay\ServerEntry.lua"
}
call return 不一致测试:
function zxjFunA()
for i = 1, 100000, 1 do
local a = {}
end
end
function zxjFunB()
for i = 1, 100000, 1 do
local a = {}
end
zxjFunA()
end
function zxjFunC()
zxjFunB()
end
function zxjFunD()
for i = 1, 100000, 1 do
local a = {}
end
return zxjFunC() --直接return fun 会导致return 不一致
end
function zxjFunE()
zxjFunD();
end
call: zxjFunE();
结果:
[CppLog] Call callTimesss:1 func:function: 0x00b6a598 linedefined:806 funName:zxjFunE
[CppLog]
[CppLog] Call callTimesss:2 func:function: 0x00b6a580 linedefined:800 funName:zxjFunD
[CppLog]
[CppLog] Call callTimesss:3 func:function: 0x00b6a568 linedefined:797 funName:zxjFunD --此处call 的funName其实应该是zxjFunC
[CppLog]
[CppLog] Call callTimesss:4 func:function: 0x00b6a550 linedefined:791 funName:zxjFunB
[CppLog]
[CppLog] Call callTimesss:5 func:function: 0x00b6a538 linedefined:786 funName:zxjFunA
[CppLog]
[CppLog] Return callTimesss:5 func:function: 0x00b6a538 linedefined:786 funName:zxjFunA
[CppLog]
[CppLog] Return callTimesss:4 func:function: 0x00b6a550 linedefined:791 funName:zxjFunB
[CppLog]
[CppLog] Return callTimesss:3 func:function: 0x00b6a568 linedefined:797 funName:zxjFunD --缺少一次return 本次return其实是zxjFunC
[CppLog]
[CppLog] Return callTimesss:2 func:function: 0x00b6a598 linedefined:806 funName:zxjFunE
]]
if action == "line" then
self.cache_lineInfo.source = caller_info.source; --记录最近一次逐行调用信息
self.cache_lineInfo.line = caller_info.currentline;
self.lineProfiler_cost_time = self.lineProfiler_cost_time + os.clock() - self.profile_start_Time;
return;
end
CppLog("")
-- CppLog(action.." name:"..caller_info.source.." "..caller_info.name..caller_info.linedefined.." currentline:"..caller_info.currentline)
CppLog(action.." name:"..caller_info.name.." :"..caller_info.linedefined)
if action == "call" then
-- CppLog("[cache_lineInfo] source:"..self.cache_lineInfo.source.. " line:"..self.cache_lineInfo.line);
-- add line profiler cost time to currPos_ar
if nil ~= self.currPos_ar then
self.currPos_ar.line_cost_time = self.currPos_ar.line_cost_time + self.lineProfiler_cost_time;
self.lineProfiler_cost_time = 0;
end
-- TO: get realy parent function for this call
-- 判定call的位置是否当前定位函数的内部
--[[
当前记录的执行函数不一定时此次call的父函数的原因: call和return的不一致
eg:
fun A() B(); return 0; end
fun B() return C() end
fun C() return 0; end
A();
call A,
call B,
call C,
return C,
return A,
加入D函数:
fun A() B(); D();return 0; end
fun B() return C() end
fun C() return 0; end
fun D() return 0; end
A();
call A,
call B,
call C,
return C,
no return B,
call D,
没执行该处理,则 D 的父函数视为B,但实际情况D的父函数可以为A
]]
while nil ~= self.currPos_ar and
(self.cache_lineInfo.source ~= self.currPos_ar.source or
(self.cache_lineInfo.line < self.currPos_ar.linedefined or
self.cache_lineInfo.line > self.currPos_ar.lastlinedefined)) do
self:_one_fun_return(self.currPos_ar.caller_info);
end
local latest_ar = self.currPos_ar
-- Are we allowed to profile this function?
local should_not_profile = 0
for k,v in pairs(self.prevented_functions) do
if k == caller_info.func then
should_not_profile = v
end
end
-- Also check the top activation record...
if latest_ar then
if latest_ar.should_not_profile == 2 then
should_not_profile = 2
end
end
-- if latest_ar then
-- CppLog("[parent]name:"..latest_ar.fun_name..latest_ar.linedefined);
-- end
-- Making a call...
local this_ar = {}
this_ar.should_not_profile = should_not_profile
this_ar.parent_ar = latest_ar
this_ar.anon_child = 0
this_ar.name_child = 0
this_ar.children = {}
this_ar.children_time = {}
this_ar.clock_start = self.profile_start_Time
this_ar.func = caller_info.func;
this_ar.source = caller_info.source;
this_ar.linedefined = caller_info.linedefined;
this_ar.lastlinedefined = caller_info.lastlinedefined;
this_ar.fun_name = caller_info.name or tostring(caller_info.func);
this_ar.caller_info = caller_info;
this_ar.line_cost_time = 0; --行分析消耗时间
-- Last thing to do on a call is to insert this onto the ar stack...
table.insert( self.callstack, this_ar )
-- CppLog("len:"..#self.callstack)
--fun call update currpos
self.currPos_ar = this_ar;
-- CppLog("[setCurPos2] name:"..self.currPos_ar.fun_name..self.currPos_ar.linedefined.."["..self.currPos_ar.linedefined..","..self.currPos_ar.lastlinedefined.."] source:"..self.currPos_ar.source)
this_ar.proflier_time = os.clock() - self.profile_start_Time; --call 的分析消耗时间
-- CppLog(this_ar.fun_name..this_ar.linedefined.." proflier_time:"..this_ar.proflier_time);
elseif action == "return" then
-- add line profiler cost time to currPos_ar
if nil ~= self.currPos_ar then
self.currPos_ar.line_cost_time = self.currPos_ar.line_cost_time + self.lineProfiler_cost_time;
self.lineProfiler_cost_time = 0;
end
-- 因为call return 不一致
-- 需要将跳过的return做计算
for i = #self.callstack, 1, -1 do
local this_ar = self.callstack[i];
self:_one_fun_return(this_ar.caller_info);
if this_ar.func == caller_info.func or this_ar.linedefined == caller_info.linedefined then
break;
end
end
end
end
function _profiler._one_fun_return(self,caller_info)
if #self.callstack <= 0 then
return;
end
local profile_return_start_Time = self.profile_start_Time;
local this_ar = table.remove(self.callstack,#self.callstack);
this_ar.clock_end = self.profile_start_Time
this_ar.this_time = this_ar.clock_end - this_ar.clock_start
- this_ar.proflier_time --减去自身call 和子函数call、return 的分析消耗时间
- this_ar.line_cost_time --减去自身函数内部的逐行分析消耗时间
-- CppLog("[one_fun_return]name:"..this_ar.fun_name..this_ar.linedefined)
-- Now, if we have a parent, update its call info...
if this_ar.parent_ar then
-- CppLog("[parent]name:"..this_ar.parent_ar.fun_name..this_ar.parent_ar.linedefined)
local funcStrKey = this_ar.fun_name.."_"..this_ar.linedefined;
this_ar.parent_ar.children[funcStrKey] =
(this_ar.parent_ar.children[funcStrKey] or 0) + 1
this_ar.parent_ar.children_time[funcStrKey] =
(this_ar.parent_ar.children_time[funcStrKey] or 0 ) +
this_ar.this_time
if this_ar.fun_name == nil then
this_ar.parent_ar.anon_child =
this_ar.parent_ar.anon_child + this_ar.this_time
else
this_ar.parent_ar.name_child =
this_ar.parent_ar.name_child + this_ar.this_time
end
end
-- Now if we're meant to record information about ourselves, do so...
if this_ar.should_not_profile == 0 then
local inforec = self:_get_func_rec(this_ar.fun_name,this_ar.linedefined,this_ar.func)
inforec.count = inforec.count + 1
inforec.time = inforec.time + this_ar.this_time
inforec.anon_child_time = inforec.anon_child_time + this_ar.anon_child
inforec.name_child_time = inforec.name_child_time + this_ar.name_child
inforec.func_info = this_ar.caller_info
inforec.parent_info = ""
if this_ar.parent_ar then
inforec.parent_info = this_ar.parent_ar.source.." ["..this_ar.parent_ar.fun_name.."]:"..this_ar.parent_ar.linedefined
end
for k,v in pairs(this_ar.children) do
inforec.children[k] = (inforec.children[k] or 0) + v
inforec.children_time[k] =
(inforec.children_time[k] or 0) + this_ar.children_time[k]
end
end
-- CppLog(this_ar.fun_name..this_ar.linedefined.." this_time:"..this_ar.this_time.." proflier_time:"..this_ar.proflier_time);
if this_ar.parent_ar then
local nowTime = os.clock();
this_ar.parent_ar.proflier_time = this_ar.parent_ar.proflier_time
+ this_ar.proflier_time --子函数调用的分析消耗
+ (nowTime - profile_return_start_Time) --这次 return 的分析耗时
this_ar.parent_ar.line_cost_time = this_ar.parent_ar.line_cost_time + this_ar.line_cost_time --传递子函数的逐行分析耗时
self.profile_start_Time = nowTime; --避免重复计算消耗
-- CppLog("[parent]"..this_ar.parent_ar.fun_name..this_ar.parent_ar.linedefined.." proflier_time:"..this_ar.parent_ar.proflier_time);
end
--fun return update currpos
self.currPos_ar = self.callstack[#self.callstack];
-- if self.currPos_ar then
-- CppLog("[setCurPos1] name:"..self.currPos_ar.fun_name..self.currPos_ar.linedefined.."["..self.currPos_ar.linedefined..","..self.currPos_ar.lastlinedefined.."] source:"..self.currPos_ar.source)
-- end
end
function _profiler._get_func_rec(self,funName,linedefined,func)
-- Find the function ref for 'func' (if force and not present, create one)
local ret = self.rawstats[funName.."_"..linedefined]
if ret == nil then
-- Build a new function statistics table
ret = {}
ret.func = func
ret.count = 0
ret.time = 0
ret.anon_child_time = 0
ret.name_child_time = 0
ret.children = {}
ret.children_time = {}
self.rawstats[funName.."_"..linedefined] = ret
end
return ret
end
--
-- This writes a profile report to the output file object. If
-- sort_by_total_time is nil or false the output is sorted by
-- the function time minus the time in it's children.
--
function _profiler.report( self, outfile, sort_by_total_time )
-- table_print(self.rawstats)
outfile:write
[[Lua Profile output created by profiler.lua. Copyright Pepperfish 2002+
]]
-- This is pretty awful.
local terms = {}
if self.variant == "time" then
terms.capitalized = "Sample"
terms.single = "sample"
terms.pastverb = "sampled"
elseif self.variant == "call" then
terms.capitalized = "Call"
terms.single = "call"
terms.pastverb = "called"
else
assert(false)
end
local total_time = 0
local ordering = {}
for func,record in pairs(self.rawstats) do
table.insert(ordering, func)
end
if sort_by_total_time then
table.sort( ordering,
function(a,b) return self.rawstats[a].time > self.rawstats[b].time end
)
else
table.sort( ordering,
function(a,b)
local arec = self.rawstats[a]
local brec = self.rawstats[b]
local atime = arec.time - (arec.anon_child_time + arec.name_child_time)
local btime = brec.time - (brec.anon_child_time + brec.name_child_time)
return atime > btime
end
)
end
for i=1,table.getn(ordering) do
local func = ordering[i]
local record = self.rawstats[func]
local thisfuncname = " " .. self:_pretty_name(func,true) .. " "
-- if string.len( thisfuncname ) < 42 then
-- thisfuncname =
-- string.rep( "-", (42 - string.len(thisfuncname))/2 ) .. thisfuncname
-- thisfuncname =
-- thisfuncname .. string.rep( "-", 42 - string.len(thisfuncname) )
-- end
total_time = total_time + ( record.time - ( record.anon_child_time +
record.name_child_time ) )
outfile:write( "No."..i..string.rep( "-", 19 ) .. thisfuncname .. " [parent]" .. record.parent_info ..
string.rep( "-", 19 ) .. "\n" )
outfile:write( terms.capitalized.." count: " ..
string.format( "%4d", record.count ) .. "\n" )
outfile:write( "Time spend total: " ..
string.format( "%4.3f", record.time ) .. "ms\n" )
outfile:write( "Time spent in children: " ..
string.format("%4.3f",record.anon_child_time+record.name_child_time) ..
"ms\n" )
local timeinself =
record.time - (record.anon_child_time + record.name_child_time)
outfile:write( "Time spent in self: " ..
string.format("%4.3f", timeinself) .. "ms\n" )
outfile:write( "Time spent per " .. terms.single .. ": " ..
string.format("%4.5f", record.time/record.count) ..
"ms/" .. terms.single .. "\n" )
outfile:write( "Time spent in self per "..terms.single..": " ..
string.format( "%4.5f", timeinself/record.count ) .. "ms/" ..
terms.single.."\n" )
-- Report on each child in the form
-- Child <funcname> called n times and took a.bs
local added_blank = 0
local childrenlist = {}
for k,v in pairs(record.children) do
if self.prevented_functions[k] == nil or
self.prevented_functions[k] == 0
then
-- if added_blank == 0 then
-- outfile:write( "\n" ) -- extra separation line
-- added_blank = 1
-- end
if record.children_time[k] ~= 0 then
local childrenInfo = {}
childrenInfo.str = "Child " .. self:_pretty_name(k) ..
string.rep( " ", 41-string.len(self:_pretty_name(k)) ) .. " " ..
terms.pastverb.." " .. string.format("%6d", v) .. " times. Took " ..
string.format("%4.2f", record.children_time[k] ) .. "ms\n"
childrenInfo.time = record.children_time[k];
table.insert(childrenlist,childrenInfo);
end
end
end
table.sort(childrenlist,function (a,b)
return a.time > b.time;
end)
outfile:write( "\n" )
for k, v in pairs(childrenlist) do
outfile:write(v.str);
end
outfile:write( "\n" ) -- extra separation line
outfile:flush()
end
outfile:write( "\n\n" )
outfile:write( "Total time spent in profiled functions: " ..
string.format("%5.3g",total_time) .. "s\n" )
outfile:write( [[
END
]] )
outfile:flush()
end
--
-- This writes the profile to the output file object as
-- loadable Lua source.
--
function _profiler.lua_report(self,outfile)
-- Purpose: Write out the entire raw state in a cross-referenceable form.
local ordering = {}
local functonum = {}
for func,record in pairs(self.rawstats) do
table.insert(ordering, func)
functonum[func] = table.getn(ordering)
end
outfile:write(
"-- Profile generated by profiler.lua Copyright Pepperfish 2002+\n\n" )
outfile:write( "-- Function names\nfuncnames = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
outfile:write( "funcnames[" .. i .. "] = " ..
string.format("%q", self:_pretty_name(thisfunc)) .. "\n" )
end
outfile:write( "\n" )
outfile:write( "-- Function times\nfunctimes = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "functimes[" .. i .. "] = { " )
outfile:write( "tot=" .. record.time .. ", " )
outfile:write( "achild=" .. record.anon_child_time .. ", " )
outfile:write( "nchild=" .. record.name_child_time .. ", " )
outfile:write( "count=" .. record.count .. " }\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child links\nchildren = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "children[" .. i .. "] = { " )
for k,v in pairs(record.children) do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( functonum[k] .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child call counts\nchildcounts = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "children[" .. i .. "] = { " )
for k,v in record.children do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( v .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child call time\nchildtimes = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc];
outfile:write( "children[" .. i .. "] = { " )
for k,v in pairs(record.children) do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( record.children_time[k] .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n\n-- That is all.\n\n" )
outfile:flush()
end
-- Internal function to calculate a pretty name for the profile output
function _profiler._pretty_name(self,func,bTitle)
-- Only the data collected during the actual
-- run seems to be correct.... why?
local info = self.rawstats[ func ].func_info
-- local info = debug.getinfo( func )
local name = ""
if info.what == "Lua" then
name = "L:"
end
if info.what == "C" then
name = "C:"
end
if info.what == "main" then
name = " :"
end
if info.name == nil then
name = name .. "<"..tostring(func) .. ">"
else
name = name .. info.name
end
if info.source then
name = name .. "@" .. info.source
else
if info.what == "C" then
name = name .. "@?"
else
name = name .. "@<string>"
end
end
name = name .. ":"
if info.what == "C" then
name = name .. "?"
else
name = name .. info.linedefined
end
if bTitle then
name = name .. " Root"
end
if info.name then
name = name .." Fun:"..info.name;
end
return name
end
--
-- This allows you to specify functions which you do
-- not want profiled. Setting level to 1 keeps the
-- function from being profiled. Setting level to 2
-- keeps both the function and its children from
-- being profiled.
--
-- BUG: 2 will probably act exactly like 1 in "time" mode.
-- If anyone cares, let me (zorba) know and it can be fixed.
--
function _profiler.prevent(self, func, level)
self.prevented_functions[func] = (level or 1)
end
_profiler.prevented_functions = {
[_profiler.start] = 2,
[_profiler.stop] = 2,
[_profiler._internal_profile_by_call] = 2,
[_profiler_hook_wrapper_by_call] = 2,
[_profiler.prevent] = 2,
[_profiler._get_func_rec] = 2,
[_profiler.report] = 2,
[_profiler.lua_report] = 2,
[_profiler._pretty_name] = 2,
}
local function _list_table(tb, table_list, level)
local ret = ""
local indent = string.rep(" ", level*4)
for k, v in pairs(tb) do
local quo = type(k) == "string" and "\"" or ""
ret = ret .. indent .. "[" .. quo .. tostring(k) .. quo .. "] = "
if type(v) == "table" then
local t_name = table_list[v]
if t_name then
ret = ret .. tostring(v) .. " -- > [\"" .. t_name .. "\"]\n"
else
table_list[v] = tostring(k)
ret = ret .. "{\n"
ret = ret .. _list_table(v, table_list, level+1)
ret = ret .. indent .. "}\n"
end
elseif type(v) == "string" then
ret = ret .. "\"" .. tostring(v) .. "\"\n"
else
ret = ret .. tostring(v) .. ",\n"
end
end
local mt = getmetatable(tb)
if mt then
ret = ret .. "\n"
local t_name = table_list[mt]
ret = ret .. indent .. "<metatable> = "
if t_name then
ret = ret .. tostring(mt) .. " -- > [\"" .. t_name .. "\"]\n"
else
ret = ret .. "{\n"
ret = ret .. _list_table(mt, table_list, level+1)
ret = ret .. indent .. "}\n"
end
end
return ret
end
-------------------------------------------------------------------
-- Public functions
-------------------------------------------------------------------
function table_tostring(tb)
--print("table_tostring")
if type(tb) ~= "table" then
print("Sorry, it's not table, it is " .. type(tb) .. ".","table_Print")
end
local ret = " = {\n"
local table_list = {}
table_list[tb] = "root table"
ret = ret .. _list_table(tb, table_list, 1)
ret = ret .. "}"
return ret
end
function table_print(tb)
if tb == nil then
print("table_Print {}","table_Print")
return
end
if CppLog then
CppLog(tostring(tb) .. table_tostring(tb))
end
-- print(tostring(tb) .. table_tostring(tb))
end
主要对_internal_profile_by_call做了修改,
增加逐行勾子(测试逐行监听只会增加小量的时间消耗),
增加了定位当前执行函数 currPos_ar ,为了准确定位函数调用的嵌套关系,
增加了call、return、line分析的耗时记录,减少因分析带来的时间消耗影响分析结果,但无法做到全部消耗时间剔除,数据结果的时间值只适用于耗时比例分析,无法做为时间的运行时间。
修改_get_func_rec的匹配条件
注:毫秒单位其实有点大,建议重写os.clock 返回微妙,提供准确性
注:CppLog 是自己封装的log,其实就是print
注释已经写了一些调试信息和思路,这里做一些补充:
1.为什么要增加逐行勾子:
为了记录call的最后一次行数调用的信息cache_lineInfo,可以确定ache_lineInfo一定是本次call的父函数,
根据这个信息和调用堆栈callstack,可以找到本次call的父函数,并且能确定该父函数前的其他堆栈函数已经执行结束,但是没有返回return勾子,所以将这些行数做为return处理。
2.call 、return 都有_one_fun_return操作
记录的执行函数 currPos_ar 每次call是前移到当前call上,同时调用堆栈callstack Add,
return时后退,同时调用堆栈callstack Remove。
在return丢失,我们当前记录的执行函数 currPos_ar和调用堆栈callstack其实不准确(少后退和少移除),
return丢失后的下一次操作可以是call和return,所以都要做执行函数 currPos_ar 校准操作,将少后退的数据做return处理。
(1、2条其实做同一件事)
结束:
脚本经过我的反复调试和修改,不那么美观,也懒得整理,希望帮助到你
结果展示:
找到你report的文件位置,打开会看到如图:
还是不错的
---------------------------------------2021.5.7----------------------
使用一段时间后,对脚本做了修改优化
--[[
Example usage:
profiler = newProfiler(false)
profiler:start()
< call some functions that take time >
profiler:stop()
local outfile = io.open( "profile.txt", "w+" )
profiler:report( outfile )
outfile:close()
--]]
--
-- All profiler related stuff is stored in the top level table '_profiler'
--
_profiler = {}
local bZLog = false; --zLog 是否打印
local bCppLogWrite = false; --CppLog 打印是否写文件
local cppLogWriteOutPath = "PepperfishProfiler_CppLog.txt"
---tool fun
local table_print,CppLogInit,zLog,CppLogEnd,_CppLog;
--
-- newProfiler() creates a new profiler object for managing
-- the profiler and storing state. Note that only one profiler
-- object can be executing at one time.
--
function newProfiler(bRecordCFun)
if _profiler.running then
print("Profiler already running.")
return
end
local newprof = {}
for k,v in pairs(_profiler) do
newprof[k] = v
end
newprof.variant = "call"
newprof.bRecordCFun = bRecordCFun==nil and true or false; --记录C方法
return newprof
end
--
-- This function starts the profiler. It will do nothing
-- if this (or any other) profiler is already running.
--
function _profiler.start(self)
if _profiler.running then
return
end
-- Start the profiler. This begins by setting up internal profiler state
_profiler.running = self
self.rawstats = {}
self.callstack = {}
self.currPos_ar = nil; --定位当前执行函数
self.cache_lineInfo = {};
self.cache_startTime = os.clock();
self.lineProfiler_cost_time = 0;
self.all_profile_cost_Time = 0;
debug.sethook( _profiler_hook_wrapper_by_call, "crl" )
if bCppLogWrite then
CppLogInit();
end
end
--
-- This function stops the profiler. It will do nothing
-- if a profiler is not running, and nothing if it isn't
-- the currently running profiler.
--
function _profiler.stop(self)
if _profiler.running ~= self then
return
end
-- Stop the profiler.
debug.sethook( nil )
_profiler.running = nil
CppLog("[all profiler time]"..os.clock()-self.cache_startTime.."ms")
CppLog("[all_profile_cost_Time] "..self.all_profile_cost_Time);
-- CppLog("[lineProfiler_cost_time]"..self.lineProfiler_cost_time.."ms")
end
--
-- Simple wrapper to handle the hook. You should not
-- be calling this directly. Duplicated to reduce overhead.
--
function _profiler_hook_wrapper_by_call(action)
if _profiler.running == nil then
debug.sethook( nil )
end
_profiler.running.profile_start_Time = os.clock();
local t = os.clock();
_profiler.running:_internal_profile_by_call(action)
_profiler.running.all_profile_cost_Time = _profiler.running.all_profile_cost_Time + os.clock() - t;
end
--
-- This is the main by-function-call function of the profiler and should not
-- be called except by the hook wrapper
--
function _profiler._internal_profile_by_call(self,action)
-- Since we can obtain the 'function' for the item we've had call us, we
-- can use that...
local caller_info = debug.getinfo( 3 )
if caller_info == nil then
print "No caller_info"
self.lineProfiler_cost_time = self.lineProfiler_cost_time + os.clock() - self.profile_start_Time;
return
end
if self.bRecordCFun == false and caller_info.what == "C" then
self.lineProfiler_cost_time = self.lineProfiler_cost_time + os.clock() - self.profile_start_Time;
return;
end
if caller_info.name == nil then
-- 这种情况太复杂,暂时忽略
self.lineProfiler_cost_time = self.lineProfiler_cost_time + os.clock() - self.profile_start_Time;
return;
end
--[[
caller_info:
table: 0x00472a38 = {
["linedefined"] = 797,
["currentline"] = 797,
["func"] = function: 0x0013dd50,
["isvararg"] = false,
["namewhat"] = "global"
["lastlinedefined"] = 799,
["source"] = "@GamePlay\ServerEntry.lua"
["nups"] = 0,
["what"] = "Lua"
["nparams"] = 0,
["name"] = "zxjFunD"
["short_src"] = "GamePlay\ServerEntry.lua"
}
call return 不一致测试:
function zxjFunA()
for i = 1, 100000, 1 do
local a = {}
end
end
function zxjFunB()
for i = 1, 100000, 1 do
local a = {}
end
zxjFunA()
end
function zxjFunC()
zxjFunB()
end
function zxjFunD()
for i = 1, 100000, 1 do
local a = {}
end
return zxjFunC() --直接return fun 会导致return 不一致
end
function zxjFunE()
zxjFunD();
end
call: zxjFunE();
结果:
[CppLog] Call callTimesss:1 func:function: 0x00b6a598 linedefined:806 funName:zxjFunE
[CppLog]
[CppLog] Call callTimesss:2 func:function: 0x00b6a580 linedefined:800 funName:zxjFunD
[CppLog]
[CppLog] Call callTimesss:3 func:function: 0x00b6a568 linedefined:797 funName:zxjFunD --此处call 的funName其实应该是zxjFunC
[CppLog]
[CppLog] Call callTimesss:4 func:function: 0x00b6a550 linedefined:791 funName:zxjFunB
[CppLog]
[CppLog] Call callTimesss:5 func:function: 0x00b6a538 linedefined:786 funName:zxjFunA
[CppLog]
[CppLog] Return callTimesss:5 func:function: 0x00b6a538 linedefined:786 funName:zxjFunA
[CppLog]
[CppLog] Return callTimesss:4 func:function: 0x00b6a550 linedefined:791 funName:zxjFunB
[CppLog]
[CppLog] Return callTimesss:3 func:function: 0x00b6a568 linedefined:797 funName:zxjFunD --缺少一次return 本次return其实是zxjFunC
[CppLog]
[CppLog] Return callTimesss:2 func:function: 0x00b6a598 linedefined:806 funName:zxjFunE
]]
if action == "line" then
self.cache_lineInfo.source = caller_info.source; --记录最近一次逐行调用信息
self.cache_lineInfo.line = caller_info.currentline;
self.lineProfiler_cost_time = self.lineProfiler_cost_time + os.clock() - self.profile_start_Time;
return;
end
zLog("")
zLog(action.." name:"..caller_info.source.." "..caller_info.name..caller_info.linedefined.." currentline:"..caller_info.currentline)
if action == "call" then
zLog("[cache_lineInfo] source:"..self.cache_lineInfo.source.. " line:"..self.cache_lineInfo.line);
-- add line profiler cost time to currPos_ar
if nil ~= self.currPos_ar then
self.currPos_ar.line_cost_time = self.currPos_ar.line_cost_time + self.lineProfiler_cost_time;
self.lineProfiler_cost_time = 0;
end
-- TO: get realy parent function for this call
-- 判定call的位置是否当前定位函数的内部
--[[
当前记录的执行函数不一定时此次call的父函数的原因: call和return的不一致
eg:
fun A() B(); return 0; end
fun B() return C() end
fun C() return 0; end
A();
call A,
call B,
call C,
return C,
return A,
加入D函数:
fun A() B(); D();return 0; end
fun B() return C() end
fun C() return 0; end
fun D() return 0; end
A();
call A,
call B,
call C,
return C,
no return B,
call D,
没执行该处理,则 D 的父函数视为B,但实际情况D的父函数可以为A
]]
while nil ~= self.currPos_ar and
(self.cache_lineInfo.source ~= self.currPos_ar.source or
(self.cache_lineInfo.line < self.currPos_ar.linedefined or
self.cache_lineInfo.line > self.currPos_ar.lastlinedefined)) do
zLog("[cache_lineInfo Data] source:"..self.cache_lineInfo.source.." line:"..self.cache_lineInfo.line.."\n\t"..
"[currPos_ar Data:] source:"..self.currPos_ar.source.." linedefined:"..self.currPos_ar.linedefined.." lastlinedefined:"..self.currPos_ar.lastlinedefined)
self:_one_fun_return(self.currPos_ar.caller_info);
end
local latest_ar = self.currPos_ar
-- Are we allowed to profile this function?
local should_not_profile = 0
for k,v in pairs(self.prevented_functions) do
if k == caller_info.func then
should_not_profile = v
end
end
-- Also check the top activation record...
if latest_ar then
if latest_ar.should_not_profile == 2 then
should_not_profile = 2
end
end
if latest_ar then
zLog("[parent]name:"..latest_ar.fun_name..latest_ar.linedefined);
end
-- Making a call...
local this_ar = {}
this_ar.should_not_profile = should_not_profile
this_ar.parent_ar = latest_ar
this_ar.anon_child = 0
this_ar.name_child = 0
this_ar.children = {}
this_ar.children_time = {}
this_ar.clock_start = self.profile_start_Time
this_ar.func = caller_info.func;
this_ar.source = caller_info.source;
this_ar.linedefined = caller_info.linedefined;
this_ar.lastlinedefined = caller_info.lastlinedefined;
this_ar.fun_name = caller_info.name or tostring(caller_info.func);
this_ar.caller_info = caller_info;
this_ar.line_cost_time = 0; --行分析消耗时间
-- Last thing to do on a call is to insert this onto the ar stack...
table.insert( self.callstack, this_ar )
--fun call update currpos
self.currPos_ar = this_ar;
this_ar.proflier_time = os.clock() - self.profile_start_Time; --call 的分析消耗时间
elseif action == "return" then
-- add line profiler cost time to currPos_ar
if nil ~= self.currPos_ar then
self.currPos_ar.line_cost_time = self.currPos_ar.line_cost_time + self.lineProfiler_cost_time;
self.lineProfiler_cost_time = 0;
end
-- 因为call return 不一致
-- 需要将跳过的return做计算
for i = #self.callstack, 1, -1 do
local this_ar = self.callstack[i];
self:_one_fun_return(this_ar.caller_info);
if this_ar.func == caller_info.func or this_ar.linedefined == caller_info.linedefined then
break;
end
end
end
end
function _profiler._one_fun_return(self,caller_info)
if #self.callstack <= 0 then
return;
end
local profile_return_start_Time = self.profile_start_Time;
local this_ar = table.remove(self.callstack,#self.callstack);
this_ar.clock_end = self.profile_start_Time
this_ar.this_time = this_ar.clock_end - this_ar.clock_start
- this_ar.proflier_time --减去自身call 和子函数call、return 的分析消耗时间
- this_ar.line_cost_time --减去自身函数内部的逐行分析消耗时间
zLog("[one_fun_return]name:"..this_ar.fun_name..this_ar.linedefined)
-- Now, if we have a parent, update its call info...
if this_ar.parent_ar then
zLog("[one_fun_return parent]name:"..this_ar.parent_ar.fun_name..this_ar.parent_ar.linedefined)
local funcStrKey = this_ar.fun_name.."_"..this_ar.linedefined.."_"..this_ar.source;
this_ar.parent_ar.children[funcStrKey] =
(this_ar.parent_ar.children[funcStrKey] or 0) + 1
this_ar.parent_ar.children_time[funcStrKey] =
(this_ar.parent_ar.children_time[funcStrKey] or 0 ) +
this_ar.this_time
if this_ar.fun_name == nil then
this_ar.parent_ar.anon_child =
this_ar.parent_ar.anon_child + this_ar.this_time
else
this_ar.parent_ar.name_child =
this_ar.parent_ar.name_child + this_ar.this_time
end
end
-- Now if we're meant to record information about ourselves, do so...
if this_ar.should_not_profile == 0 then
local inforec = self:_get_func_rec(this_ar.fun_name,this_ar.linedefined,this_ar.func,this_ar.source)
inforec.count = inforec.count + 1
inforec.time = inforec.time + this_ar.this_time
inforec.anon_child_time = inforec.anon_child_time + this_ar.anon_child
inforec.name_child_time = inforec.name_child_time + this_ar.name_child
inforec.func_info = this_ar.caller_info
inforec.parent_info = ""
if this_ar.parent_ar then
inforec.parent_info = this_ar.parent_ar.source.." ["..this_ar.parent_ar.fun_name.."]:"..this_ar.parent_ar.linedefined
end
for k,v in pairs(this_ar.children) do
inforec.children[k] = (inforec.children[k] or 0) + v
inforec.children_time[k] =
(inforec.children_time[k] or 0) + this_ar.children_time[k]
end
end
if this_ar.parent_ar then
local nowTime = os.clock();
this_ar.parent_ar.proflier_time = this_ar.parent_ar.proflier_time
+ this_ar.proflier_time --子函数调用的分析消耗
+ (nowTime - profile_return_start_Time) --这次 return 的分析耗时
this_ar.parent_ar.line_cost_time = this_ar.parent_ar.line_cost_time + this_ar.line_cost_time --传递子函数的逐行分析耗时
self.profile_start_Time = nowTime; --避免重复计算消耗
end
--fun return update currpos
self.currPos_ar = self.callstack[#self.callstack];
end
function _profiler._get_func_rec(self,funName,linedefined,func,source)
-- Find the function ref for 'func' (if force and not present, create one)
local ret = self.rawstats[funName.."_"..linedefined.."_"..source]
if ret == nil then
-- Build a new function statistics table
ret = {}
ret.func = func
ret.count = 0
ret.time = 0
ret.anon_child_time = 0
ret.name_child_time = 0
ret.children = {}
ret.children_time = {}
self.rawstats[funName.."_"..linedefined.."_"..source] = ret
end
return ret
end
--
-- This writes a profile report to the output file object. If
-- sort_by_total_time is nil or false the output is sorted by
-- the function time minus the time in it's children.
--
function _profiler.report( self, outfile, sort_by_total_time )
-- table_print(self.rawstats)
outfile:write
[[Lua Profile output created by profiler.lua. Copyright Pepperfish 2002+
]]
-- This is pretty awful.
local terms = {}
if self.variant == "time" then
terms.capitalized = "Sample"
terms.single = "sample"
terms.pastverb = "sampled"
elseif self.variant == "call" then
terms.capitalized = "Call"
terms.single = "call"
terms.pastverb = "called"
else
assert(false)
end
local total_time = 0
local ordering = {}
for func,record in pairs(self.rawstats) do
table.insert(ordering, func)
end
if sort_by_total_time then
table.sort( ordering,
function(a,b) return self.rawstats[a].time > self.rawstats[b].time end
)
else
table.sort( ordering,
function(a,b)
local arec = self.rawstats[a]
local brec = self.rawstats[b]
local atime = arec.time - (arec.anon_child_time + arec.name_child_time)
local btime = brec.time - (brec.anon_child_time + brec.name_child_time)
return atime > btime
end
)
end
for i=1,table.getn(ordering) do
local func = ordering[i]
local record = self.rawstats[func]
local thisfuncname = " " .. self:_pretty_name(func,true) .. " "
-- if string.len( thisfuncname ) < 42 then
-- thisfuncname =
-- string.rep( "-", (42 - string.len(thisfuncname))/2 ) .. thisfuncname
-- thisfuncname =
-- thisfuncname .. string.rep( "-", 42 - string.len(thisfuncname) )
-- end
total_time = total_time + ( record.time - ( record.anon_child_time +
record.name_child_time ) )
outfile:write( "No."..i..string.rep( "-", 19 ) .. thisfuncname .. " [parent]" .. record.parent_info ..
string.rep( "-", 19 ) .. "\n" )
outfile:write( terms.capitalized.." count: " ..
string.format( "%4d", record.count ) .. "\n" )
outfile:write( "Time spend total: " ..
string.format( "%4.3f", record.time ) .. "ms\n" )
outfile:write( "Time spent in children: " ..
string.format("%4.3f",record.anon_child_time+record.name_child_time) ..
"ms\n" )
local timeinself =
record.time - (record.anon_child_time + record.name_child_time)
outfile:write( "Time spent in self: " ..
string.format("%4.3f", timeinself) .. "ms\n" )
outfile:write( "Time spent per " .. terms.single .. ": " ..
string.format("%4.5f", record.time/record.count) ..
"ms/" .. terms.single .. "\n" )
outfile:write( "Time spent in self per "..terms.single..": " ..
string.format( "%4.5f", timeinself/record.count ) .. "ms/" ..
terms.single.."\n" )
-- Report on each child in the form
-- Child <funcname> called n times and took a.bs
local added_blank = 0
local childrenlist = {}
for k,v in pairs(record.children) do
if self.prevented_functions[k] == nil or
self.prevented_functions[k] == 0
then
-- if added_blank == 0 then
-- outfile:write( "\n" ) -- extra separation line
-- added_blank = 1
-- end
-- if record.children_time[k] ~= 0 then
local childrenInfo = {}
childrenInfo.str = "Child " .. self:_pretty_name(k) ..
string.rep( " ", 41-string.len(self:_pretty_name(k)) ) .. " " ..
terms.pastverb.." " .. string.format("%6d", v) .. " times. Took " ..
string.format("%4.2f", record.children_time[k] ) .. "ms\n"
childrenInfo.time = record.children_time[k];
table.insert(childrenlist,childrenInfo);
-- end
end
end
table.sort(childrenlist,function (a,b)
return a.time > b.time;
end)
outfile:write( "\n" )
for k, v in pairs(childrenlist) do
outfile:write(v.str);
end
outfile:write( "\n" ) -- extra separation line
outfile:flush()
end
outfile:write( "\n\n" )
outfile:write( "Total time spent in profiled functions: " ..
string.format("%5.3g",total_time) .. "s\n" )
outfile:write( [[
END
]] )
outfile:flush()
if bCppLogWrite then
CppLogEnd();
end
end
--
-- This writes the profile to the output file object as
-- loadable Lua source.
--
function _profiler.lua_report(self,outfile)
-- Purpose: Write out the entire raw state in a cross-referenceable form.
local ordering = {}
local functonum = {}
for func,record in pairs(self.rawstats) do
table.insert(ordering, func)
functonum[func] = table.getn(ordering)
end
outfile:write(
"-- Profile generated by profiler.lua Copyright Pepperfish 2002+\n\n" )
outfile:write( "-- Function names\nfuncnames = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
outfile:write( "funcnames[" .. i .. "] = " ..
string.format("%q", self:_pretty_name(thisfunc)) .. "\n" )
end
outfile:write( "\n" )
outfile:write( "-- Function times\nfunctimes = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "functimes[" .. i .. "] = { " )
outfile:write( "tot=" .. record.time .. ", " )
outfile:write( "achild=" .. record.anon_child_time .. ", " )
outfile:write( "nchild=" .. record.name_child_time .. ", " )
outfile:write( "count=" .. record.count .. " }\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child links\nchildren = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "children[" .. i .. "] = { " )
for k,v in pairs(record.children) do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( functonum[k] .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child call counts\nchildcounts = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc]
outfile:write( "children[" .. i .. "] = { " )
for k,v in record.children do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( v .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n" )
outfile:write( "-- Child call time\nchildtimes = {}\n" )
for i=1,table.getn(ordering) do
local thisfunc = ordering[i]
local record = self.rawstats[thisfunc];
outfile:write( "children[" .. i .. "] = { " )
for k,v in pairs(record.children) do
if functonum[k] then -- non-recorded functions will be ignored now
outfile:write( record.children_time[k] .. ", " )
end
end
outfile:write( "}\n" )
end
outfile:write( "\n\n-- That is all.\n\n" )
outfile:flush()
end
-- Internal function to calculate a pretty name for the profile output
function _profiler._pretty_name(self,func,bTitle)
-- Only the data collected during the actual
-- run seems to be correct.... why?
local info = self.rawstats[ func ].func_info
-- local info = debug.getinfo( func )
local name = ""
if info.what == "Lua" then
name = "L:"
end
if info.what == "C" then
name = "C:"
end
if info.what == "main" then
name = " :"
end
if info.name == nil then
name = name .. "<"..tostring(func) .. ">"
else
name = name .. info.name
end
if info.source then
name = name .. "@" .. info.source
else
if info.what == "C" then
name = name .. "@?"
else
name = name .. "@<string>"
end
end
name = name .. ":"
if info.what == "C" then
name = name .. "?"
else
name = name .. info.linedefined
end
if bTitle then
name = name .. " Root"
end
if info.name then
name = name .." Fun:"..info.name;
end
return name
end
--
-- This allows you to specify functions which you do
-- not want profiled. Setting level to 1 keeps the
-- function from being profiled. Setting level to 2
-- keeps both the function and its children from
-- being profiled.
--
-- BUG: 2 will probably act exactly like 1 in "time" mode.
-- If anyone cares, let me (zorba) know and it can be fixed.
--
function _profiler.prevent(self, func, level)
self.prevented_functions[func] = (level or 1)
end
_profiler.prevented_functions = {
[_profiler.start] = 2,
[_profiler.stop] = 2,
[_profiler._internal_profile_by_call] = 2,
[_profiler_hook_wrapper_by_call] = 2,
[_profiler.prevent] = 2,
[_profiler._get_func_rec] = 2,
[_profiler.report] = 2,
[_profiler.lua_report] = 2,
[_profiler._pretty_name] = 2,
}
-------------------------------------------------------------------
-- Tool functions
-------------------------------------------------------------------
local function _list_table(tb, table_list, level)
local ret = ""
local indent = string.rep(" ", level*4)
for k, v in pairs(tb) do
local quo = type(k) == "string" and "\"" or ""
ret = ret .. indent .. "[" .. quo .. tostring(k) .. quo .. "] = "
if type(v) == "table" then
local t_name = table_list[v]
if t_name then
ret = ret .. tostring(v) .. " -- > [\"" .. t_name .. "\"]\n"
else
table_list[v] = tostring(k)
ret = ret .. "{\n"
ret = ret .. _list_table(v, table_list, level+1)
ret = ret .. indent .. "}\n"
end
elseif type(v) == "string" then
ret = ret .. "\"" .. tostring(v) .. "\"\n"
else
ret = ret .. tostring(v) .. ",\n"
end
end
local mt = getmetatable(tb)
if mt then
ret = ret .. "\n"
local t_name = table_list[mt]
ret = ret .. indent .. "<metatable> = "
if t_name then
ret = ret .. tostring(mt) .. " -- > [\"" .. t_name .. "\"]\n"
else
ret = ret .. "{\n"
ret = ret .. _list_table(mt, table_list, level+1)
ret = ret .. indent .. "}\n"
end
end
return ret
end
local function table_tostring(tb)
--print("table_tostring")
if type(tb) ~= "table" then
print("Sorry, it's not table, it is " .. type(tb) .. ".","table_Print")
end
local ret = " = {\n"
local table_list = {}
table_list[tb] = "root table"
ret = ret .. _list_table(tb, table_list, 1)
ret = ret .. "}"
return ret
end
table_print = function (tb)
if tb == nil then
print("table_Print {}","table_Print")
return
end
if zLog then
zLog(tostring(tb) .. table_tostring(tb))
end
-- print(tostring(tb) .. table_tostring(tb))
end
local cppLogStr = ""
CppLogInit = function()
cppLogStr = ""
end
_CppLog = function(str)
cppLogStr = cppLogStr .."\n".. str;
end
zLog = function(str)
end
CppLogEnd = function()
local outfile = io.open(cppLogWriteOutPath,"w+");
outfile:write(cppLogStr)
outfile:flush()
end
if bCppLogWrite then
CppLog = _CppLog;
_profiler.prevented_functions[CppLog] = 2;
_profiler.prevented_functions[CppLogInit] = 2;
_profiler.prevented_functions[CppLogEnd] = 2;
end
if bZLog then
zLog = CppLog
end