Developer Stuff

page to put things and stuff

• Profiling Code
  • In-Game Macros
    • Print the profiles after combat
    • Clear the data after printing
  • Hekili.lua
    • Updated ProfileCPU function
    • Function for storing data over time (live profiling), scalable
    • Print Function for the profiler
    • Clear data for print function
    • GetNextPrediction Profile printer (real time instead of CPU time)
    • Clear data from GetNextPrediction Profile printer
  • Scripts.lua
    • Updated CheckScript with profiling for individual APL entries
    • GetModifiers with profiling
    • GetConditionsAndValues with profiling

Profiling Code

In-Game Macros

Print the profiles after combat

/run Hekili:PrintProfileSummary()
/run Hekili:PrintNextPredictionProfile()

Clear the data after printing

/run Hekili:ClearProfileData()
/run Hekili:ResetNextPredictionProfile()

Hekili.lua

Updated ProfileCPU function

This is the function that allows you to write stuff like this to have a function added to the profiler Hekili:ProfileCPU( "QueueEvent", state.QueueEvent ) Hekili:ProfileCPU( "ThreadedUpdate", Hekili.Update ) Hekili:ProfileCPU( "GetNextPrediction", Hekili.GetNextPrediction )

Theoretically, you can add any function you want.

    local cpuProfileDB = {}
    Hekili.CPUProfileResults = {}
    
    function Hekili:ProfileCPU(name, func)
        -- Store the original function for reference
        cpuProfileDB[name] = func
    
        -- Wrap the function to measure CPU time
        self.CPUProfileResults[name] = { totalCPUTime = 0, calls = 0, maxCPU = 0, minCPU = math.huge }
    
        -- Redefine the function with a profiling wrapper
        self[name] = function(...)
            local startCPU = debugprofilestop()
            local result = { func(...) }
            local endCPU = debugprofilestop()
    
            -- Calculate CPU time for this call
            local cpuTime = endCPU - startCPU
    
            -- Update profiling data
            local profileData = self.CPUProfileResults[name]
            profileData.totalCPUTime = profileData.totalCPUTime + cpuTime
            profileData.calls = profileData.calls + 1
            profileData.maxCPU = math.max(profileData.maxCPU, cpuTime)
            profileData.minCPU = math.min(profileData.minCPU, cpuTime)
    
            -- Return the original function's results
            return unpack(result)
        end
    end

Function for storing data over time (live profiling), scalable

function Hekili:AddProfileData(name, timeSpent)
    self.ProfileResults = self.ProfileResults or {}

    if not self.ProfileResults[name] then
        self.ProfileResults[name] = { totalTime = 0, count = 0, max = 0, min = math.huge }
    end

    local result = self.ProfileResults[name]
    result.totalTime = result.totalTime + timeSpent
    result.count = result.count + 1
    result.max = math.max(result.max, timeSpent)
    result.min = math.min(result.min, timeSpent)
end

Print Function for the profiler

function Hekili:PrintProfileSummary()
    -- Ensure there is profiling data to print
    if not self.ProfileResults or next(self.ProfileResults) == nil then
        print("No profiling data recorded.")
    else
        -- Prepare a list of keys sorted by total time in descending order
        local sortedEntries = {}
        for name, data in pairs(self.ProfileResults) do
            table.insert(sortedEntries, { name = name, data = data })
        end

        -- Sort by totalTime in descending order
        table.sort(sortedEntries, function(a, b)
            return a.data.totalTime > b.data.totalTime
        end)

        -- Print the top 10 entries by total time
        print("Top 10 APL Entries (Sorted by Total Time in Descending Order):")
        for i = 1, math.min(10, #sortedEntries) do
            local entry = sortedEntries[i]
            local name = entry.name
            local data = entry.data
            local avg = data.totalTime / data.count
            local pack, list, entryNumber = name:match("Conditions:(.-):(.-):(%d+)")
            
            print(string.format("Conditions: %s: %s - Total Time: %.1f ms | Calls: %d | Avg: %.3f ms | Max: %.3f ms | Min: %.3f ms",
                list or "N/A", entryNumber or "N/A", data.totalTime, data.count, avg, data.max, data.min))
        end
    end

      -- Check for CPU profiling data
      if Hekili.CPUProfileResults then
        print("\nCPU Profile Summary:")

        -- Sort CPU profiling data by total CPU time in descending order
        local cpuSortedEntries = {}
        for funcName, data in pairs(Hekili.CPUProfileResults) do
            table.insert(cpuSortedEntries, { funcName = funcName, data = data })
        end

        table.sort(cpuSortedEntries, function(a, b)
            return a.data.totalCPUTime > b.data.totalCPUTime
        end)

        -- Print the top entries by total CPU time
        for i = 1, math.min(10, #cpuSortedEntries) do
            local entry = cpuSortedEntries[i]
            local funcName = entry.funcName
            local data = entry.data
            local avgCPU = data.totalCPUTime / data.calls

            print(string.format("Function: %s - Total CPU Time: %.1f ms | Calls: %d | Avg CPU: %.3f ms | Max CPU: %.3f ms | Min CPU: %.3f ms",
                funcName, data.totalCPUTime, data.calls, avgCPU, data.maxCPU, data.minCPU))
        end
    else
        print("No CPU profiling data recorded.")
    end

    -- Add engine performance data if available
    if Hekili.Engine and Hekili.Engine.threadUpdates then
        local engineData = Hekili.Engine.threadUpdates
        print("\nEngine Thread Performance Summary:")
        print(string.format("Updates Per Second: %.2f", engineData.updatesPerSec or 0))
        print(string.format("Mean Clock Time: %.3f ms | Peak Clock Time: %.3f ms", engineData.meanClockTime or 0, engineData.peakClockTime or 0))
        print(string.format("Mean Work Time: %.3f ms | Peak Work Time: %.3f ms", engineData.meanWorkTime or 0, engineData.peakWorkTime or 0))
        print(string.format("Mean Frames: %.2f | Peak Frames: %.2f", engineData.meanFrames or 0, engineData.peakFrames or 0))
        print(string.format("Total Wasted Time: %.3f ms | Peak Wasted Time: %.3f ms | Mean Wasted Time: %.3f ms",
            engineData.totalWasted or 0, engineData.peakWasted or 0, engineData.meanWasted or 0))
    else
        print("No engine performance data recorded.")
    end
end

Clear data for print function

-- Function to clear all profiling data
function Hekili:ClearProfileData()
    -- Ensure the ProfileResults and CPUProfileResults tables exist
    self.ProfileResults = self.ProfileResults or {}
    self.CPUProfileResults = self.CPUProfileResults or {}

    -- Wipe the ProfileResults table
    wipe(self.ProfileResults)
    print("Profiling data cleared.")

    -- Wipe the CPUProfileResults table
    wipe(self.CPUProfileResults)
    print("CPU profiling data cleared.")

    -- Clear the engine performance data if available
    if Hekili.Engine and Hekili.Engine.threadUpdates then
        Hekili.Engine.threadUpdates = {
            meanClockTime  = 0,
            meanWorkTime   = 0,
            meanFrames     = 0,
            meanWasted     = 0,
            firstUpdate    = 0,
            updates        = 0,
            updatesPerSec  = 0,
            peakClockTime  = 0,
            peakWorkTime   = 0,
            peakFrames     = 0,
            peakWasted     = 0,
            totalWasted    = 0
        }
        print("Engine performance data cleared.")
    else
        print("No engine performance data to clear.")
    end
end

GetNextPrediction Profile printer (real time instead of CPU time)

function Hekili:PrintNextPredictionProfile()
    local data = self.NextPredictionProfile

    if data.count == 0 then
        print("No GetNextPrediction calls have been recorded.")
        return
    end

    -- Calculate average time
    local avgTime = data.totalTime / data.count

    -- Print the results with combat status
    print(string.format("GetNextPrediction - Total Time: %.4f ms, Calls: %d, Average Time per Call: %.4f ms %s", 
        data.totalTime, data.count, avgTime, data.inCombat and "(In Combat)" or "(Out of Combat)"))
end

Clear data from GetNextPrediction Profile printer

function Hekili:ResetNextPredictionProfile()
    self.NextPredictionProfile.totalTime = 0
    self.NextPredictionProfile.count = 0
    print("GetNextPrediction profiling data has been reset.")
end

Scripts.lua

Updated CheckScript with profiling for individual APL entries

function scripts:CheckScript(scriptID, action, elem)
    -- Capture the action we're checking.
    local prev_action = state.this_action
    if action then state.this_action = action end

    -- Retrieve the script from the database.
    local script = self.DB[scriptID]

    if not script then
        state.this_action = prev_action
        return false
    end

    -- Profiling for the entire CheckScript function.
    local startCheckScript
    if InCombatLockdown() then
        startCheckScript = debugprofilestop()
    end

    -- Initialize the result variables.
    local result, errorMessage

    if not elem then
        -- Profiling for general Conditions.
        local startConditions, timeSpentConditions
        if InCombatLockdown() then
            startConditions = debugprofilestop()
        end

        if script.Error then
            result = false
            errorMessage = script.Error

        elseif not script.Conditions then
            result = true

        else
            -- Error handling for Conditions to catch potential issues.
            local success, conditionsResult = pcall(script.Conditions)
            if success then
                result = conditionsResult
            else
                result = false
                errorMessage = "Error in Conditions: " .. conditionsResult
            end
        end

        -- Record time spent on Conditions evaluation.
        if InCombatLockdown() and startConditions then
            timeSpentConditions = debugprofilestop() - startConditions
            Hekili:AddProfileData("CheckScript:Conditions:" .. scriptID, timeSpentConditions)
        end

    else
        -- Profiling for Modifier checks.
        local startModifier, timeSpentModifier
        if InCombatLockdown() then
            startModifier = debugprofilestop()
        end

        if not script.Modifiers[elem] then
            result = nil
            errorMessage = elem .. " not set."

        else
            local success, value = pcall(script.Modifiers[elem])
            if success then
                result = value
            else
                result = false
                errorMessage = "Error in Modifier " .. elem .. ": " .. value
            end
        end

        -- Record time spent on the Modifier evaluation.
        if InCombatLockdown() and startModifier then
            timeSpentModifier = debugprofilestop() - startModifier
            Hekili:AddProfileData("CheckScript:Modifier:" .. scriptID .. ":" .. elem, timeSpentModifier)
        end
    end

    -- Restore the previous action state.
    state.this_action = prev_action

    -- Record the total time for CheckScript if applicable.
    if InCombatLockdown() and startCheckScript then
        local timeSpentTotal = debugprofilestop() - startCheckScript
        Hekili:AddProfileData("CheckScript:Total:" .. scriptID, timeSpentTotal)
    end

    -- Return the result with potential error message.
    return result, errorMessage
end

GetModifiers with profiling

function scripts:GetModifiers(scriptID, out)
    print("GetModifiers called for scriptID:", scriptID)  -- Debug print
    -- Start profiling for the whole GetModifiers function
    local startTotal
    if InCombatLockdown() then
        print("In combat, starting profiling for GetModifiers")  -- Debug print
        startTotal = debugprofilestop()
    end

    out = out or {}
    local script = self.DB[scriptID]

    if not script then
        print("No script found for scriptID:", scriptID)  -- Debug print
        -- End profiling if exiting early
        if InCombatLockdown() and startTotal then
            local endTotal = debugprofilestop() - startTotal
            Hekili:AddProfileData("GetModifiers:" .. scriptID, endTotal)
        end
        return out
    end

    for k, v in pairs(script.Modifiers) do
        local start, timeSpent
        if InCombatLockdown() then
            start = debugprofilestop()
            print("Profiling modifier:", k)  -- Debug print
        end
        
        local success, value = pcall(v)
        
        if success then
            out[k] = value
        else
            print("Failed to execute modifier:", k)  -- Debug print for failure
        end

        -- Record profiling data for each modifier
        if InCombatLockdown() and start then
            timeSpent = debugprofilestop() - start
            print("Time spent on modifier:", k, "=", timeSpent)  -- Debug print
            Hekili:AddProfileData("Modifier:" .. k, timeSpent)
        end
    end

    -- End profiling for the entire function
    if InCombatLockdown() and startTotal then
        local endTotal = debugprofilestop() - startTotal
        Hekili:AddProfileData("GetModifiers:" .. scriptID, endTotal)
        print("Total time spent on GetModifiers:", endTotal)  -- Debug print
    end

    return out
end

GetConditionsAndValues with profiling

    function scripts:GetConditionsAndValues(scriptID, listName, actID, recheck)
        -- Skip if snapshot or debug is not enabled
        if troubleshootingSnapshotTimes or not Hekili.ActiveDebug then return "[no data]" end
    
        -- Adjust scriptID if listName and actID are provided
        if listName and actID then
            scriptID = scriptID .. ":" .. listName .. ":" .. actID
        end
    
        -- Start profiling for the whole GetConditionsAndValues function
        local startTotal = debugprofilestop()
        
        -- Retrieve the script from the database
        local script = self.DB[scriptID]
        
        -- Check if this is a recheck and profile accordingly
        if recheck then
            local startRecheck = debugprofilestop()
            local result = embedConditionsAndValues(script.RecheckScript, script.RecheckElements)
            local endRecheck = debugprofilestop() - startRecheck
            Hekili:AddProfileData("RecheckConditions:" .. scriptID, endRecheck)
            
            -- End profiling for total function and return
            local endTotal = debugprofilestop() - startTotal
            Hekili:AddProfileData("GetConditionsAndValues:" .. scriptID, endTotal)
            
            return result
        end
    
        -- Profile if there is a custom Print function
        if script.Print then
            local startPrint = debugprofilestop()
            local result = script.Print()
            local endPrint = debugprofilestop() - startPrint
            Hekili:AddProfileData("PrintFunction:" .. scriptID, endPrint)
            
            -- End profiling for total function and return
            local endTotal = debugprofilestop() - startTotal
            Hekili:AddProfileData("GetConditionsAndValues:" .. scriptID, endTotal)
            
            return result
        end
    
        -- Profile standard condition evaluation with embedConditionsAndValues
        local startEmbed = debugprofilestop()
        local result = embedConditionsAndValues(script.SimC, script.Elements)
        local endEmbed = debugprofilestop() - startEmbed
        Hekili:AddProfileData("ConditionEvaluation:" .. scriptID, endEmbed)
    
        -- End profiling for total function
        local endTotal = debugprofilestop() - startTotal
        Hekili:AddProfileData("GetConditionsAndValues:" .. scriptID, endTotal)
        
        return result
    end