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):
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:
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.
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.