ALL THE THINGS

ALL THE THINGS

31M Downloads

Function GetDataCache ran too long

lexming opened this issue · 23 comments

commented

ATT version 1.7.9 and the previous version 1.7.8d throws the following error on login with WoW 8.1. ATT is the only addon being loaded and I already tried to make a clean install of ATT by deleting its SavedVariables in WTF/.

Message: Interface\AddOns\AllTheThings\AllTheThings.lua:1210: script ran too long
Time: Sat Dec 15 00:23:02 2018
Count: 1
Stack: Interface\AddOns\AllTheThings\AllTheThings.lua:1210: script ran too long
Interface\AddOns\AllTheThings\AllTheThings.lua:1210: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1209>
Interface\AddOns\AllTheThings\AllTheThings.lua:1237: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:1250: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:1224>
Interface\AddOns\AllTheThings\AllTheThings.lua:8120: in function `GetDataCache'
Interface\AddOns\AllTheThings\AllTheThings.lua:9977: in function <Interface\AddOns\AllTheThings\AllTheThings.lua:9973>
Interface\AddOns\AllTheThings\src\base.lua:8: in function <Interface\AddOns\AllTheThings\src\base.lua:8>

Locals: group = <table> {
itemID = 99410
c = <table> {
}
b = 1
parent = <table> {
}
s = 52691
lvl = 90
f = 7
}
field = "speciesID"
(*temporary) = <function> defined @interface\AddOns\AllTheThings\AllTheThings.lua:1199
(*temporary) = <table> {
itemID = 99410
c = <table> {
}
b = 1
parent = <table> {
}
s = 52691
lvl = 90
f = 7
}
(*temporary) = "speciesID"
(*temporary) = nil
(*temporary) = "script ran too long"
CacheFieldValue = <function> defined @interface\AddOns\AllTheThings\AllTheThings.lua:1199

commented

I'm getting the same error.

I tried disabling different filters on different characters, but I still get it.

I noticed one thing that might be a clue.

I looked up the itemID in the error and it always seemed to be for a piece of gear that's the wrong type. For example, my warrior errors on a cloth belt (127001), my warlock errors on mail, leather and plate pieces (127001, 149059, 144945, 148597, 148464, 99410). I have my mini-list set to class only gear on all of my characters.

I have yet to get an error on an item that would be mogable (is that a word?).

commented

I can add that removing all cached data inside the folder "World of Warcraft\_retail_\Cache" does not fix this error. So it does not seem to be related to any corrupt files.

commented

I am also getting this error when running through Wine, and have been trying to look into it more.

The actual reading of db and the populating of allData.g does not seem to be much of an issue, and takes little time. It's just rebuilding in BuildGroups and CacheFields that's causing issues. BuildGroups is noticeable, but probably tolerable. But CacheFields is overwhelmingly slow and eventually raises the dreaded "script too long" error.

If I severely restrict CacheFields to only process mapID and ignore other attribute, then it does seem to complete (if I also disable OnUpdate) although I of course end up with a sparsely populated dataset. Adding a second field fails to finish execution.

The consequence of this is that only a subset of the total dataset in db is ever populated, and users end up with perpetually incomplete checklists.


I am still trying to understand things better, but as one suggestion, is it possible that BuildGroups could be integrated into the preprocessing step where the db files are created, so that parents are pre-constructed? It would not solve the problem, but it would reduce the amount of work in WoW.

commented

For what it's worth:

If I disable all CacheFieldID and related calls inside CacheField except those related to mapID, then I do about 218k CacheField calls and do complete the GetDataCache.

If I re-enable all of the CacheFieldID calls, then I get to about 75k CacheField calls before I hit the timeout.

commented

I confirm getting this error using wine. Does it not happen natively on Windows?

commented

I'm using Lutris to manage my games.

I switched my Wine runner to tkg-protonified-3.21-x86_64 and I don't get the error. I tried a couple other Wine versions and they either gave me the error or didn't support DXVK, so no WoW at all.

However, it still takes about 4-6 seconds to do a refresh, where on Windows it was 1-2 seconds. My Linux desktop is massively more powerful than my Company Windows Laptop.

commented

I have updated to the latest version. I am running in Wine.

I did a little more testing.

  • I copied my entire WoW directory to a windows 10 machine. The error does not pop up.
  • I went through 18 different alts. This was all pretty fast.
    -- Set them to a saved mini-list profile
    -- Shift+click refresh
    -- Looked up a raid boss in the mini-list
  • I replaced my entire Wine WoW directory with the updated Windows WoW directory. The error comes back in Wine.
    -- When I select a mini-list profile there is a 12 second delay where all of WoW is locked up. After that the mini-list does display.

I don't believe all of the data is there, since I have been seeing items that do not show any collected (or not) data. But, when I equip some of those I do get the new item notificaiton.

commented

Amendment to my previous comment: BuildGroups does not actually take much time at all, so can probably be ignored here.

Part of the confusion was that BuildGroups adds the parent property to the allData tree nodes, which seems to cause a different function (RefreshData) to take much longer. When those properties are present, RefreshData does its work and becomes a bottleneck; when parent is absent, then RefreshData doesn't do much work and is no longer a bottleneck.

So probably best to just focus on CacheFields performance.

(While RefreshData is another potential bottleck, it is probably best ignored for now.)

commented

Also wanted to confirm @bcarter 's suggestion to use a newer version of Wine. I'm now running a 4.0-rc2 release (this one) and ATT loaded without much trouble.

I still think these performance issues matter, but maybe this will sort itself out within Wine.

commented

I have been continuing to work my way further through the source, and it does seem that the tables in the .lua files in contrib/Parser/DATAS are directly translated into db/Categories.lua entries as tinsert calls, with no modification or transformation.

I hope this is not too naive of me to suggest, but it does seem to me the transformed tables performed by BuildGroups and CacheFields functions could be done as a preprocessing step, and that these modified tables could be imported directly in a new Categories.lua (etc) file.

Even if this particular problem sorted out by a patched Wine as suggested by @bcarter (which I'll also try out), it seems like this could be a major performance improvement for all users.

@DFortun81 Is this a crazy suggestion? Do you think this is possible?

(BTW not suggesting that you ought to do this; I am happy to either give it a try or step back and let more experienced developers have a go.)

commented

In Lutris, I'm using Wine 4.3 staging with DXVK 1.0.1.

In the BattleNet launcher I am using the startup parameter -opengl

Ever since this bug was opened, ATT has been causing about 3 to 10 seconds of lockup every time something is added/removed from the collected lists. But this is the best I have been able to get it working.

commented

Hey,

I'm currently using wine-4.2 staging and I'm getting these errors too. I started to try to narrow it down but I just stumbled into your issue where you seem to have gone much further than me in the tracking down. Could you confirm whether this stopped happening to you, and which wine version you're using now? Thanks!

commented

A lot of people have reported this issue since that release. One of the main features that came with that release was the "Symbolic Link" system. I have made adjustments to the system to prevent the Symbolic Links from evaluating on startup as they were primarily used by rewards for the weekly quests when hovering over these items in their tooltip. (Timewalking Reward Boxes, Caches, etc)

Please download the latest Git and let me know if this issue is still occurring for you.

commented

I downloaded AllTheThings.lua and tested it by caging a pet.

If I get time today, I'll go see if I can get a new piece of gear.

Previously it was locking up for 5-10 seconds when I caged a pet and up to 5 seconds when I learned a pet.

Now there's only about a 2-3 second lock when I cage and none when I'm learning a pet.

This is a great improvement.

---EDIT---
The 2-3 second lock may be another mod. I just noticed that by only copying over the one file ATT breaks so it wasn't doing anything at all.

I'll pull the whole thing and try again.

commented

OK, now I have some coffee in me.

I created a new toon and disabled all addons except ATT.

I loaded the latest ATT on Curse and from GitHub. I get the same results in both.

  • I get the long lockup when I cage a battle pet.
  • If I run Wine 4.3(Staging) I get the "Interface\AddOns\AllTheThings\AllTheThings.lua:2072: script ran too long" error
  • If I run Wine tkg-protonified-4.1-x86_64 I do not get the "script ran too long" error. However, running that version of wine causes other problems with the game now that they messed with DirectX again.
commented

I just tried using Wine tkg-4.3-x86_64.

The "script ran too long" error goes away, but there's still a 10-30 second delay when I log into the game.

Pet cage time is the same as above.

Side Note: The other non-ATT issues from Wine tkg-protonified-4.1-x86_64 seem to be gone.

commented

I'm having the same issue, long delay when refreshing, small delays when acquiring new items. Similarly I also get small delays when vendoring items with trade skill master running as well (no issues when these addons are disabled). I've been away from the game for some time, so i don't know when it began, but these issues didn't exist around the start of BfA, so I wonder if something changed in wine that causes this. I know both ATT and TSM have fairly large data files, perhaps wine is having issues parsing these files? Just throwing out some ideas in case it sparks something in someone else.

commented

I think it is a combination of optimizations in both, but I cannot really tell which particular change made a bigger difference. This is even more complicated because anything can contribute to making GetDataCache not reach the time limit and trigger the ran too long error. For instance, I upgraded GCC and now I'm compiling wine with gcc-8.3.0, that might have helped as well. All I know for sure is that I have not changed my hardware, so the solution comes from software optimizations.

commented

This issue no longer happens with ATT-1.9.5 in WoW-8.2 using wine-4.11. Thanks for all the feedback and the constant updates of ATT.

commented

Any idea whether the bug was fixed in wine or in ATT?

commented

This is also working OK for me now (great news!) but any idea what changes were made? There was a lot of potential improvements to the database, wondering if anything was done there?

commented

I significantly changed how we cache data for our database lookups. Rather than checking for every significant key explicitly, it now loops over the keys exclusive to each instance that are known prior to API triggers and requests. (All fields are no longer reflected down to the metatables that make up the instance’s class structure by using rawget.)

commented

This single massive change was likely responsible for the speed increase.