ALL THE THINGS

ALL THE THINGS

31M Downloads

LUA error - Script ran too long when logging into toons as of today

raysmith59 opened this issue · 22 comments

commented

** EDIT: This also happened when I got an achievement so it isn't just a one-time-per-toon-on-login thing, seems to happen any time ATT is activated. **

Just started happening, the game is freezing when I log into toons, in most cases they come back okay but in a few cases when it took long enough I got this error:

Message: Interface\AddOns\AllTheThings\AllTheThings-2.1.2.lua:88: script ran too long
Time: Sun Oct 25 09:53:41 2020
Count: 1
Stack: Interface\AddOns\AllTheThings\AllTheThings-2.1.2.lua:88: script ran too long

Locals:

commented

Is there any more information included in those errors? That specific point in code is basically just the generic logic handling another method which is running iteratively per multiple in-game frames. This is used in many places in the addon to attempt to not receive the specific error you are receiving.

Knowing that it happened when you specific got an achievement is helpful, perhaps we can track it down from there. But if you find anymore information on how to trigger this for yourself, please do post it.

commented

Many changes from version to version, but I can't think of anything that specifically requires more computation this time around... I will hopefully be able to do some debugging tonight, but as I've never encountered this issue (even with ~50 addons enabled) it will definitely be hard to know if I can find it, and if I can fix it. You mentioned that earning an achievement will also cause this issue? That might be easier to pin-point the source compared to 'just login to any character'.

commented

I enabled some additional logging, hopefully this helps.

1x AllTheThings\AllTheThings-2.1.2.lua:88: script ran too long
[string "@AllTheThings\AllTheThings-2.1.2.lua"]:88: in function `?'
[string "@AllTheThings\AllTheThings-2.1.2.lua"]:62: in function <AllTheThings\AllTheThings.lua:59>
[string "@AllTheThings\src\base.lua"]:31: in function <AllTheThings\src\base.lua:30>

Locals:
ok = false
err = "AllTheThings\AllTheThings.lua:8405: script ran too long"
(*temporary) = false
(*temporary) = "AllTheThings\AllTheThings.lua:8405: script ran too long"
(*temporary) = "script ran too long"
instance =
app =

{
CreatePetType = defined @AllTheThings\AllTheThings.lua:7006
SetDataMember = defined @AllTheThings\AllTheThings.lua:132
UniqueModeItemCollectionHelper = defined @AllTheThings\AllTheThings.lua:8630
BaseAzeriteEssence =
{
}
PlayCompleteSound = defined @AllTheThings\AllTheThings.lua:746
AccountWideFlightPaths = true
BaseItem =
{
}
FilterItemClass_RequireBinding = defined @AllTheThings\AllTheThings.lua:7947
ToggleMainList = defined @AllTheThings\AllTheThings.lua:4327
CompletionistItemRemovalHelper = defined @AllTheThings\AllTheThings.lua:8638
ItemBindFilter = defined @AllTheThings\AllTheThings.lua:7878
RecursiveIsDescendantOfParentWithValue = defined @AllTheThings\AllTheThings.lua:8340
IsComplete = defined @AllTheThings\AllTheThings.lua:1009
SearchForField = defined @AllTheThings\AllTheThings.lua:3430
BaseVignette =
{
}
CollectibleBreadcrumbs = false
CreateMount = defined @AllTheThings\AllTheThings.lua:6752
ShowPopupDialogWithEditBox = defined @AllTheThings\src\base.lua:99
PlayRareFindSound = defined @AllTheThings\AllTheThings.lua:760
OpenMiniListForCurrentZone = defined @AllTheThings\AllTheThings.lua:12107
UpdateWindows = defined @AllTheThings\AllTheThings.lua:9086
BaseTitle =
{
}
BaseUnit =
{
}
CreateUnit = defined @AllTheThings\AllTheThings.lua:5234
CreateNPC = defined @AllTheThings\AllTheThings.lua:6907
UpdateParentProgress = defined @AllTheThings\AllTheThings.lua:8446
events =
{
}
BasePetType =
{
}
CreateFollower = defined @AllTheThings\AllTheThings.lua:5750
FlightPathDB =
{
}
print = defined @AllTheThings\AllTheThings.lua:740
CreateFlightPath = defined @AllTheThings\AllTheThings.lua:5676
FilterItemClass_RequiredSkill = defined @AllTheThings\AllTheThings.lua:7954
RequiredSkillFilter = defined @AllTheThings\AllTheThings.lua:7882
BaseQuestObjective =
{
}
ClassIndex = 11
GetNumberOfItemsUntilNextPercentage = defined @AllTheThings\AllTheThings.lua:8798
Presets =
{
}
GetName = defined @AllTheThings\src\base.lua:8
CreateGearSet = defined @AllTheThings\AllTheThings.lua:5915
FilterItemClass_RequireClasses = defined @AllTheThings\AllTheThings.lua:7916
AccountWideFollowers = true
BaseGarrisonBuilding =
{
}
CreateFilter = defined @AllTheThings\AllTheThings.lua:5696
L =
{
}
BaseIllusion =
{
}
BaseMount =
{
}
CreateMap = defined @AllTheThings\AllTheThings.lua:6675
CreateRecipe = defined @AllTheThings\AllTheThings.lua:7382
GetDataMember = defined @AllTheThings\AllTheThings.lua:135
CreatePVPRank = defined @AllTheThings\AllTheThings.lua:7087
GetProgressTextRemaining = defined @AllTheThings\AllTheThings.lua:850
CollectibleFlightPaths = true
_ = {
}
CreateGearSource = defined @AllTheThings\AllTheThings.lua:5948
Col

commented

Oh, and the easiest way to trigger it is to just log into a toon... any time I log into a toon I either get a significant delay or, if the delay is long enough, this error. It's possible that a fast enough PC won't see the error, though.

commented

Do you have WoW installed on HDD or SSD?

commented

Thanks for the additional information.

Yea, unfortunately I don't think any of the contributors have noticed this issue, so it will make it very difficult to diagnose, debug and fix :( But having a slower computer should not be a reason for having issues, so hopefully we can figure this out.

commented

SSD, although a relatively early SATA one. My assumption is that something that was changed in the most recent version is looping through some new code. I'm not sure how to tell what code changed between versions in github, though.

commented

If you are able to test using the latest Git version, I made a few modifications which may possibly have some impact in your situation? It's very hard to know for certain, but if you are able to test using the latest version from Git and notice that your problem has been fixed or at least improved upon then we might know we're moving in the right direction.

commented

No change in the lastest Master. I'll do some poking around myself to see if I can figure anything out.

commented

Do you have the same performance issue if you disable all addons except ATT? I’m wondering whether there is a conflict issue with another addon.

commented

Yes, happens when ATT is the only active add-on. I should also clarify that when ATT stalls out, the game completely stalls but I get a Windows loading-style cursor that I can move around. It's almost like ATT is accessing some sort of external resource and is getting stuck.

commented

The extent of 'external resources' accessible to an add-on would be it's own resources, like sound files or textures. Never heard of that being an issue before though since it's not the add-on accessing those files, it's the wow executable. And if other add-ons work for you then it's probably not that...
To help debug specifically where it is hanging, you can add print("text") statements into the AllTheThings.lua file so they should show in the game chat window if they are called prior to the freeze. Way down near the bottom of the file there's a function that happens when "VARIABLES_LOADED" is fired by the game. This would be the initial point of when the add-on starts processing on start up, and might include whatever is freezing your game. If you do that and find out anything, please let us know.

commented

Here's another question: Do you have any mounts learned on your Account? I'm guessing yes, but if you happen to be a new player... perhaps that might be the cause.

If so, please don't learn any mount yet so we can test whether this can be fixed! Hah :)

commented

Yeah, I'm already about 4 hours into adding print statements to various functions to see if I can figure out where it's stalling, no luck so far but I'm going top-down and focusing on larger functions so I haven't gotten to your suggestion yet, I'll redirect to that one. And yes, I have many mounts. :)

At some point I also need to revert versions to confirm it's just the latest with the issue but I'm confident that's the case.

commented

I've been following the code and it seems I've hit on something I can't explain s I don't know where to go from here. I have multiple calls to function OnScrollbarValueChanged, the last thing I can see is that the function executes (print("endfunc")), I have a diagnostic print("beforefunc") and print("afterfunc") before and after the setscript that calls OnScrollbarValueChanged, it shows up every time other than the last instance of "endfunc".

For reference:

local function OnScrollBarValueChanged(self, value)
local un = math.floor(value);
local up = un + 1;
self.CurrentValue = (up - value) > (-(un - value)) and un or up;
self:GetParent():Refresh();
print("EndFunc")
end

scrollbar:SetScript("OnValueChanged", OnScrollBarValueChanged);
print("AfterFunc")

Based on this, I'd expect to see trios of BeforeFunc, EndFunc, AfterFunc. However, that isn't the case.

From WoW:

BeforeFunc
AfterFunc
EndFunc

That's where it ends, there are roughly 9 trios, all in that order.

Where can I go from here?

commented

Wow... very strange. It sounds like due to the reinstall fixing things temporarily that it may have something to do with trying to load the addon's existing Saved Variables.

Try renaming your saved variables for All The Things (while the game is NOT running)
[...\WTF\Account\ACCOUNTNAME\SavedVariables\AllTheThings.lua] to AllTheThings.lua.old
then re-open the game and see if the issue continues to occur.

Alternatively, I just pushed another small bit of changes to try and help things from running too long within a single frame, but reading your updates it seems it probably won't help anything :(

The readout of the print statements seems normal for that sequence of events actually.
scrollbar:SetScript is telling the game: "When this event happens, run this bit of code"
So you are seeing the 'AfterFunc' before the 'EndFunc' because it's just setting the code to run when that event happens, then the event actually happens and you see the 'EndFunc'.

In the latest Master, try uncommenting (remove the --) the print statements in AllTheThings.lua between lines 59 -> 99. If you can screenshot or note the last few lines in the chat window before the freeze and post them in here for reference.

commented

Also keep in mind that WoW has a very stupid bug in 9.0 where your changes to addons for 'All' only affects the current character. So double check that the addons you think are not on, are actually not on when logging into a character... thanks Blizzard.

commented

Yeah, I've come across that All bug. My test toon is a low level orphaned toon so I don't care about whether add-ons are enabled or not. I have about 120 add-ons and about 40 of them are still bugged post-patch so it's really tough to do this type of testing on toons I play regularly, trying to remember which 40 add-ons I have to disable is rough. Plus, I can't get the Addon Control Panel add-on to actually create and restore add-on sets properly.

Anyway, yeah, I understand what you're saying in terms of the way setscript works, except that I'd expect those setscript segments to only run once during initialization but they continue to execute for each time the function actually runs. Frankly, I'm also not sure why scroll bar changes are happening 9 times before the add-on even finishes initializing since there are no visible frames at that point, I would have expected they'd be created as necessary.

I'll do some further testing as indicated, thanks. More soon, I want to get this figured out.

commented

Good call on the WTF file, I'd considered that but hadn't done anything about it. I cleared it, logged into my test toon (worked), logged into a normal toon with other add-ons (still worked), then back to my test toon and all seems good.

The new WTF file is about 400KB, the one that had the issues was about 5.6MB. I'm assuming that's just a function of not having logged into my other 48 toons yet and not opening various windows to load the data. It's possible that once I've done that I'll run into the issue again but for now things seem to be working so I'm going to close this off, thanks much for the assistance!

commented

It's successfully getting through VARIABLES_LOADED, seems like TOYS_UPDATED is the last function it's actually running (successfully) but it's getting out cleanly. Where does it go after that? No issue with any of the functions below VARIABLES_LOADED. Note that there seems to be a second or two delay before the stall happens, in case that helps. Maybe further indication that it isn't happening during the load process.

commented

This is interesting.

So, the older version gave me a hint that I wasn't expecting, it worked fine but I also noticed that there was a "Refreshing collection..." output that I hadn't noticed before in the load chat spam. So, the issue in the latest version was happening before that.

I then updated to the latest version, logged in... and all was good. Not sure why it helped but re-installing seems to have fixed it. I then went back to one of my toons with all add-ons enabled... and it's back. Then went back to my test toon who only has ATT installed and it's broken again now too.

So, when first installed it's fine but something about other add-ons being enabled is breaking it in a way that affects even a toon that doesn't have add-ons loaded. New one on me.

I'm going to keep poking around at functions that appear to run before the Refreshing Collection output.

commented

Alright, well if you end up logging into other toons the file size should end up near 5-6MB again (mine is) as everything is cached. If you run into the issue again, you can re-open this and maybe we can figure out what exactly is the problem with the old saved variables. But it's nice to know that it's working for you again!