Measuring addon load times?

[Terrillyn]

I'm wondering if there is a way (maybe built-in) to measure the load time of all addons, I've tried measuring the time between EVENT_ADD_ON_LOADED calls, but results seem to be wrong (maybe due to how the events are called), or measuring something else.

what I tried:

AddonLoadingTime = {
    name = "AddonLoadingTime",
    author = "",
    version = "100013.000",
}
 
local GetTime = GetGameTimeMilliseconds
local loadingTimes = {}
local lastAddonName = nil
local lastTick = GetTime()
 
function AddonLoadingTime.OnAddOnLoaded(event, addonName)
    if lastAddonName then
        loadingTimes[lastAddonName] = (GetTime() - lastTick)
    end
 
    lastAddonName = addonName
    lastTick = GetTime()
end
 
function AddonLoadingTime.OnPlayerActivated(event)
    for k,v in pairs(loadingTimes) do
        if not string.match(k, '^ZO_') then
            d(string.format("%s took %s ms", k, tostring(v)))
        end
    end
 
    EVENT_MANAGER:UnregisterForEvent(AddonLoadingTime.name, EVENT_PLAYER_ACTIVATED)
end
 
EVENT_MANAGER:RegisterForEvent(AddonLoadingTime.name, EVENT_ADD_ON_LOADED, AddonLoadingTime.OnAddOnLoaded)
EVENT_MANAGER:RegisterForEvent(AddonLoadingTime.name, EVENT_PLAYER_ACTIVATED, AddonLoadingTime.OnPlayerActivated)

example output:

merTorchbug took 4 ms
SkyShards took 7 ms
HarvensExtendedStats took 0 ms
DeveloperSuite took 0 ms
AddonLoadingTime took 4 ms
BankManagerRevived took 88 ms
HarvestMapDC took 0 ms
WidgetTest took 9 ms
Destinations took 0 ms
ImmersionToggles took 38 ms
SimpleXPBar took 10 ms
HarvestMap took 4 ms
AUI took 0 ms
AwesomeInfo took 120 ms
Ledger took 0 ms
HarvestMapEP took 0 ms
DevTools took 0 ms
JunkIt took 182 ms
AddonTemplate took 12 ms

One of the reasons I think this is wrong is because ImmersionToggles is taking 38ms while Destinations is taking 0ms this is pretty much nonsense, since ~3 times as much work is going on at the startup of Destinations. These results are pretty consistent though even when the load order is different, so I don't think its noise from calls in-between. Am I doing this wrong? or is it even possible to measure these correctly?

EDIT: So after thinking about it a bit more, I can only assume the my results are scewed because of the order in which the events are called, e.g. sometimes AddonLoadingTime.OnAddOnLoaded is being called before the target addon and sometimes after. So maybe measuring this isn't doable, or I may need to use another method.

[sorry if this is the wrong subforum wasn't sure which to post this in]

[sirinsidiator]

This method won't tell you anything at all about addon load times, because you never know what happens between two events.
For example there could be any number of controls being updated inbetween. Addons could also defer some work and either do it in a different event (player activated) or via zo_callLater.
In order to measure the loading time, you would need to edit the addons directly and add a StartMeasurement() and StopMeasurement() into the appropriate lines of code.

[haggen]

I have the impression that the last step of loading any add-on is to initialize the top level controls, so I'd test something like:

1. Saving the time in the first line of the very first file in your manifest.
2. Comparing it to the time of the OnInitialize callback from your top level control.

If you don't have any XML create an empty TopLevelControl with just the callback in question.

I might be wrong about this but I think it's worth a shot. The OnAddOnLoaded event is unreliable, as said by @sirinsidiat0r, the game might trigger it way after your add-on has actually been loaded.

[Ayantir]

To improve user loading time, don't look at your code, look at master merchant one

[Terrillyn]

Originally Posted by sirinsidiator This method won't tell you anything at all about addon load times, because you never know what happens between two events. For example there could be any number of controls being updated inbetween. Addons could also defer some work and either do it in a different event (player activated) or via zo_callLater. In order to measure the loading time, you would need to edit the addons directly and add a StartMeasurement() and StopMeasurement() into the appropriate lines of code.

That's what I figured, it wasn't really important enough for me to edit other addons, I was mostly trying to find which addon was causing long load times, I ended up narrowing it down to craftstore which as adding around 4seconds.

To improve user loading time, don't look at your code, look at master merchant one

I didn't really see anything in there that would help load times but it was a jungle of code so I didn't know what I was looking for anyways.