Bug - Waiting for Info Performance issue

Linknoid

Member
Running automated commands recently started running really slow. For example, during login it takes over a minute to process breakfast. It's taking almost a second for each automated command to process.

You can skip this next paragraph if you don't want the backstory:

It started quite suddenly, and I assumed it was either heavy server load or a slow network connection. But it was still slow the next day, and even stranger, it only affected my main account. Maybe something weird is going on with that account. Was I being throttled by the server for making too many requests or something? I hadn't done anything usual recently. I had done a fresh OS install recently, but it was fast for a few days after that, then suddenly got slow. It continued happening, so I started experimenting. Doing stuff in the relay browser didn't seem affected. Usually I don't do more than 1 action a second manually, so maybe I wasn't just clicking fast enough. Extending Asdon Martin buffs involves a lot of clicking, so I did that manually, and it was still super fast. Then I had a realization, maybe it's not network or server related at all. It's been happening a few days, maybe since the beginning of the month. Hmm, that also which happened to be when the PvP season ended and I pulled all my stuff from Hagnks. Maybe it has to do with the size of my inventory, since my other characters' inventories are much smaller. That means it's probably CPU bound. Time to start profiling.

If anyone is looking for a profiler for Java, I would recommend VisualVM, it's trivial to set up, easy to use, and completely free. It's only requirement is to have JDK installed. Anyway, I did some profiling during login, and the speed issue is related to inventory size.

All the slowness is coming from swingui\GearChangeFrame.java. In particular, a series of methods resembling the following (one for each gear slot):

Code:
	private List<AdventureResult> validAccessoryItems( final AdventureResult currentAccessory )
	{
		List<AdventureResult> items = new ArrayList<>();

		// Search inventory for accessories
		for ( AdventureResult currentItem : KoLConstants.inventory )
		{
			addAccessory( items, currentItem );
		}

		// Add the current accessory
		addAccessory( items, currentAccessory );

		// Add "(none)"
		if ( !items.contains( EquipmentRequest.UNEQUIP ) )
		{
			items.add( EquipmentRequest.UNEQUIP );
		}

		return items;
	}

So every time it does a status update, it recalculates all this stuff (possible more than once? I don't have that level of detail from the profiler). It creates a new list, adds each accessory to the list, one by one, and then finally adds the currently equipped accessory to it. Hmm, kind of weird it's only adding one, that must mean it's getting called 3 times, once for each slot, which probably explains why accessories are using way more CPU time than the other slots.

Building this list is an O(N^2) operation, because each item it adds to the list, it checks if that item already exists in the list:

Code:
	private boolean addItem( final List<AdventureResult> items, final AdventureResult item, final int type )
	{
		// Only add it once
		if ( items.contains( item ) )
		{
			return false;
		}

		// Only add items of specified type
		if ( type != ItemDatabase.getConsumptionType( item.getItemId() ) )
		{
			return false;
		}

		// Make sure we meet requirements in Limitmode, otherwise show (greyed out)
		if ( KoLCharacter.getLimitmode() != null && !EquipmentManager.canEquip( item.getName() ) )
		{
			return false;
		}

		return true;
	}

The profiler says it's spending about 1/2 its time in AdventureResult.equals(object), and the other half in the body of GearChangeFrame.addItem(List<AdventureResult>, AdventureResult, int). Ultimately this code is being called repeatedly from GearChangeFrame.ensureValidSelections(). It builds the list for updateEquipmentList, and then uses it to populate each drop down in the gear changer tab.

Switching the list to a hashing collection (not sure what the Java equivalent of C# HashSet is) would go a long way to making this faster. But if that's not an option, addItem should validate that the item is worth adding before checking if it's already in the list. Given that it's checking inventory, which should already guarantee uniqueness, it seems like the "items.contains" is completely unnecessary in the inventory loop.

And from a higher level perspective, the whole tab could be optimized by not populating the dropdowns until they're actually needed. I don't know if there's an event hook on the dropdowns to load the full list of gear choices when it gets focus, but the lists certainly don't need to be populated while the gear changer tab isn't active.
 

Veracity

Developer
Staff member
Something that changed recently is that after building each list, we are now updating the model in the swing thread. That is correct behavior, but the extra task switching isn’t helping.

Thanks for the profiling. I’m playing with making one pass over inventory and building all lists at once and then updating the model from them. Should remove millions of comparisons.

Stay tuned.
 

xKiv

Active member
The profiler says it's spending about 1/2 its time in AdventureResult.equals(object)

Many years ago, I ran my own profiling and found this too (except it was close to 90% of all runtime; maybe it was ADventureResult.compareTo too).
So I went and changed things a bit around so that the next profiling looked much better.
Then I realized that my "performance" problems were not CPU bound, but rather "passing pages from kol to relay browser is slow" and "mafia needs to process the entire page result before it starts sending the mangled result to relay browser, which makes it look to me like the loading is slower" bound, so I didn't post a patch (I think, I might be misremembering). But I have been running with it ever since.
It consist of (from memory, it is on a different computer)
- creating a new class AdventureResultKey which has a static TreeMap of all AdventureResultKey(s) ordered by o1.name.compareTo(o2.name) , String name which is what AdventureResult.name was, Integer ord (which I will get to in a bit), and a static "dirty" flag that is set whenever a new name is added
- it also has a "factory" method that, for a given name, either returns an existing AdventureResultKey or creates a new one and puts in into the TreeMap
(I think I also added a KEY_NONE constant that it returns for null names, to simplify some comparisons)
- removing AdventureResult.name + replacing its read-uses with a getter on the AdventureResultKey (key)
- delegating the final comparisons in AdventureResult.equals and AdventureResult.compareTo to the respective methods of AdventureResultKey
- when compareTo or equals is called and the dirty flag is set, walk the TreeMap (which is already sorted by name) and setting ord to increasing numbers (from 1); then clear the dirty flag
- after this, key1.compareTo(key2) delegates to key1.ord.compareTo(key2.ord) and equals delegates to key1.ord.equals(key2.ord)
- but even before that, since there is only one AdventureResultKey for a given name, things will get sped up because equals starts with something like "if (o1==o2) return true" (the "old" way had different name objects for each AdventureResult, I think, because they were usually taken from some other input)

All of this to avoid the multimillions of string comparisons that were happening.
 

Veracity

Developer
Staff member
Try revision 20346.

This was a major refactoring of code. Much simpler, much more readable, much more performance optimized.
It should go through the inventory exactly once and add items to all equipment lists, as appropriate, filter out things that should not be shown.

I want to make sure that stickers and folders continue to work - or, at least, work as well as before.

But, this was a big change, so let's see how it behaves in thw wild.

In the mean time, tell me how it works for you.

I will note that your comment about refreshing the Gear Changer only when it is visible is something which seems to apply only to you - or people like you, who, unlike me, have the Gear Changer in a tab. I have the Gear Changer in a frame which is created the first time you open it. It looked to me like it created and displayed it WAY faster than before. Hopefully, it will work better for you, too.

Tell me about performance with this revision.
Also tell me about correctness. :)
 

Linknoid

Member
I just tried 20347 and it's blazing fast now. Thank you!

Thank you for pointing out that you can add/remove tabs. For users who don't customize the UI (I would assume the majority of people just take the defaults), the initial tabs are "Adventure", "Graphical CLI", "Purchases", "Gear Changer", and "Skill Casting". So I suspect this is going to affect a lot of people who don't even use the gear changer. I must admit, other than moving the CLI into an external window, I've never done any customization on tabs, and managed to forget you even could.

I did some testing of behavior in the gear changer, and it seems to switch gear, familiars, outfits, folders, and stickers just fine. The Weapon/Off-Hand filters are really slow when you check one, like 3 seconds to re-populate the list. But that only occurs when you actually click on something, so it's probably way lower priority than something that happens on every request.

Also, the Crown of Thrones and Buddy Bjorn options seem to get out of sync with the game. If I equip/unequip a bjorn/crown in the relay browser, the enabled/disabled state of the dropdown doesn't update immediately. I was able to unequip the crown in the relay browser and still tell the gear changer to swap familiars in the crown. But then it remained convinced I had that familiar in the crown (or at least never bothered to update the UI), even after visiting the familiar page or un/re-equipped the crown, and didn't correct its mistake until I switched it to a different familiar. It's quite possible this issue was pre-existing, and it's pretty minor. I've never tested the functionality of gear changer trying to break it before.
 

Veracity

Developer
Staff member
I'm going to keep working on this. I especially want to look at the familiar item list, which is a real equipment "slot", as defined by KoL We also have "pseudo" slots - Crown of Thrones, Buddy Bjorn, 3 stickers, 5 folders, card sleeve - and bootspur and bootskin, which two are handled like normal slots in the code I changed.

But familiar items and crown of throne and buddy bjorn are problematic, and I want to understand better how they are handled.

I'll also look more at the filters.

Thanks for testing!
 

Veracity

Developer
Staff member
By the way, my tabs omit Gear Changer and add Preferences. I use Gear Changer every day, but, for whatever reason, decided that I was willing to defer creating the frame until I first used it. Ditto for Item Manager, Coinmasters, and Maximizer, all of which I use every day.

Maybe I removed Gear Changer because it took so long to create. :)
 

Linknoid

Member
I've seen another speed issue with the gear changer. It only triggers occasionally, but when it does, I've seen it take up to 12 seconds to finish. I caught it happening with VisualVM, and it's happening in swingui/GearChangerFrame.java:

Code:
	private static void updateEquipmentList( final LockableListModel<AdventureResult> currentItems, final List<AdventureResult> newItems, final AdventureResult equippedItem )
	{
		currentItems.retainAll( newItems );
		newItems.removeAll( currentItems );
		currentItems.addAll( newItems );
		currentItems.setSelectedItem( equippedItem );
	}

Pretty much 100% CPU usage is being spent on "currentItems.retainAll( newItems )" line. I'm not sure exactly what's triggering it, because it happens infrequently, but it might be related to swapping weapons programatically. The call stack at the time looks something like this in the profiler:

Code:
...java.awt event queue stuff
InvokcationEvent.dispatch()
GearChangeFrame$1.run()
GearChangeFrame.access$2300()
GearChangeFrame.updateEquipmentModelsInternal()
GearChangeFrame.updateEquipmentList()
LockableListModel.retainAll()
LockableListModel$ListModelIterator.remove()
LockableListModel.remove()
LockableListModel.removeVisibleElement()
AbstractListModel.fireIntervalRemoved()
... a bunch of internal swing stuff
BasicListUI.updateLayoutState()
kolmafia.swingui.widget.ListCellRendererFactor$UsableEquipmentRenderer.getListCellRendererComponent()
JLabel.setText()

Sorry I left out a bunch of details like namespaces, I'm retying non-copy/pastable text and just trying to provide a summary.
 
Top