Addon system bug reports

[Adelea]

Inspect.System.Watchdog() seems to be bugged at the moment, always returning 0.1s no matter what.

I found this out when updating my diagnostic tracking to store the closest the Watchdog timer got to triggering a warning.

It most certainly does not always return 0.1 =)

In my MoneyBags addon I build all the UI elements (about 150 or so UI.CreateFrame() calls), and I have liberal smatterings of this function:

local yieldcnt = 0
local function WATCHDOGWAIT(x)
	local rmx = Inspect.System.Watchdog()
	while rmx < 0.05 do
		yieldcnt = yieldcnt+1
		Debug("#"..yieldcnt..":rmx: "..rmx.." ["..x.."]",20)
		coroutine.yield()
		rmx = Inspect.System.Watchdog()
	end
end

And after a /reloadui or fresh login, I can see that it has to yield fairly often :

11:59:35: [MoneyBags] #1:rmx: 0.02849086932838 [BuildUIElements:8:Planarite]
11:59:35: [MoneyBags] #2:rmx: 0.016551787033677 [BuildUIElements:8:Cursed Sourcestone]
11:59:35: [MoneyBags] #3:rmx: 0.040966678410769 [BuildUIElements:11]

I have seen as many as 15 frames where it has yielded due to running out of time -- but it doesnt throw up performance warnings any more =)

[Semele]

Ok, then I'll re-phrase it to on US servers it's broken - or off, or something.

[DoomSprout]

Ok, then I'll re-phrase it to on US servers it's broken - or off, or something.

But the doggy lives in the client; he's tucked up behind your hard-drive, drooling on your graphics card and waiting to pounce as soon as your CPU is distracted...

[Semele]

But the doggy lives in the client; he's tucked up behind your hard-drive, drooling on your graphics card and waiting to pounce as soon as your CPU is distracted...

How is it I always get a flat value from the command then, sure KBM isn't that fast. The calls are made inside known issue handlers.

I even had it print directly per call to ensure there was no rounding issues, and the value returned by the command is ALWAYS 0.1000000149012 - code used: dump(Inspect.System.Watchdog())

I'm suggesting the US client didn't patch with it, or I'm missing a trick somewhere. Or I have a "special" client. Either way, that doesn't look right to me.

[DoomSprout]

How is it I always get a flat value from the command then, sure KBM isn't that fast. The calls are made inside known issue handlers.

I even had it print directly per call to ensure there was no rounding issues, and the value returned by the command is ALWAYS 0.1000000149012 - code used: dump(Inspect.System.Watchdog())

I'm suggesting the US client didn't patch with it, or I'm missing a trick somewhere. Or I have a "special" client. Either way, that doesn't look right to me.

The watchdog runs in a separate thread, and there are some clever arcane shenanigans going on somewhere to keep the watchdog thread and the addon execution thread talking to each other. I don't know how it works, but here's a scenario that *could* explain it...

The watchdog wakes up every 100ms, and makes a note of the current time, and which event handler is currently running. If the same handler is running the next time the dog wakes up, it throws the performance warning.

When you call Inspect.Watchdog(), if the event handler the dog saw is different to the one currently running, it always returns 0.1s, otherwise it returns (0.1 - time since dog last woke up).

This means a lucky handler could get 0.1999s to run, an unlucky one exactly 0.1s.

This would tie in with what Zorba said about you always getting at least the reported time, and maybe more.

If I'm right with this theory (and I'm probably not), if you call Inspect() before the dog wakes up during your event handler, you'll always see 0.1s. For a really quick handler, this will probably happen most of the time. Or... if you are making the call right at the start of your handler, it'll probably always return 0.1s as well.

When you get the warnings fired out in the wild, it could be something totally unrelated to the addon that caused a hiccup on the user's machine. They decided to defrag their hard-drive, alt-tabbed out of RIFT, opened up a 15th copy of RIFT while multi-boxing, etc.

With an addon as massively used as KBM, it's not going to take many little hiccups to trigger the warning email.

PS. In practice, I'd assume the dog wakes up more often than every 100ms, but the same rough theory would still apply. There will be a chunk of time before the dog wakes up and notices your event handler running where you'll always see 0.1s.

[Adelea]

How is it I always get a flat value from the command then, sure KBM isn't that fast. The calls are made inside known issue handlers.

I even had it print directly per call to ensure there was no rounding issues, and the value returned by the command is ALWAYS 0.1000000149012 - code used: dump(Inspect.System.Watchdog())

I'm suggesting the US client didn't patch with it, or I'm missing a trick somewhere. Or I have a "special" client. Either way, that doesn't look right to me.

When are you measuring time remaining?

If I try this in luapad:

local trash = {}
local context = UI.CreateContext("test")

local t1 = Inspect.Time.Real()
local w1 = Inspect.System.Watchdog()

for x=1, 1000 do
trash[x] = UI.CreateFrame("Frame", "testframe", context)
end

local w2 = Inspect.System.Watchdog()
local t2 = Inspect.Time.Real()

print(string.format("Time taken: %f, watchdog time: %f (%f-%f)", t2-t1, w1-w2, w1, w2))

And click run, I get:

Time taken: 0.048958, watchdog time: 0.043367 (0.100000-0.056633)

If I put this as a function inside an addon and run it directly from the console :

/script _MoneyBags.testthis()
13:41:36: [/script] Time taken: 0.029826, watchdog time: 0.000000 (0.100000-0.100000)

If I then instead run it from inside a coroutine being driven by Event.System.Update.Begin :

/script _MoneyBags.b_testthis = true
13:44:52: [MoneyBags] Time taken: 0.029423, watchdog time: 0.000000 (0.100000-0.100000)

So, elapsed time is non-zero, but watchdog time remains unused - so I guess inside one of those you have more than 0.1s available sometimes moments.

If I then turn it around, so instead of timing how long X takes, we see how many X we can do in the time:

local trash = {}
local context = UI.CreateContext("test")
local cnt=0
local w1 = Inspect.System.Watchdog()
local x = w1
while x > 0.01 do
  cnt = cnt+1
  trash[cnt] = UI.CreateFrame("Frame", "testframe", context)
  x=Inspect.System.Watchdog()
end

print(string.format("%d frames created in %f watchdog time", cnt, w1-x))

From inside luapad:

3277 frames created in 0.090027 watchdog time

Calling an addon function directly:

2223 frames created in 0.089458 watchdog time

And finally running the addon function via a coroutine handler:

3141 frames created in 0.090006 watchdog time

I dont really understand why the first example doesnt use any watchdog time when running code from an addon, but the second does though...

[Adelea]

Did a bit of playing around with the 1st example from my post, bumping the number in the loop to 100,000

It locked up my client, and after about 3s, it was killed :

Error: performance error, execution halted
In Console / /script
stack traceback:
[C]: in function 'createFrame_core'
MoneyBags/MoneyBags_Main.lua:1248: in function 'testthis1'
[string "_MoneyBags.testthis1()"]:1: in main chunk

I had been saving the loop counter to a global variable, and it had reached 24,862

So maybe the 1000 was too small.

I repeated the test with the counter set to 5000

Time taken: 0.257508, watchdog time: 0.100000 (0.100000-0.000000)

And it threw up a performance warning

But something seems weird that 1000 iterations take 0 time, but 5000 invokes the 'dog.

[Semele]

This isn't some quick test where I test it with a quick call to dump, it's maintained lowest result of the course of any length of time with real-world diagnostics. It is as accurate as it's going to get without it being run as a separate program/thread entirely with high priority.

KBM's latest version has this in it, and is constantly watching it's own 3 main handlers which give reports. Buff additions, Unit Availability and the Main System.Update.Begin handler.

function KBM:BuffAdd(unitID, Buffs)
	-- Used to manage Triggers and soon Tank-Swap managing.
	local TimeStore = Inspect.Time.Real()
	
	if KBM.Options.Enabled then
		if KBM.Encounter then
			if unitID then
				for BuffID, bool in pairs(Buffs) do
					local bDetails = Inspect.Buff.Detail(unitID, BuffID)
					if bDetails then
						if not KBM.Buffs.Active[unitID] then
							KBM.Buffs.Active[unitID] = {
								Buff_Count = 1,
							}
						else
							KBM.Buffs.Active[unitID].Buff_Count = KBM.Buffs.Active[unitID].Buff_Count + 1
						end
						KBM.Buffs.Active[unitID][BuffID] = bDetails
						if KBM.Trigger.Buff[KBM.CurrentMod.ID] then
							if KBM.Trigger.Buff[KBM.CurrentMod.ID][bDetails.name] then
								TriggerObj = KBM.Trigger.Buff[KBM.CurrentMod.ID][bDetails.name]
								if TriggerObj.Unit.UnitID == unitID then
									KBM.Trigger.Queue:Add(TriggerObj, unitID, unitID, bDetails.remaining)
								end
							end
						end
						if KBM.Trigger.PlayerDebuff[KBM.CurrentMod.ID] ~= nil and bDetails.debuff == true then
							if KBM.Trigger.PlayerDebuff[KBM.CurrentMod.ID][bDetails.name] then
								TriggerObj = KBM.Trigger.PlayerDebuff[KBM.CurrentMod.ID][bDetails.name]
								if LibSRM.Group.UnitExists(unitID) ~= nil or unitID == KBM.Player.UnitID then
									if KBM.Debug then
										print("Debuff Trigger matched: "..bDetails.name)
										if LibSRM.Grouped() then
											print("LibSRM Match: "..tostring(LibSRM.Group.UnitExists(unitID)))
										end
										print("Player Match: "..KBM.Player.UnitID.." - "..unitID)
										print("---------------")
										dump(bDetails)
									end
									KBM.Trigger.Queue:Add(TriggerObj, unitID, unitID, bDetails.remaining)
								end
							end
						end
						if KBM.Trigger.PlayerIDBuff[KBM.CurrentMod.ID] then
							if KBM.Trigger.PlayerIDBuff[KBM.CurrentMod.ID][bDetails.type] then
								TriggerObj = KBM.Trigger.PlayerIDBuff[KBM.CurrentMod.ID][bDetails.type]
								if LibSRM.Group.UnitExists(unitID) ~= nil or unitID == KBM.Player.UnitID then
									if KBM.Debug then
										print("Debuff Trigger matched: "..bDetails.name)
										if LibSRM.Grouped() then
											print("LibSRM Match: "..tostring(LibSRM.Group.UnitExists(unitID)))
										end
										print("Player Match: "..KBM.Player.UnitID.." - "..unitID)
										print("---------------")
										dump(bDetails)
									end
									KBM.Trigger.Queue:Add(TriggerObj, unitID, unitID, bDetails.remaining)
								end
							end
						end
						if KBM.Trigger.PlayerBuff[KBM.CurrentMod.ID] then
							if KBM.Trigger.PlayerBuff[KBM.CurrentMod.ID][bDetails.name] then
								TriggerObj = KBM.Trigger.PlayerBuff[KBM.CurrentMod.ID][bDetails.name]
								if LibSRM.Group.UnitExists(unitID) ~= nil or unitID == KBM.Player.UnitID then
									if KBM.Debug then
										print("Buff Trigger matched: "..bDetails.name)
										if LibSRM.Grouped() then
											print("LibSRM Match: "..tostring(LibSRM.Group.UnitExists(unitID)))
										end
										print("Player Match: "..KBM.Player.UnitID.." - "..unitID)
										print("---------------")
										dump(bDetails)
									end
									KBM.Trigger.Queue:Add(TriggerObj, unitID, unitID, bDetails.remaining)
								end
							end
						end
						if KBM.TankSwap.Active then
							if KBM.TankSwap.Tanks[unitID] then
								if KBM.TankSwap.DebuffName[bDetails.name] then
									KBM.TankSwap.Tanks[unitID]:BuffUpdate(BuffID, bDetails.name)
								end
							end
						end
					end
				end
			end
		else
			if unitID then
				for BuffID, bool in pairs(Buffs) do
					local bDetails = Inspect.Buff.Detail(unitID, BuffID)
					if bDetails then
						if not KBM.Buffs.Active[unitID] then
							KBM.Buffs.Active[unitID] = {
								Buff_Count = 1,
							}
						else
							KBM.Buffs.Active[unitID].Buff_Count = KBM.Buffs.Active[unitID].Buff_Count + 1
						end
						KBM.Buffs.Active[unitID][BuffID] = bDetails
						if KBM.Trigger.EncStart["playerBuff"] then
							if KBM.Trigger.EncStart["playerBuff"][bDetails.name] then
								TriggerMod = KBM.Trigger.EncStart["playerBuff"][bDetails.name]
								if TriggerMod.Dummy then
									KBM.CheckActiveBoss(TriggerMod.Dummy.Details, "Dummy")
								end
							end
						end
					end
				end
			end
		end
	end
	local TimeEllapsed = tonumber(string.format("%0.05f", Inspect.Time.Real() - TimeStore))
	local TimeLeft = Inspect.System.Watchdog()
	KBM.Watchdog.Buffs.Count = KBM.Watchdog.Buffs.Count + 1
	KBM.Watchdog.Buffs.Total = KBM.Watchdog.Buffs.Total + TimeEllapsed
	if KBM.Watchdog.Buffs.Peak < TimeEllapsed then
		KBM.Watchdog.Buffs.Peak = TimeEllapsed
	end
	if KBM.Watchdog.Buffs.wTime > TimeLeft then
		KBM.Watchdog.Buffs.wTime = TimeLeft
	end
	
end

But, since you asked, that's just the buff handler. I obviously wouldn't place the time tracing at the top, that would be incredibly stupid.

But, even if the Peak sits at 0.05 the results for the Watchdog do not change, ever. If you add a dump call to inspect in any of the 3 handlers in KBM, I get the same number, no mater the Peak time nor the actual handler duration. And the wTime variable (which initializes to 99 btw) is always stuck at 0.100...stupid float here.

[Semele]

Ok, I've gone through my logs and managed to find ONE!! occurrence of it registering a different watchdog time remaining of 0.098913s with a peak of 0.00099s execution time.

So, I guess it is working but I've optimized the hell out the new engine and it's just not triggering on my i7. This seems odd though, since this was with the above Buff.Add handler and has a sample size of 69,372 buffs tracked over the course of a HK run.

I had to dig around though, as most of the logs report 0.1 as per usual.

My bad, might as well delete this entire debate since it is working, just not very obvious on my machine, even during high stress situations such as full 20 man raids.

I guess the previous incarnations of the Watchdog have made me nervous.

[ZorbaTHut]

The watchdog runs in a separate thread, and there are some clever arcane shenanigans going on somewhere to keep the watchdog thread and the addon execution thread talking to each other. I don't know how it works, but here's a scenario that *could* explain it...

The watchdog wakes up every 100ms, and makes a note of the current time, and which event handler is currently running. If the same handler is running the next time the dog wakes up, it throws the performance warning.

When you call Inspect.Watchdog(), if the event handler the dog saw is different to the one currently running, it always returns 0.1s, otherwise it returns (0.1 - time since dog last woke up).

This means a lucky handler could get 0.1999s to run, an unlucky one exactly 0.1s.

This would tie in with what Zorba said about you always getting at least the reported time, and maybe more.

If I'm right with this theory (and I'm probably not)

Actually, you're pretty much dead-on. Good analysis.

[Adelea]

I've been rewriting sections of my Rattus addon, and noticed something strange this morning.

The Event.Achievement.Update event was being fired for the "Fishing for Artifacts" achievement.

This in itself isnt so weird, but I hadnt actually obtained one of the two artifacts I need, but had instead

- picked up a daily crafting quest that taught me a new temporary recipe.

Of the 8 daily quests I picked up, 5 taught me a new recipe, and each of those 5 fired the Achievement update event.

- listed something on the auction house.

I listed 18 items, and after each one the achievement update event fired.

[Adelea]

And more bad/weird behaviour...

When I change zone (but not on login)

Event.Achievement.Update() fires twice.

Once with 908 achievement IDs, and once with 3.

These 911 IDs contain 2 duplicates, so 909 uniques.

I'm fairly sure the act of zoning does not constitute updates for 909 achievements - in fact, I cannot see a single one that has anything to do with zoning around Argent Glade.

Looking further into these 909, only 880 are for Guardians, 29 are for Defiants.

For example:

/script dump(Inspect.Achievement.Detail("c6A11387959766A23 "))

10:19:06: [/script] {alliance = "defiant", category = "C0000004319E337BD", description = "Subscribe for 18 months.", faction = "defiant", icon = "Data/\\UI\\item_icons\\veteran_rewards_18.dds", id = "c6A11387959766A23", name = "18 Month Veteran", requirement = {{complete = true, count = 540, countDone = 540, name = "Subscribe for 18 months.", type = "event"}}, sort = 5000}

So, why I am receiving updates for achievements that I cannot possibly have changed since logging in?

And of the 880 that could perhaps be applicable to me, 806 were already completed.

/script dump(Inspect.Achievement.Detail("c188A919944FA305A "))

10:19:13: [/script] {category = "C00000011491DEBD6", complete = true, description = "Defeat Xerus in the Stillmoor expert rift The Redemption of Perdeen", icon = "Data/\\UI\\ability_icons\\paladin-vengeful_wrath.dds", id = "c188A919944FA305A", name = "Lost and Found", requirement = {{complete = true, name = "Defeat Xerus in the Stillmoor expert rift The Redemption of Perdeen", type = "event"}}, score = 20, sort = 5000}

Which was completed over a year ago... 5/20/2011 10:35pm

So why am I receiving update notifications for these ?

With the watchdog throwing warnings and errors all the time, I'm sure we are trying to be efficient - but when the game itself appears to be conspiring against us, it's a bit depressing.

We have to assume that the event we receive are relevant and process them if we have subscribed to them - and this all takes time, time which the watchdog doesnt give us...

[ZorbaTHut]

So, why I am receiving updates for achievements that I cannot possibly have changed since logging in?

For *some* of this, keep in mind that the event system explicitly allows a few unnecessary events. Sometimes there are situations where the bookkeeping to figure out what didn't change is extremely difficult. Events are guaranteed to fire when things change, but once in a while, they may fire even when things didn't change.

That said, this is intended to be a rare occurrence, and if you're getting mega-achievement-change events when simply walking from one zone to another, something's broken. I'll look into that.

[Adelea]

For *some* of this, keep in mind that the event system explicitly allows a few unnecessary events. Sometimes there are situations where the bookkeeping to figure out what didn't change is extremely difficult. Events are guaranteed to fire when things change, but once in a while, they may fire even when things didn't change.

That said, this is intended to be a rare occurrence, and if you're getting mega-achievement-change events when simply walking from one zone to another, something's broken. I'll look into that.

It's not when walking, its when using the porticulum.

x=0
for k,v in pairs(Inspect.Achievement.List()) do
x=x+1
end
print(x)

Shows 1030, so its not updates for all achievements either, just a big chunk of them!

From what it looks like, this doesnt happen on a /reloadui, or a login - only when using a porticulum.

If I remove all eventhandlers apart from Event.Achievement.Update, then the handler certainly isnt called.

So - if these events dont fire at login/reloadui - there is no reason to send ANY update when taking a porticulum is there?

[ZorbaTHut]

It's not when walking, its when using the porticulum.

Ah, that makes more sense. That one's just going to keep firing - the problem is that the player is unloaded and then re-loaded on the client, and it's possible that the player has acquired achievements in the meantime.

The only way I'd have of checking which achievements have changed is by doing the exact same thing that addons currently have to - caching the entire list of achievements and comparing them after it reloads. Right now, improved functionality is more important

It *should* be firing that event on login, btw - if it's not, that's probably a bug. Can you double-check? My local tests show that it's firing on login, but something weird may be happening with a real character.