From fcfbc5e17cd6c6381ee8ad4e226d51e5bf9c65b6 Mon Sep 17 00:00:00 2001
From: Frank <frank@inter-zone.de>
Date: Sat, 22 Aug 2020 21:24:35 +0200
Subject: [PATCH 1/2] Profiler

- Added lua Profiler.
---
 Moose Development/Moose/Modules.lua           |   1 +
 .../Moose/Utilities/Profiler.lua              | 502 ++++++++++++++++++
 Moose Setup/Moose.files                       |   2 +
 3 files changed, 505 insertions(+)
 create mode 100644 Moose Development/Moose/Utilities/Profiler.lua

diff --git a/Moose Development/Moose/Modules.lua b/Moose Development/Moose/Modules.lua
index da80d374b..cd287683a 100644
--- a/Moose Development/Moose/Modules.lua	
+++ b/Moose Development/Moose/Modules.lua	
@@ -1,6 +1,7 @@
 __Moose.Include( 'Scripts/Moose/Utilities/Enums.lua' )
 __Moose.Include( 'Scripts/Moose/Utilities/Routines.lua' )
 __Moose.Include( 'Scripts/Moose/Utilities/Utils.lua' )
+__Moose.Include( 'Scripts/Moose/Utilities/Profiler.lua' )
 
 __Moose.Include( 'Scripts/Moose/Core/Base.lua' )
 __Moose.Include( 'Scripts/Moose/Core/UserFlag.lua' )
diff --git a/Moose Development/Moose/Utilities/Profiler.lua b/Moose Development/Moose/Utilities/Profiler.lua
new file mode 100644
index 000000000..1c0bd73bc
--- /dev/null
+++ b/Moose Development/Moose/Utilities/Profiler.lua	
@@ -0,0 +1,502 @@
+--- **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 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? *
+--
+-- ===
+--
+-- ![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** 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.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 desanitized!")
+    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()))
+    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
+    
+    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
+
+--- 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,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()
+end
+
diff --git a/Moose Setup/Moose.files b/Moose Setup/Moose.files
index 39014df5d..d3820c7e6 100644
--- a/Moose Setup/Moose.files	
+++ b/Moose Setup/Moose.files	
@@ -1,5 +1,7 @@
 Utilities/Routines.lua
 Utilities/Utils.lua
+Utilities/Enums.lua
+Utilities/Profiler.lua
 
 Core/Base.lua
 Core/UserFlag.lua

From 45d809a641abf80c80856c6757c66c6b70caabca Mon Sep 17 00:00:00 2001
From: Frank <frank@inter-zone.de>
Date: Sat, 22 Aug 2020 22:39:54 +0200
Subject: [PATCH 2/2] Update Profiler.lua

---
 Moose Development/Moose/Utilities/Profiler.lua | 18 +++++++++++++++---
 1 file changed, 15 insertions(+), 3 deletions(-)

diff --git a/Moose Development/Moose/Utilities/Profiler.lua b/Moose Development/Moose/Utilities/Profiler.lua
index 1c0bd73bc..b2ce3a825 100644
--- a/Moose Development/Moose/Utilities/Profiler.lua	
+++ b/Moose Development/Moose/Utilities/Profiler.lua	
@@ -7,7 +7,7 @@
 -- ### Author: **TAW CougarNL**, *funkyfranky*
 -- 
 -- @module Utilities.PROFILER
--- @image MOOSE.JPG
+-- @image Utils_Profiler.jpg
 
 
 --- PROFILER class.
@@ -26,7 +26,7 @@
 -- @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?*
 --
 -- ===
 --
@@ -39,7 +39,19 @@
 -- 
 -- # Prerequisites
 -- 
--- The modules **os** and **lfs** need to be desanizied.
+-- 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