FlightControl-Master/MOOSE
1
0
Fork 0
mirror of https://github.com/FlightControl-Master/MOOSE.git synced 2025-10-29 16:58:06 +00:00
Code Issues Packages Projects Releases Wiki Activity

Merge branch 'master' into develop

Browse Source
This commit is contained in:
Frank
2020-08-30 17:15:31 +02:00
parent 45d809a641 848336f8ac
commit c84a92c787
23 changed files with 3089 additions and 2215 deletions
Download Patch File Download Diff File Expand all files Collapse all files

264
Moose Development/Moose/Utilities/Profiler.lua
View File

@@ -5,7 +5,7 @@
-- ===
--
-- ### Author: **TAW CougarNL**, *funkyfranky*
--
--
-- @module Utilities.PROFILER
-- @image Utils_Profiler.jpg
@@ -33,14 +33,14 @@
-- ![Banner Image](..\Presentations\Utilities\PROFILER_Main.jpg)
--
-- # 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')
@@ -48,57 +48,57 @@
-- 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",
@@ -140,11 +140,11 @@ function PROFILER.Start(Delay, Duration)
if not io then
env.error("ERROR: Profiler needs io to be desanitized!")
go=false
end
end
if not lfs then
env.error("ERROR: Profiler needs lfs to be desanitized!")
go=false
end
end
if not go then
return
end
@@ -152,14 +152,14 @@ function PROFILER.Start(Delay, Duration)
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
@@ -168,25 +168,26 @@ function PROFILER.Start(Delay, Duration)
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()))
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.
@@ -194,24 +195,24 @@ 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
@@ -232,35 +233,35 @@ end
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
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
@@ -276,12 +277,12 @@ end
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]
return n.name, n.short_src, n.linedefined, PROFILER.fTimeTotal[func]
end
--- Write text to log file.
@@ -298,46 +299,80 @@ end
function PROFILER.showTable(data, f, runTimeGame)
-- Loop over data.
for i=1, #data do
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()
function PROFILER.getfilename(ext)
local dir=lfs.writedir()..[[Logs\]]
local file=dir..PROFILER.fileNamePrefix.."."..PROFILER.fileNameSuffix
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, PROFILER.fileNameSuffix)
local file=string.format("%s%s-%03d.%s", dir,PROFILER.fileNamePrefix, i, ext)
if not UTILS.FileExists(file) then
return file
end
end
end
@@ -348,31 +383,31 @@ end
function PROFILER.showInfo(runTimeGame, runTimeOS)
-- Output file.
local file=PROFILER.getfilename()
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 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,
@@ -381,7 +416,7 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
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
@@ -396,63 +431,62 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
else
tserialize.count=tserialize.count+T.count
tserialize.tm=tserialize.tm+T.tm
end
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
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
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.
-- 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)
end
env.info("**************************************************************************************************")
env.info(string.format("Profiler"))
env.info(string.format("--------"))
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("**************************************************************************************************")
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,"************************************************************************************************************************")
@@ -471,7 +505,7 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
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,string.format("* Total func time threshold = %.3f sec", PROFILER.ThreshTtot))
PROFILER._flog(f,"")
PROFILER._flog(f,"************************************************************************************************************************")
PROFILER._flog(f,"")
@@ -479,7 +513,7 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
-- 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,"************************************************************************************************************************")
@@ -489,10 +523,10 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
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,"************************************************************************************************************************")
@@ -502,7 +536,7 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
PROFILER._flog(f,"------------------------------------")
PROFILER._flog(f,"")
PROFILER.showTable(t, f, runTimeGame)
-- Closing.
PROFILER._flog(f,"")
PROFILER._flog(f,"************************************************************************************************************************")
@@ -510,5 +544,7 @@ function PROFILER.showInfo(runTimeGame, runTimeOS)
PROFILER._flog(f,"************************************************************************************************************************")
-- Close file.
f:close()
end
-- Print csv file.
PROFILER.printCSV(t, runTimeGame)
end