Lua Profiler 工具(基于PepperfishProfiler 修改)

注:本文例子使用的是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

 

 

 

 

 

 

 

 

 

 

 

 

 

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值