mirror of
https://github.com/FlightControl-Master/MOOSE.git
synced 2025-08-15 10:47:21 +00:00
0441acf101
Improve the consistency of the module intros to the most commonly used version (single dash). Add missing module information (abbreviated where none existed previously). Fix broken documentation links Make module names correspond to filenames (and fix links). Fix typos.
557 lines
18 KiB
Lua
557 lines
18 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 Utils_Profiler.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 ThreshCPS Low calls per second threshold. Only write output if function has more calls per second than this value.
|
|
-- @field #number ThreshTtot Total time threshold. Only write output if total function CPU time is more 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**, **io** and **lfs** need to be desanizied. Comment out the lines
|
|
--
|
|
-- --sanitizeModule('os')
|
|
-- --sanitizeModule('io')
|
|
-- --sanitizeModule('lfs')
|
|
--
|
|
-- in your *"DCS World OpenBeta/Scripts/MissionScripting.lua"* file.
|
|
--
|
|
-- But be aware that these changes can make you system vulnerable to attacks.
|
|
--
|
|
-- # Disclaimer
|
|
--
|
|
-- **Profiling itself is CPU expensive!** Don't use this when you want to fly or host a mission.
|
|
--
|
|
--
|
|
-- # 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.ThreshCPS=1.5
|
|
--
|
|
-- With this setting, only functions which are called more than 1.5 times per second are displayed. The default setting is PROFILER.ThreshCPS=0.0 (no threshold).
|
|
--
|
|
-- Furthermore, you can limit the output for functions that consumed a certain amount of CPU time in total by
|
|
--
|
|
-- PROFILER.ThreshTtot=0.005
|
|
--
|
|
-- With this setting, which is also the default, only functions which in total used more than 5 milliseconds CPU time.
|
|
--
|
|
-- @field #PROFILER
|
|
PROFILER = {
|
|
ClassName = "PROFILER",
|
|
Counters = {},
|
|
dInfo = {},
|
|
fTime = {},
|
|
fTimeTotal = {},
|
|
eventHandler = {},
|
|
logUnknown = false,
|
|
ThreshCPS = 0.0,
|
|
ThreshTtot = 0.005,
|
|
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, io and lfs are available.
|
|
local go = true
|
|
if not os then
|
|
env.error( "ERROR: Profiler needs os to be de-sanitized!" )
|
|
go = false
|
|
end
|
|
if not io then
|
|
env.error("ERROR: Profiler needs io to be desanitized!")
|
|
go=false
|
|
end
|
|
if not lfs then
|
|
env.error("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)
|
|
|
|
-- 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.ThreshCPS))
|
|
env.info(string.format("- Total function time threshold %.3f sec", PROFILER.ThreshTtot))
|
|
env.info(string.format("- Output file \"%s\" in your DCS log file folder", PROFILER.getfilename(PROFILER.fileNameSuffix)))
|
|
env.info(string.format("- Output file \"%s\" in CSV format", PROFILER.getfilename("csv")))
|
|
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 )
|
|
end
|
|
end
|
|
|
|
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
|
|
|
|
local threshCPS=cps>=PROFILER.ThreshCPS
|
|
local threshTot=t.tm>=PROFILER.ThreshTtot
|
|
|
|
if threshCPS and threshTot then
|
|
|
|
-- Output
|
|
local text=string.format("%30s: %8d calls %8.1f/sec - Time Total %8.3f sec (%.3f %%) %5.3f sec/call %s line %s", t.func, t.count, cps, t.tm, t.tm/runTimeGame*100, t.tm/t.count, tostring(t.src), tostring(t.line))
|
|
PROFILER._flog(f, text)
|
|
|
|
end
|
|
end
|
|
|
|
end
|
|
|
|
--- Print csv file.
|
|
-- @param #table data Data table.
|
|
-- @param #number runTimeGame Game run time in seconds.
|
|
function PROFILER.printCSV( data, runTimeGame )
|
|
|
|
-- Output file.
|
|
local file = PROFILER.getfilename( "csv" )
|
|
local g = io.open( file, 'w' )
|
|
|
|
-- Header.
|
|
local text="Function,Total Calls,Calls per Sec,Total Time,Total in %,Sec per Call,Source File;Line Number,"
|
|
g:write(text.."\r\n")
|
|
|
|
-- Loop over data.
|
|
for i=1, #data do
|
|
local t=data[i] --#PROFILER.Data
|
|
|
|
-- Calls per second.
|
|
local cps = t.count / runTimeGame
|
|
|
|
-- Output
|
|
local txt=string.format("%s,%d,%.1f,%.3f,%.3f,%.3f,%s,%s,", t.func, t.count, cps, t.tm, t.tm/runTimeGame*100, t.tm/t.count, tostring(t.src), tostring(t.line))
|
|
g:write(txt.."\r\n")
|
|
|
|
end
|
|
|
|
-- Close file.
|
|
g:close()
|
|
end
|
|
|
|
--- Write info to output file.
|
|
-- @param #string ext Extension.
|
|
-- @return #string File name.
|
|
function PROFILER.getfilename(ext)
|
|
|
|
local dir=lfs.writedir()..[[Logs\]]
|
|
|
|
ext=ext or PROFILER.fileNameSuffix
|
|
|
|
local file=dir..PROFILER.fileNamePrefix.."."..ext
|
|
|
|
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, ext )
|
|
|
|
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(PROFILER.fileNameSuffix)
|
|
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('############################ Profiler Stopped ############################')
|
|
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(string.format("* Writing to file : \"%s\"", PROFILER.getfilename("csv")))
|
|
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,string.format("* Calls per second threshold = %.3f/sec", PROFILER.ThreshCPS))
|
|
PROFILER._flog(f,string.format("* Total func time threshold = %.3f sec", PROFILER.ThreshTtot))
|
|
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.tm/a.count>b.tm/b.count end)
|
|
|
|
-- Detailed data.
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"************************************************************************************************************************")
|
|
PROFILER._flog(f,"")
|
|
PROFILER._flog(f,"--------------------------------------")
|
|
PROFILER._flog(f,"---- Data Sorted by Time per Call ----")
|
|
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 Total 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()
|
|
|
|
-- Print csv file.
|
|
PROFILER.printCSV( t, runTimeGame )
|
|
end
|