How to create benchmarking event handler method for a scripted entity.

dvd_video-legacy · August 23, 2017, 1:54pm

So guys,

As I was coding yesterday, decided to create benchmearking handler for my spinner.

I want to set the sampling time in [ms]

dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L89


function ENT:GetSpinCenter()
  if(SERVER)     then return self:GetPhysicsObject():GetMassCenter()
  elseif(CLIENT) then return self:GetNWVector(gsSentHash.."_cen") end
end
function ENT:IsToggled()
  if(SERVER)     then local oSent = self[gsSentHash]; return oSent.Togg
  elseif(CLIENT) then return self:GetNWBool(gsSentHash.."_togg") end
end
if(SERVER) then
  -- Represents the arguments of ENT:BroadCast()
  local gtBroadCast = {
    [1] = {"SetNWFloat", gsSentHash.."_power", 0},
    [2] = {"SetNWFloat", gsSentHash.."_lever", 0}
  }
  -- Used for rate array output
  local gtRateMap = {
    [1]  = {"bcTot", 1000},
    [2]  = {"bcTim", 1000},
    [3]  = {"eTick", 1000},

and display the amount of CPU time taken
https://github.com/dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L95 for all the calculations here:

github.com

dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L249


  oSent.IsERM = varRemoveER:GetBool() -- Whenever to remove the entity on error
  oSent.IsTDB = varEnableDT:GetBool() -- Enables the tick rate system array output
  oSent.Rate.isWDT = varEnableWT:GetBool() -- Translate SENT watchdog to an error
  oSent.Rate.bcTot = (varBroadCast:GetFloat() / 1000) -- Broadcast time sever-clients [ms] to [s]
  oSent.Rate.bcTim = (varBroadCast:GetFloat() / 1000) -- Broadcast compare value      [ms] to [s]
  oSent.Rate.eTick = (varTickRate:GetFloat()  / 1000) -- Entity ticking interval      [ms] to [s]
  return self
end
function ENT:Setup(stSpinner)
  self:SetPhysRadius(stSpinner.Radi)         -- Set the radius if given
  local oPhys = self:GetPhysicsObject()
  if(oPhys and oPhys:IsValid()) then
    self:SetToggled(stSpinner.Togg)          -- Is it going to be toggled
    self:SetTorqueAxis(stSpinner.AxiL)       -- Axis direction
    self:SetPower(stSpinner.Power)           -- Torque amount
    self:SetTorqueLever(stSpinner.LevL, stSpinner.CLev) -- Lever direction and count
    self:SetLever(stSpinner.Lever)           -- Leverage length
    self:SetNWVector(gsSentHash.."_cen", oPhys:GetMassCenter())
    local oSent = self[gsSentHash]
    local nMass = math.Clamp(tonumber(stSpinner.Mass) or 1, 1, varMaxMass:GetFloat())

However it seems that the broadcasting event https://github.com/dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L257
does not trigger at 300 [ms] as expected.

Looks like the tame delta in [ms] is calculated wrong here:

github.com

dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L246


function ENT:ApplyTweaks()
  local oSent  = self[gsSentHash]
  oSent.IsERM = varRemoveER:GetBool() -- Whenever to remove the entity on error
  oSent.IsTDB = varEnableDT:GetBool() -- Enables the tick rate system array output
  oSent.Rate.isWDT = varEnableWT:GetBool() -- Translate SENT watchdog to an error
  oSent.Rate.bcTot = (varBroadCast:GetFloat() / 1000) -- Broadcast time sever-clients [ms] to [s]
  oSent.Rate.bcTim = (varBroadCast:GetFloat() / 1000) -- Broadcast compare value      [ms] to [s]
  oSent.Rate.eTick = (varTickRate:GetFloat()  / 1000) -- Entity ticking interval      [ms] to [s]
  return self
end
function ENT:Setup(stSpinner)
  self:SetPhysRadius(stSpinner.Radi)         -- Set the radius if given
  local oPhys = self:GetPhysicsObject()
  if(oPhys and oPhys:IsValid()) then
    self:SetToggled(stSpinner.Togg)          -- Is it going to be toggled
    self:SetTorqueAxis(stSpinner.AxiL)       -- Axis direction
    self:SetPower(stSpinner.Power)           -- Torque amount
    self:SetTorqueLever(stSpinner.LevL, stSpinner.CLev) -- Lever direction and count
    self:SetLever(stSpinner.Lever)           -- Leverage length

But when we see that SysTime() returns the time in seconds, so when I subtract seconds from seconds and multiply by 1000 to get the [ms] and the result is about (0.025),
which is quite small, considering the 300 [ms] for broadcast pass like 300 seconds …

Do any Ideas ?

code_gs-legacy · August 23, 2017, 3:02pm

Your time calculation isn’t wrong: you are thinking it takes much longer than it actually is. The problem is that you aren’t returning true in ENT:Think, so your NextThink call won’t be applied.

dvd_video-legacy · August 23, 2017, 3:17pm

Hmm, I do recall putting it at the end of the line though

github.com

dvdvideo1234/SpinnerTool/blob/master/lua/entities/sent_spinner.lua#L301


    tmRate.thEvt = (tmRate.thStN - tmRate.thStO) -- Think event delta [s]
    tmRate.thTim = (tmRate.thEnd - tmRate.thStO) -- Think hook delta [s]
    tmRate.thDet = (tmRate.thTim / tmRate.thEvt) * 100 -- Think duty margin []
    if(tmRate.thTim >= tmRate.thEvt and tmRate.isWDT) then -- Watchdog error
      self:SetError("ENT.Tic: Duty margin fail ["..tostring(tmRate.thDet).."%]") end
    tmRate.bcTim = tmRate.bcTim - tmRate.thEvt         -- Update broadcast time [s]
  end; return self
end
function ENT:Toc()
  local tmRate = self[gsSentHash].Rate
  tmRate.thEnd = sysNow()
  if(not tmRate.isRdy) then tmRate.isRdy = true end
  return self
end
function ENT:BroadCast(...)
  local tmRate = self[gsSentHash].Rate
  if(tmRate.bcTim <= 0) then
    local arList = {...}               -- Values stack for networking
    for ID = 1, #gtBroadCast do        -- Go trough all like a list

code_gs-legacy · August 23, 2017, 3:18pm

Sorry, it’s very difficult to read the single-line multi-statements on mobile. Just my first point, then.

dvd_video-legacy · August 23, 2017, 3:23pm

I do think it takes too long. 300 [ms] are 1/3 of a second, though the trigger event takes about a minute to be called, which is kinda weird LOL.

dvd_video-legacy · September 27, 2017, 2:13pm

Found the problem. On Entiti initialization I was inserting the time in [s] instead of [ms]

Fixed now ! Cheers !