perf: debug channel for perf metrics

Author: pvaiko

Courseplay.lua

@@ -145,7 +145,7 @@ function Courseplay:setupGui()
 			g_messageCenter:publishDelayed(MessageType.GUI_CP_INGAME_OPEN)
 		end, false, true, false, true)
 		g_inputBinding:setActionEventTextVisibility(id, false)
-		-- CpDebug.registerEvents()
+		CpDebug.registerEvents()
 	end
 	PlayerInputComponent.registerGlobalPlayerActionEvents = Utils.overwrittenFunction(
 		PlayerInputComponent.registerGlobalPlayerActionEvents, addPlayerActionEvents)

config/DebugChannels.xml

@@ -20,5 +20,6 @@
 	<DebugChannel active="false" name="DBG_HUD" 			text="hud action"/>
 	<DebugChannel active="false" name="DBG_MULTIPLAYER" 	text="multiplayer"/>
 	<DebugChannel active="true"  name="DBG_IMPLEMENTS" 		text="implements"/>
-	<DebugChannel active="false" name="DBG_AI_DRIVER" 		text="AIDriver common"/>
+	<DebugChannel active="false" name="DBG_AI_DRIVER" 		text="ai common"/>
+	<DebugChannel active="true"  name="DBG_PERF" 			text="perf"/>
 </DebugChannels>

modDesc.xml

@@ -109,6 +109,7 @@ Changelog 8.1.0.0
 		<sourceFile filename="scripts/util/MovingAverage.lua"/>
 		<sourceFile filename="scripts/util/CpRemainingTime.lua"/>
 		<sourceFile filename="scripts/util/HelperNode.lua"/>
+		<sourceFile filename="scripts/util/Profiler.lua"/>
 
 		<sourceFile filename="scripts/geometry/Vector.lua"/>
 		<sourceFile filename="scripts/geometry/Vertex.lua"/>

scripts/ai/strategies/AIDriveStrategyFieldWorkCourse.lua

@@ -147,7 +147,6 @@ end
 
 --- This is the interface to the Giant's AIFieldWorker specialization, telling it the direction and speed
 function AIDriveStrategyFieldWorkCourse:getDriveData(dt, vX, vY, vZ)
-
     self:updateFieldworkOffset(self.course)
     self:updateLowFrequencyImplementControllers()
     Markers.refreshMarkerNodes(self.vehicle, self.measuredBackDistance)

scripts/debug/CpDebug.lua

@@ -132,13 +132,13 @@ end
 
 function CpDebug:activateEvents()
 	for _, id in pairs(CpDebug.eventIds) do 
-		g_currentMission.inputManager:setActionEventActive(id, true)
+		g_inputBinding:setActionEventActive(id, true)
 	end
 end
 
 function CpDebug:deactivateEvents()
 	for _, id in pairs(CpDebug.eventIds) do 
-		g_currentMission.inputManager:setActionEventActive(id, false)
+		g_inputBinding:setActionEventActive(id, false)
 	end
 end
 

scripts/specializations/CpAIFieldWorker.lua

@@ -9,6 +9,8 @@ CpAIFieldWorker.NAME = ".cpAIFieldWorker"
 CpAIFieldWorker.SPEC_NAME = CpAIFieldWorker.MOD_NAME .. CpAIFieldWorker.NAME
 CpAIFieldWorker.KEY = "."..CpAIFieldWorker.MOD_NAME..CpAIFieldWorker.NAME
 
+local profilers = {}
+
 -- shortcut to access the spec
 function CpAIFieldWorker.getSpec(self)
     return self["spec_" .. CpAIFieldWorker.SPEC_NAME]
@@ -311,7 +313,16 @@ end
 --- Makes sure a callstack is printed, when an error appeared.
 --- TODO: Might be a good idea to stop the cp helper.
 local function onUpdate(vehicle, superFunc, ...)
+    if not profilers[vehicle] then
+        profilers[vehicle] = Profiler(vehicle)
+    end
+    profilers[vehicle]:start()
     CpUtil.try(superFunc, vehicle, ...)
+    profilers[vehicle]:stop()
+    profilers[vehicle]:render()
+    if g_updateLoopIndex % 100  == 0 then
+        profilers[vehicle]:log()
+    end
 end
 
 AIFieldWorker.onUpdate = Utils.overwrittenFunction(AIFieldWorker.onUpdate, onUpdate)

scripts/specializations/CpAIWorker.lua

@@ -10,6 +10,8 @@ CpAIWorker.SPEC_NAME = CpAIWorker.MOD_NAME .. CpAIWorker.NAME
 CpAIWorker.KEY = "." .. CpAIWorker.MOD_NAME .. CpAIWorker.NAME .. "."
 CpAIWorker.LAST_JOB_KEY = "vehicles.vehicle(?).aiJobVehicle.lastJob"
 
+local logger = Logger('CpAIWorker', Logger.level.debug, CpUtil.DBG_AI_DRIVER)
+
 function CpAIWorker.initSpecialization()
     local schema = Vehicle.xmlSchemaSavegame
     --- Registers the last job key.
@@ -248,15 +250,15 @@ end
 
 --- Directly starts a cp job or stops a currently active job.
 function CpAIWorker:cpStartStopDriver(isStartedByHud)
-    CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Start/stop cp helper")
+    logger:debug(self, "Start/stop cp helper")
     if self:getIsAIActive() then
         self:stopCurrentAIJob(AIMessageSuccessStoppedByUser.new())
-        CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Stopped current helper.")
+        logger:debug(self, "Stopped current helper.")
     else
         self:updateAIFieldWorkerImplementData()
         local job = self:getCpStartableJob(isStartedByHud)
         if job == nil then
-            CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Could not find a CP job to start!")
+            logger:debug(self, "Could not find a CP job to start!")
             return
         end
         if self:getCanStartCp() and job then
@@ -266,15 +268,15 @@ function CpAIWorker:cpStartStopDriver(isStartedByHud)
             local success, message = job:validate()
             if success then
                 g_client:getServerConnection():sendEvent(AIJobStartRequestEvent.new(job, self:getOwnerFarmId()))
-                CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Cp helper started.")
+                logger:debug(self, "Cp helper started.")
             else
-                CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Could not start CP helper: %s", tostring(message))
+                logger:debug(self, "Could not start CP helper: %s", tostring(message))
                 if message then
                     g_currentMission:showBlinkingWarning("CP: " .. message, 5000)
                 end
             end
         else
-            CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Could not start CP helper!")
+            logger:debug(self, "Could not start CP helper!")
         end
     end
 end
@@ -352,10 +354,10 @@ function CpAIWorker:stopCurrentAIJob(superFunc, message, ...)
                         -- since we often stop for instance in convoy mode when waiting for another vehicle to turn
                         -- (when we do this, we set our maxSpeed to 0). So we also check our maxSpeed, this way the Giants timer will
                         -- fire if we are blocked (thus have a maxSpeed > 0 but not moving)
-                        CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, 'Overriding the Giants did not move timer, with speed: %.2f', maxSpeed)
+                        logger:debug(self, 'Overriding the Giants did not move timer, with speed: %.2f', maxSpeed)
                         return
                     else
-                        CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, 'Giants did not move timer triggered, with speed: %.2f!', maxSpeed)
+                        logger:debug(self, 'Giants did not move timer triggered, with speed: %.2f!', maxSpeed)
                     end
                 end
             end
@@ -364,7 +366,7 @@ function CpAIWorker:stopCurrentAIJob(superFunc, message, ...)
             return
         end
     end
-    CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "stop message: %s", message:getI18NText())
+    logger:debug(self, "stop message: %s", message:getI18NText())
     superFunc(self, message,...)
 end
 
@@ -385,6 +387,7 @@ function CpAIWorker:onUpdate(dt)
             return
         end
         local tX, tZ, moveForwards, maxSpeedStrategy = spec.driveStrategy:getDriveData(dt)
+        logger:debug('Speed %.1f', maxSpeedStrategy)
         local maxSpeed = math.min(maxSpeedStrategy or math.huge, self:getCruiseControlMaxSpeed())
         if not spec.driveStrategy then
             return
@@ -533,13 +536,13 @@ end
 --- Auto drive stop
 function CpAIWorker:onStopAutoDrive(isPassingToCP, isStartingAIVE)
     if g_server then
-        CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "isPassingToCP: %s, isStartingAIVE: %s", tostring(isPassingToCP), tostring(isStartingAIVE))
+        logger:debug(self, "isPassingToCP: %s, isStartingAIVE: %s", tostring(isPassingToCP), tostring(isStartingAIVE))
         if self.ad.restartCP then
             --- Is restarted for refilling or unloading.
-            CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Was refilled/unloaded by AD.")
+            logger:debug(self, "Was refilled/unloaded by AD.")
         else
             --- Is sent to a field.
-            CpUtil.debugVehicle(CpDebug.DBG_FIELDWORK, self, "Was sent to field by AD.")
+            logger:debug(self, "Was sent to field by AD.")
         end
     end
 end

scripts/util/Profiler.lua

@@ -0,0 +1,50 @@
+Profiler = CpObject()
+
+function Profiler:init(vehicle, n)
+    self.logger = Logger('Profiler', Logger.level.debug, CpUtil.DBG_PERF)
+    self.movingAverage = MovingAverage(n or 100)
+    self.elapsed = 0
+    self.max = 0
+    self.min = math.huge
+    self.vehicle = vehicle
+end
+
+function Profiler:start()
+    self.startSec = getTimeSec()
+end
+
+function Profiler:stop()
+    self.elapsed = getTimeSec() - self.startSec
+    self.movingAverage:update(self.elapsed)
+    if self.elapsed > self.max then
+        self.max = self.elapsed
+    end
+    if self.elapsed < self.min then
+        self.min = self.elapsed
+    end
+end
+
+function Profiler:getAverageMs()
+    return self.movingAverage:get() * 1000
+end
+
+function Profiler:getMaxMs()
+    return self.max * 1000
+end
+
+function Profiler:getMinMs()
+    return self.min * 1000
+end
+
+function Profiler:log()
+    self.logger:debug(self.vehicle, "avg: %.3f ms, min: %.3f ms, max: %.3f ms",
+            self:getAverageMs(), self:getMinMs(), self:getMaxMs())
+end
+
+function Profiler:render()
+    if not CpUtil.isVehicleDebugActive(self.vehicle) or not CpDebug:isChannelActive(CpDebug.DBG_PERF) then
+        return
+    end
+    renderText(0.8, 0.9, 0.018, string.format('current: %.1f ms, average: %.1f ms',
+            self.elapsed * 1000, self:getAverageMs()))
+end