mirror of
https://github.com/FlightControl-Master/MOOSE.git
synced 2025-08-15 10:47:21 +00:00
481 lines
15 KiB
Lua
481 lines
15 KiB
Lua
--- **Utils** - Lua Profiler.
|
|
--
|
|
-- Find out how many times functions are called and how much real time it costs.
|
|
--
|
|
-- ===
|
|
--
|
|
-- ### Author: **TAW CougarNL**, *funkyfranky*
|
|
--
|
|
-- @module Utilities.PROFILER
|
|
-- @image MOOSE.JPG
|
|
|
|
|
|
--- PROFILER class.
|
|
-- @type PROFILER
|
|
-- @field #string ClassName Name of the class.
|
|
-- @field #table Counters Function counters.
|
|
-- @field #table dInfo Info.
|
|
-- @field #table fTime Function time.
|
|
-- @field #table fTimeTotal Total function time.
|
|
-- @field #table eventhandler Event handler to get mission end event.
|
|
-- @field #number TstartGame Game start time timer.getTime().
|
|
-- @field #number TstartOS OS real start time os.clock.
|
|
-- @field #boolean logUnknown Log unknown functions. Default is off.
|
|
-- @field #number lowCpsThres Low calls per second threashold. Only write output if function has more calls per second than this value.
|
|
-- @field #string fileNamePrefix Output file name prefix, e.g. "MooseProfiler".
|
|
-- @field #string fileNameSuffix Output file name prefix, e.g. "txt"
|
|
|
|
--- *The emperor counsels simplicity. First principles. Of each particular thing, ask: What is it in itself, in its own constitution? What is its causal nature? *
|
|
--
|
|
-- ===
|
|
--
|
|
-- 
|
|
--
|
|
-- # The PROFILER Concept
|
|
--
|
|
-- Profile your lua code. This tells you, which functions are called very often and which consume most real time.
|
|
-- With this information you can optimize the perfomance of your code.
|
|
--
|
|
-- # Prerequisites
|
|
--
|
|
-- The modules **os** and **lfs** need to be desanizied.
|
|
--
|
|
--
|
|
-- # Start
|
|
--
|
|
-- The profiler can simply be started with the @{#PROFILER.Start}(*Delay, Duration*) function
|
|
--
|
|
-- PROFILER.Start()
|
|
--
|
|
-- The optional parameter *Delay* can be used to delay the start by a certain amount of seconds and the optional parameter *Duration* can be used to
|
|
-- stop the profiler after a certain amount of seconds.
|
|
--
|
|
-- # Stop
|
|
--
|
|
-- The profiler automatically stops when the mission ends. But it can be stopped any time with the @{#PROFILER.Stop}(*Delay*) function
|
|
--
|
|
-- PROFILER.Stop()
|
|
--
|
|
-- The optional parameter *Delay* can be used to specify a delay after which the profiler is stopped.
|
|
--
|
|
-- When the profiler is stopped, the output is written to a file.
|
|
--
|
|
-- # Output
|
|
--
|
|
-- The profiler output is written to a file in your DCS home folder
|
|
--
|
|
-- X:\User\<Your User Name>\Saved Games\DCS OpenBeta\Logs
|
|
--
|
|
-- The default file name is "MooseProfiler.txt". If that file exists, the file name is "MooseProfiler-001.txt" etc.
|
|
--
|
|
-- ## Data
|
|
--
|
|
-- The data in the output file provides information on the functions that were called in the mission.
|
|
--
|
|
-- It will tell you how many times a function was called in total, how many times per second, how much time in total and the percentage of time.
|
|
--
|
|
-- If you only want output for functions that are called more than X times per second, you can set
|
|
--
|
|
-- PROFILER.lowCpsThres=1.5
|
|
--
|
|
-- With this setting, only functions which are called more than 1.5 times per second are displayed.
|
|
--
|
|
-- @field #PROFILER
|
|
PROFILER = {
|
|
ClassName = "PROFILER",
|
|
Counters = {},
|
|
dInfo = {},
|
|
fTime = {},
|
|
fTimeTotal = {},
|
|
eventHandler = {},
|
|
logUnknown = false,
|
|
lowCpsThres = 0.0,
|
|
fileNamePrefix = "MooseProfiler",
|
|
fileNameSuffix = "txt"
|
|
}
|
|
|
|
--- Waypoint data.
|
|
-- @type PROFILER.Data
|
|
-- @field #string func The function name.
|
|
-- @field #string src The source file.
|
|
-- @field #number line The line number
|
|
-- @field #number count Number of function calls.
|
|
-- @field #number tm Total time in seconds.
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
-- Start/Stop Profiler
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
--- Start profiler.
|
|
-- @param #number Delay Delay in seconds before profiler is stated. Default is immediately.
|
|
-- @param #number Duration Duration in (game) seconds before the profiler is stopped. Default is when mission ends.
|
|
function PROFILER.Start(Delay, Duration)
|
|
|
|
-- Check if os and lfs are available.
|
|
local go=true
|
|
if not os then
|
|
error("Profiler needs os to be desanitized")
|
|
go=false
|
|
end
|
|
if not lfs then
|
|
error("Profiler needs lfs to be desanitized")
|
|
go=false
|
|
end
|
|
if not go then
|
|
return
|
|
end
|
|
|
|
if Delay and Delay>0 then
|
|
BASE:ScheduleOnce(Delay, PROFILER.Start, 0, Duration)
|
|
else
|
|
|
|
-- Set start time.
|
|
PROFILER.TstartGame=timer.getTime()
|
|
PROFILER.TstartOS=os.clock()
|
|
|
|
-- Add event handler.
|
|
world.addEventHandler(PROFILER.eventHandler)
|
|
|
|
--[[
|
|
-- Message to screen.
|
|
local function showProfilerRunning()
|
|
timer.scheduleFunction(showProfilerRunning, nil, timer.getTime()+600)
|
|
trigger.action.outText("### Profiler running ###", 600)
|
|
end
|
|
-- Message.
|
|
showProfilerRunning()
|
|
]]
|
|
|
|
-- Info in log.
|
|
env.info('############################ Profiler Started ############################')
|
|
if Duration then
|
|
env.info(string.format("- Will be running for %d seconds", Duration))
|
|
else
|
|
env.info(string.format("- Will be stopped when mission ends"))
|
|
end
|
|
env.info(string.format("- Calls per second threshold %.3f/sec", PROFILER.lowCpsThres))
|
|
env.info(string.format("- Output file \"%s\" in your DCS log file folder", PROFILER.getfilename()))
|
|
env.info('###############################################################################')
|
|
|
|
|
|
-- Message on screen
|
|
local duration=Duration or 600
|
|
trigger.action.outText("### Profiler running ###", duration)
|
|
|
|
-- Set hook.
|
|
debug.sethook(PROFILER.hook, "cr")
|
|
|
|
-- Auto stop profiler.
|
|
if Duration then
|
|
PROFILER.Stop(Duration)
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
--- Stop profiler.
|
|
-- @param #number Delay Delay before stop in seconds.
|
|
function PROFILER.Stop(Delay)
|
|
|
|
if Delay and Delay>0 then
|
|
|
|
BASE:ScheduleOnce(Delay, PROFILER.Stop)
|
|
|
|
else
|
|
|
|
-- Remove hook.
|
|
debug.sethook()
|
|
|
|
|
|
-- Run time game.
|
|
local runTimeGame=timer.getTime()-PROFILER.TstartGame
|
|
|
|
-- Run time real OS.
|
|
local runTimeOS=os.clock()-PROFILER.TstartOS
|
|
|
|
-- Show info.
|
|
PROFILER.showInfo(runTimeGame, runTimeOS)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
--- Event handler.
|
|
function PROFILER.eventHandler:onEvent(event)
|
|
if event.id==world.event.S_EVENT_MISSION_END then
|
|
PROFILER.Stop()
|
|
end
|
|
end
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
-- Hook
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
--- Debug hook.
|
|
-- @param #table event Event.
|
|
function PROFILER.hook(event)
|
|
|
|
local f=debug.getinfo(2, "f").func
|
|
|
|
if event=='call' then
|
|
|
|
if PROFILER.Counters[f]==nil then
|
|
|
|
PROFILER.Counters[f]=1
|
|
PROFILER.dInfo[f]=debug.getinfo(2,"Sn")
|
|
|
|
if PROFILER.fTimeTotal[f]==nil then
|
|
PROFILER.fTimeTotal[f]=0
|
|
end
|
|
|
|
else
|
|
PROFILER.Counters[f]=PROFILER.Counters[f]+1
|
|
end
|
|
|
|
if PROFILER.fTime[f]==nil then
|
|
PROFILER.fTime[f]=os.clock()
|
|
end
|
|
|
|
elseif (event=='return') then
|
|
|
|
if PROFILER.fTime[f]~=nil then
|
|
PROFILER.fTimeTotal[f]=PROFILER.fTimeTotal[f]+(os.clock()-PROFILER.fTime[f])
|
|
PROFILER.fTime[f]=nil
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
-- Data
|
|
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|
|
|
|
--- Get data.
|
|
-- @param #function func Function.
|
|
-- @return #string Function name.
|
|
-- @return #string Source file name.
|
|
-- @return #string Line number.
|
|
-- @return #number Function time in seconds.
|
|
function PROFILER.getData(func)
|
|
|
|
local n=PROFILER.dInfo[func]
|
|
|
|
if n.what=="C" then
|
|
return n.name, "?", "?", PROFILER.fTimeTotal[func]
|
|
end
|
|
|
|
return n.name, n.short_src, n.linedefined, PROFILER.fTimeTotal[func]
|
|
end
|
|
|
|
--- Write text to log file.
|
|
-- @param #function f The file.
|
|
-- @param #string txt The text.
|
|
function PROFILER._flog(f, txt)
|
|
f:write(txt.."\r\n")
|
|
end
|
|
|
|
--- Show table.
|
|
-- @param #table data Data table.
|
|
-- @param #function f The file.
|
|
-- @param #number runTimeGame Game run time in seconds.
|
|
function PROFILER.showTable(data, f, runTimeGame)
|
|
|
|
-- Loop over data.
|
|
for i=1, #data do
|
|
local t=data[i] --#PROFILER.Data
|
|
|
|
-- Calls per second.
|
|
local cps=t.count/runTimeGame
|
|
|
|
if (cps>=PROFILER.lowCpsThres) then
|
|
|
|
-- Output
|
|
local text=string.format("%30s: %8d calls %8.1f/sec - Time %8.3f sec (%.3f %%) %s line %s", t.func, t.count, cps, t.tm, t.tm/runTimeGame*100, tostring(t.src), tostring(t.line))
|
|
PROFILER._flog(f, text)
|
|
|
|
end
|
|
end
|
|
|
|
end
|
|
|
|
--- Write info to output file.
|
|
-- @return #string File name.
|
|
function PROFILER.getfilename()
|
|
|
|
local dir=lfs.writedir()..[[Logs\]]
|
|
|
|
local file=dir..PROFILER.fileNamePrefix.."."..PROFILER.fileNameSuffix
|
|
|
|
if not UTILS.FileExists(file) then
|
|
return file
|
|
end
|
|
|
|
for i=1,999 do
|
|
|
|
local file=string.format("%s%s-%03d.%s", dir,PROFILER.fileNamePrefix, i, PROFILER.fileNameSuffix)
|
|
|
|
if not UTILS.FileExists(file) then
|
|
return file
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
--- Write info to output file.
|
|
-- @param #number runTimeGame Game time in seconds.
|
|
-- @param #number runTimeOS OS time in seconds.
|
|
function PROFILER.showInfo(runTimeGame, runTimeOS)
|
|
|
|
-- Output file.
|
|
local file=PROFILER.getfilename()
|
|
local f=io.open(file, 'w')
|
|
|
|
-- Gather data.
|
|
local Ttot=0
|
|
local Calls=0
|
|
|
|
local t={}
|
|
|
|
local tcopy=nil --#PROFILER.Data
|
|
local tserialize=nil --#PROFILER.Data
|
|
local tforgen=nil --#PROFILER.Data
|
|
local tpairs=nil --#PROFILER.Data
|
|
|
|
|
|
for func, count in pairs(PROFILER.Counters) do
|
|
|
|
local s,src,line,tm=PROFILER.getData(func)
|
|
|
|
if PROFILER.logUnknown==true then
|
|
if s==nil then s="<Unknown>" end
|
|
end
|
|
|
|
if s~=nil then
|
|
|
|
-- Profile data.
|
|
local T=
|
|
{ func=s,
|
|
src=src,
|
|
line=line,
|
|
count=count,
|
|
tm=tm,
|
|
} --#PROFILER.Data
|
|
|
|
-- Collect special cases. Somehow, e.g. "_copy" appears multiple times so we try to gather all data.
|
|
if s=="_copy" then
|
|
if tcopy==nil then
|
|
tcopy=T
|
|
else
|
|
tcopy.count=tcopy.count+T.count
|
|
tcopy.tm=tcopy.tm+T.tm
|
|
end
|
|
elseif s=="_Serialize" then
|
|
if tserialize==nil then
|
|
tserialize=T
|
|
else
|
|
tserialize.count=tserialize.count+T.count
|
|
tserialize.tm=tserialize.tm+T.tm
|
|
end
|
|
elseif s=="(for generator)" then
|
|
if tforgen==nil then
|
|
tforgen=T
|
|
else
|
|
tforgen.count=tforgen.count+T.count
|
|
tforgen.tm=tforgen.tm+T.tm
|
|
end
|
|
elseif s=="pairs" then
|
|
if tpairs==nil then
|
|
tpairs=T
|
|
else
|
|
tpairs.count=tpairs.count+T.count
|
|
tpairs.tm=tpairs.tm+T.tm
|
|
end
|
|
else
|
|
table.insert(t, T)
|
|
end
|
|
|
|
-- Total function time.
|
|
Ttot=Ttot+tm
|
|
|
|
-- Total number of calls.
|
|
Calls=Calls+count
|
|
|
|
end
|
|
|
|
end
|
|
|
|
-- Add special cases.
|
|
if tcopy then
|
|
table.insert(t, tcopy)
|
|
end
|
|
if tserialize then
|
|
table.insert(t, tserialize)
|
|
end
|
|
if tforgen then
|
|
table.insert(t, tforgen)
|
|
end
|
|
if tpairs then
|
|
table.insert(t, tpairs)
|
|
end
|
|
|
|
env.info("**************************************************************************************************")
|
|
env.info(string.format("Profiler"))
|
|
env.info(string.format("--------"))
|
|
env.info(string.format("* Runtime Game : %s = %d sec", UTILS.SecondsToClock(runTimeGame, true), runTimeGame))
|
|
env.info(string.format("* Runtime Real : %s = %d sec", UTILS.SecondsToClock(runTimeOS, true), runTimeOS))
|
|
env.info(string.format("* Function time : %s = %.1f sec (%.1f percent of runtime game)", UTILS.SecondsToClock(Ttot, true), Ttot, Ttot/runTimeGame*100))
|
|
env.info(string.format("* Total functions : %d", #t))
|
|
env.info(string.format("* Total func calls : %d", Calls))
|
|
env.info(string.format("* Writing to file : \"%s\"", file))
|
|
env.info("**************************************************************************************************")
|
|
|
|
-- Sort by total time.
|
|
table.sort(t, function(a,b) return a.tm>b.tm end)
|
|
|
|
-- Write data.
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"-------------------------")
|
|
PROFILER._flog(f,"---- Profiler Report ----")
|
|
PROFILER._flog(f,"-------------------------")
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,string.format("* Runtime Game : %s = %.1f sec", UTILS.SecondsToClock(runTimeGame, true), runTimeGame))
|
|
PROFILER._flog(f,string.format("* Runtime Real : %s = %.1f sec", UTILS.SecondsToClock(runTimeOS, true), runTimeOS))
|
|
PROFILER._flog(f,string.format("* Function time : %s = %.1f sec (%.1f %% of runtime game)", UTILS.SecondsToClock(Ttot, true), Ttot, Ttot/runTimeGame*100))
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,string.format("* Total functions = %d", #t))
|
|
PROFILER._flog(f,string.format("* Total func calls = %d", Calls))
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"")
|
|
PROFILER.showTable(t, f, runTimeGame)
|
|
|
|
-- Sort by number of calls.
|
|
table.sort(t, function(a,b) return a.count>b.count end)
|
|
|
|
-- Detailed data.
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"------------------------------")
|
|
PROFILER._flog(f,"---- Data Sorted by Calls ----")
|
|
PROFILER._flog(f,"------------------------------")
|
|
PROFILER._flog(f,"")
|
|
PROFILER.showTable(t, f, runTimeGame)
|
|
|
|
-- Closing.
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
-- Close file.
|
|
f:close()
|
|
end
|
|
|