#Changes from Develop

This commit is contained in:
Applevangelist
2022-09-10 11:49:40 +02:00
parent c58e91b956
commit 7c22e9fe69
48 changed files with 7792 additions and 3739 deletions

View File

@@ -7,7 +7,7 @@
-- ### Author: **TAW CougarNL**, *funkyfranky*
--
-- @module Utilities.PROFILER
-- @image MOOSE.JPG
-- @image Utils_Profiler.jpg
--- PROFILER class.
-- @type PROFILER
@@ -24,7 +24,8 @@
-- @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 emperor counsels simplicity.* *First principles. Of each particular thing, ask: What is it in itself, in its own constitution? What is its causal nature?*
--
-- ===
--
@@ -33,11 +34,24 @@
-- # 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 performance of your code.
-- With this information you can optimize the perfomance of your code.
--
-- # Prerequisites
--
-- The modules **os** and **lfs** need to be de-sanitized.
-- 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
--
@@ -123,12 +137,12 @@ function PROFILER.Start( Delay, Duration )
go = false
end
if not io then
env.error( "ERROR: Profiler needs io to be de-sanitized!" )
go = false
env.error("ERROR: Profiler needs io to be desanitized!")
go=false
end
if not lfs then
env.error( "ERROR: Profiler needs lfs to be de-sanitized!" )
go = false
env.error("ERROR: Profiler needs lfs to be desanitized!")
go=false
end
if not go then
return
@@ -139,11 +153,11 @@ function PROFILER.Start( Delay, Duration )
else
-- Set start time.
PROFILER.TstartGame = timer.getTime()
PROFILER.TstartOS = os.clock()
PROFILER.TstartGame=timer.getTime()
PROFILER.TstartOS=os.clock()
-- Add event handler.
world.addEventHandler( PROFILER.eventHandler )
world.addEventHandler(PROFILER.eventHandler)
-- Info in log.
env.info( '############################ Profiler Started ############################' )
@@ -152,18 +166,19 @@ function PROFILER.Start( Delay, 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( '###############################################################################' )
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 )
local duration=Duration or 600
trigger.action.outText("### Profiler running ###", duration)
-- Set hook.
debug.sethook( PROFILER.hook, "cr" )
debug.sethook(PROFILER.hook, "cr")
-- Auto stop profiler.
if Duration then
@@ -181,20 +196,29 @@ 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
local runTimeGame=timer.getTime()-PROFILER.TstartGame
-- Run time real OS.
local runTimeOS = os.clock() - PROFILER.TstartOS
local runTimeOS=os.clock()-PROFILER.TstartOS
-- Show info.
PROFILER.showInfo( runTimeGame, runTimeOS )
PROFILER.showInfo(runTimeGame, runTimeOS)
end
@@ -213,34 +237,34 @@ end
--- Debug hook.
-- @param #table event Event.
function PROFILER.hook( event )
function PROFILER.hook(event)
local f = debug.getinfo( 2, "f" ).func
local f=debug.getinfo(2, "f").func
if event == 'call' then
if event=='call' then
if PROFILER.Counters[f] == nil then
if PROFILER.Counters[f]==nil then
PROFILER.Counters[f] = 1
PROFILER.dInfo[f] = debug.getinfo( 2, "Sn" )
PROFILER.Counters[f]=1
PROFILER.dInfo[f]=debug.getinfo(2,"Sn")
if PROFILER.fTimeTotal[f] == nil then
PROFILER.fTimeTotal[f] = 0
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()
if PROFILER.fTime[f]==nil then
PROFILER.fTime[f]=os.clock()
end
elseif (event == 'return') then
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
if PROFILER.fTime[f]~=nil then
PROFILER.fTimeTotal[f]=PROFILER.fTimeTotal[f]+(os.clock()-PROFILER.fTime[f])
PROFILER.fTime[f]=nil
end
end
@@ -259,9 +283,9 @@ end
-- @return #number Function time in seconds.
function PROFILER.getData( func )
local n = PROFILER.dInfo[func]
local n=PROFILER.dInfo[func]
if n.what == "C" then
if n.what=="C" then
return n.name, "?", "?", PROFILER.fTimeTotal[func]
end
@@ -282,20 +306,20 @@ end
function PROFILER.showTable( data, f, runTimeGame )
-- Loop over data.
for i = 1, #data do
local t = data[i] -- #PROFILER.Data
for i=1, #data do
local t=data[i] --#PROFILER.Data
-- Calls per second.
local cps = t.count / runTimeGame
local cps=t.count/runTimeGame
local threshCPS = cps >= PROFILER.ThreshCPS
local threshTot = t.tm >= PROFILER.ThreshTtot
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 )
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
@@ -312,19 +336,19 @@ function PROFILER.printCSV( data, runTimeGame )
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" )
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
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" )
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
@@ -335,15 +359,15 @@ end
--- Write info to output file.
-- @param #string ext Extension.
-- @return #string File name.
function PROFILER.getfilename( ext )
function PROFILER.getfilename(ext)
local dir = lfs.writedir() .. [[Logs\]]
local dir=lfs.writedir()..[[Logs\]]
ext = ext or PROFILER.fileNameSuffix
ext=ext or PROFILER.fileNameSuffix
local file = dir .. PROFILER.fileNamePrefix .. "." .. ext
local file=dir..PROFILER.fileNamePrefix.."."..ext
if not UTILS.FileExists( file ) then
if not UTILS.FileExists(file) then
return file
end
@@ -365,34 +389,39 @@ end
function PROFILER.showInfo( runTimeGame, runTimeOS )
-- Output file.
local file = PROFILER.getfilename( PROFILER.fileNameSuffix )
local f = io.open( file, 'w' )
local file=PROFILER.getfilename(PROFILER.fileNameSuffix)
local f=io.open(file, 'w')
-- Gather data.
local Ttot = 0
local Calls = 0
local Ttot=0
local Calls=0
local t = {}
local t={}
local tcopy = nil -- #PROFILER.Data
local tserialize = nil -- #PROFILER.Data
local tforgen = nil -- #PROFILER.Data
local tpairs = nil -- #PROFILER.Data
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 )
for func, count in pairs(PROFILER.Counters) do
if PROFILER.logUnknown == true then
if s == nil then
s = "<Unknown>"
end
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
if s~=nil then
-- Profile data.
local T = { func = s, src = src, line = line, count = count, tm = tm } -- #PROFILER.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
@@ -406,119 +435,113 @@ function PROFILER.showInfo( runTimeGame, runTimeOS )
if tserialize == nil then
tserialize = T
else
tserialize.count = tserialize.count + T.count
tserialize.tm = tserialize.tm + T.tm
tserialize.count=tserialize.count+T.count
tserialize.tm=tserialize.tm+T.tm
end
elseif s == "(for generator)" then
if tforgen == nil then
tforgen = T
elseif s=="(for generator)" then
if tforgen==nil then
tforgen=T
else
tforgen.count = tforgen.count + T.count
tforgen.tm = tforgen.tm + T.tm
tforgen.count=tforgen.count+T.count
tforgen.tm=tforgen.tm+T.tm
end
elseif s == "pairs" then
if tpairs == nil then
tpairs = T
elseif s=="pairs" then
if tpairs==nil then
tpairs=T
else
tpairs.count = tpairs.count + T.count
tpairs.tm = tpairs.tm + T.tm
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
Ttot=Ttot+tm
-- Total number of calls.
Calls = Calls + count
Calls=Calls+count
end
end
-- Add special cases.
-- Add special cases.
if tcopy then
table.insert( t, tcopy )
end
if tserialize then
table.insert( t, tserialize )
table.insert(t, tserialize)
end
if tforgen then
table.insert( t, tforgen )
end
if tpairs then
table.insert( t, tpairs )
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( "##############################################################################" )
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 )
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 )
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 )
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 )
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 )
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 )
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, "" )