Combat Tracker Loading Performance Analysis and partial fix

[darrenan]

I have experienced first-hand, and heard the grumblings from other GMs, about the performance issues in FG (many seconds of 'hang time') when loading an encounter into the combat tracker. Having nothing better to do today, I sat down and created an instrumented version of the main functions that are called when loading the combat tracker: CombatManager.addBattle, CombatManager.addNPCHelper and CombatManager2.addNPC (in the 3.5e ruleset). I am reporting this investigation in the CoreRPG section because the issues I uncovered (described below) are in the CoreRPG ruleset, even though my primary experience of this issue has been via the PFRPG ruleset.

My methodology for performing this analysis was to surround sections of code with the following pattern:


local tSomeOperationBegin = os.clock();

---SomeOperation here---

local tSomeOperationEnd = os.clock();

ChatManager.SystemMessage("SomeOperation elapsed time=" .. tSomeOperationEnd-tSomeOperationBegin);

Using this approach in a slice and dice manner, I was able to quickly isolate the bulk of the execution time as being the two calls to DB.CopyNode in CombatManager.addNPCHelper. I was able to refactor this function to eliminate one of these calls, thus effectively cutting the time to populate the combat tracker in half. I have attached the modified manager_combat.lua for review (note that there is a small section in there still commented-out, it was unclear to me whether those calls would be needed with the code in it's new form).

This is not the whole story though, as I saw some other troubling behavior during the course of this investigation. I expected to be able to add an encounter, clear the combat tracker, and then add the same encounter again and see roughly the same performance both times. I did not see this behavior, however, as every time I populated the encounter the elapsed time to populate the encounter continued to go up, even when clearing the combat tracker in-between. This tells me that somewhere the internal data structures are not being completely cleaned up, either in the LUA ruleset code or the underlying FG libraries. Performing a /reload however, did cause the load times to 'reset', effectively going back to a similar load time each time. What this means is that over the course of a 4-5 hour gaming session we should expect to be continually slowing down from one encounter to the next. I have not yet looked at the CT delete logic, but I plan to next and will post any interesting findings, if any.

I would hope that the devs would also examine the implementation of the DB functions, particularly CopyNode, which seem to be very expensive in terms of time. I'm guessing there are file I/O operations in that code path, and I've heard it said before that FG is essentially single-threaded so it doesn't do anything in the background (which also explains the complete 'hang' when loading the CT). Perhaps the Unity rewrite will enable some level asychronicity in the code?

Also, everyone I've talked to seems to correlate this issue with the number of entries on the NPC's "Spells" tab. Because this tab contains the only extendible portion of the NPC, and causes the size of the NPC to grow, it totally makes sense that NPCs with more entries on their Spells tab take longer to load as this must directly affect the performance of DB.CopyNode. This is unfortunate, as the Spells tab is the primary means for adding NPC capabilities, and will by necessity get larger as the challenge rating (level) of the campaign increases.

Hope this information helps.

D.

[Trenloe]

This is not the whole story though, as I saw some other troubling behavior during the course of this investigation. I expected to be able to add an encounter, clear the combat tracker, and then add the same encounter again and see roughly the same performance both times. I did not see this behavior, however, as every time I populated the encounter the elapsed time to populate the encounter continued to go up, even when clearing the combat tracker in-between. This tells me that somewhere the internal data structures are not being completely cleaned up, either in the LUA ruleset code or the underlying FG libraries. Performing a /reload however, did cause the load times to 'reset', effectively going back to a similar load time each time. What this means is that over the course of a 4-5 hour gaming session we should expect to be continually slowing down from one encounter to the next. I have not yet looked at the CT delete logic, but I plan to next and will post any interesting findings, if any.
Try and /save rather than a reload and see if that makes a difference. /save updated the db.xml file on disk and, I'm guessing, does some database cleanout/re-organisation. I'd be interested in seeing if /save made any difference. FYI - FG executes a database save every 5 minutes in the background.

[darrenan]

/save does not appear to make any difference.

[Trenloe]

Using this approach in a slice and dice manner, I was able to quickly isolate the bulk of the execution time as being the two calls to DB.CopyNode in CombatManager.addNPCHelper. I was able to refactor this function to eliminate one of these calls, thus effectively cutting the time to populate the combat tracker in half. I have attached the modified manager_combat.lua for review (note that there is a small section in there still commented-out, it was unclear to me whether those calls would be needed with the code in it's new form).
The first DB.copyNode creates a temporary copy of the NPC and then (after some minor changes) this temporary record is copied to the combat tracker. It will be interesting to know if there was any technical reason for this.

[Nickademus]

Moon Wizard and I narrowed this problem down to the amount of actual Cast/Heal/Damage/Effect actions in the various spell entries on an NPC. The spell class itself doesn't cause a problem. This is due to the amount of events that are fired when a new node is added to the database (presumably during DB.CopyNode).

As a current work around, what I've got in the habit of doing is to make two copies of an NPC. The first is in the encounter and gets added to the combat tracker. This copy has no spell classes. The second copy contains all the spell classes with actions and is linked in the story entry that links the combat encounter. I use the reference NPC for performing actions (which could result in inconsistencies should the NPCs be subject to certain buff or debuffs). It takes watching what changes to stats the CT NPCs get and manually adjusting before using the reference NPC, but still, it's better than locking the game up every time I have to add something to the tracker.

[Trenloe]

/save does not appear to make any difference.
Shame.

Good investigation and interesting results. I think quite a few of us knew it was related to the DB.copyNode - but it will be interesting to see if the initial process of copying to a temporary record can be removed (i.e. was there a technical issue/reason for this double copy process) and the total copying time reduced from what it is now.

Very interesting to know that the copying time gets worse the more copies that have been done previously, even if the CT is empty. Guess this means that GMs should at least /reload just before they run a game if their session has been running for a while and they've been doing some testing.

[Callum]

This is a very interesting analysis. I must say, I haven't ever noticed this issue, despite currently running a high-level 3.5E game. However, I also don't ever add NPCs to the Combat Tracker lots of times in one session.


As a current work around, what I've got in the habit of doing is to make two copies of an NPC. The first is in the encounter and gets added to the combat tracker. This copy has no spell classes. The second copy contains all the spell classes with actions and is linked in the story entry that links the combat encounter. I use the reference NPC for performing actions (which could result in inconsistencies should the NPCs be subject to certain buff or debuffs). It takes watching what changes to stats the CT NPCs get and manually adjusting before using the reference NPC, but still, it's better than locking the game up every time I have to add something to the tracker.

Doesn't that cause issues with NPC targeting for their actions?

[Nickademus]

Not that I saw. The entries in the CT have all the stats filled out so they can respond with an AC or CMD, saves, and such. The CT still parsed the Special Defenses line so that they have things like resistance, immunities and damage reduction. The only difference is that there are no 'spells' to use off of the CT entries. (I literally make the full NPC character sheet, copy it in the NPC list and remove the spell classes from the copy.)

The only problems I've had to watch out for is any effect in the CT to a particular critter that would alter an ability score, attack roll (& cmb), or caster level as that would alter the auto-calculated DC/heal/damage/save amounts.