Bug - Fixed Performance issues

[Veracity]

Obviously, we have lots of work we can do for the "processing time" performance issues. I've been ignoring those, for the moment, instead focusing on trying to reduce server requests.

I believe I am done with image caching. I added a "cache clear" command. Clearing the image cache records the date/time in lastImageCacheCleared and "cache" with no arguments prints that for you. That's a global setting, since the image cache is global; there are no per-user files stored in it.

I'm considering making image caching mandatory - removing the relayUsesCachedImages setting and always munging response text to go to the cache - and making people start with a fresh cache by clearing the cache if lastImageCacheCleared is 0.

Any reason I shouldn't do that?

 

[Fluxxdog]

"But I don't want to use a cache!"
Technically, we already use a cache. Any browser downloads first, then it displays the page based on what it downloads.

"But I use a proxy!"
Well then, the image will be on your side of the proxy already, meaning you won't have to go through the proxy to get the images.

Those are the only two complaints that spring to mind off the top of my head. Feel free to read the complaints in whiny voices if it makes you laugh ^^

 

[darkcodelagsniper]

Mafia's image caching is replicating the caching that chrome is doing for me already. Doubling up on the functionality doesn't seem like it would give any benefit(?) but it is increasing my page load times. I'm still seeing broken images very frequently on chrome with r12658 (this is after having cleared my browser cache and run a cli 'cache clear').

 

[Veracity]

Thank you for the anecdote.

Is anybody else seeing broken images? I am unable to replicate that with Firefox, Safari, or Chrome.

 

[Darzil]

I was yesterday, before your fix, but I cleared it by clearing browser cache, clearing mafia image directory and restarting mafia. Before the mafia restart but after the others, only my familiar images for my favourite familiars didn't show, presumably because mafia was already displaying them. I did have to clear both browser and mafia caches, though.

 

[xKiv]

Mafia's image caching is replicating the caching that chrome is doing for me already. Doubling up on the functionality doesn't seem like it would give any benefit(?) but it is increasing my page load times.

I thought that too, but after the first load, it *should* decrease load times (since in both cases, browser asks mafia for the file If-Modified-Since - and without cache, mafia had to ask kol's server for the same, which is probably slower than checking a local file's timestamp).

 

[Bale]

I was yesterday, before your fix, but I cleared it by clearing browser cache, clearing mafia image directory and restarting mafia. Before the mafia restart but after the others, only my familiar images for my favourite familiars didn't show, presumably because mafia was already displaying them. I did have to clear both browser and mafia caches, though.

This happened to me also, using Opera 16 which is a Chrome-clone. Cache clearing and restarting Opera did fix it.

Everything is great now!

 

[xKiv]

Huh. A few days ago I put debugging prints [1] around the .sort() calls at the end of ConcoctionDatabase.refreshConcoctions, because I thought it was slowing everything down too much. But it wasn't - the sorts might have been called 6 times for a simple "drink dirty martini" command (for a certain value of "simple"), but each time they only took ~50ms.
Not today:
1379548391254, before sorting
1379548394963, after sorting
That.s 3.709 seconds spent sorting creatableList, usableList and recalculating adventure range.

Here's stdout for an entire combat (3 rounds, got meat stack and some meat) and adding another printout (in a breakpoint's condition, I learned something new today :-D ) on the "if ( ConcoctionDatabase.recalculateAdventureRange )" line:

1379548688749, before sorting
1379548692748, before ranges
1379548692770, after sorting
2617.081: [GC [PSYoungGen: 124169K->2333K(126784K)] 223979K->102350K(520000K), 0.0282930 secs] [Times: user=0.16 sys=0.00, real=0.03 secs] 
1379548693858, before sorting
1379548697839, before ranges
1379548697849, after sorting
2622.177: [GC [PSYoungGen: 124942K->2119K(127104K)] 224959K->103477K(520320K), 0.0320890 secs] [Times: user=0.22 sys=0.00, real=0.04 secs] 
2622.396: [GC [PSYoungGen: 125074K->288K(126976K)] 226432K->103356K(520192K), 0.0058980 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2622.584: [GC [PSYoungGen: 123296K->1113K(127168K)] 226364K->104264K(520384K), 0.0048690 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2622.778: [GC [PSYoungGen: 124249K->336K(127040K)] 227400K->104374K(520256K), 0.0057610 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2622.964: [GC [PSYoungGen: 123472K->256K(127232K)] 227510K->104358K(520448K), 0.0089290 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
2623.157: [GC [PSYoungGen: 123584K->336K(127168K)] 227686K->104494K(520384K), 0.0106860 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

4 seconds just sorting (that's roughly 100 times slower than yesterday ...), and it happened *twice* for a single click.
And at least two seconds of other processing (from GC timestamps).
I wonder how that's possible ...

[1] I have recently taken to running mafia in eclipse in debug mode


update: putting in more breakpoints shows that creatableList is fine (and so is calculateAdventureRanges), bulk of time is spent on usableList - both updateFilter() and sort() (and that's with changeDetected==false)
update2: I might have found a teeeeeny problem ... creatableList has 668 actual items and 668 visible items ... nice and tidy; usableList has 6700 items (ok, there's around that amount of items in the kingdom) and whopping 979455 visible elements! and 1006247 after a few more combats! And 1026341 (running updateFilter changed it to 1033039) after another! (even though actualElements is still 6700)!
There's something rotten in LockableListModel ... namely in LockableListModel.updateSingleFilter? Anyway, once visibleElements gets crippled, this method will always makes things worse ...
So, I executed visibleElements.clear() in display view at the start of that method and things now appear to run well (no more duplicates in usableItems.visibleItems, sorting finished within 50ms, fight takes only 2s altogether).

ETA3: forgot to add - score one for running in debug mode

 

[xKiv]

Actually, I think I now see a pretty big synchronization issue in LockableListModel. Whoever wrote it might not have been very good at synchronization.
1) It synchronizes actualElements on actualElements and visibleElements on visibleElements, separately
2) (at least) visibleItems is synchronized separately at each .add
3) so when two threads try to ".updateFilter, .sort", and one of them gets between sort(actualElements) and sort(visibleElements), and at this time the other thread does updateSingleFilter, you get a mess, because updateSingleFilter expects actualElements and visibleElements to be in the same sort order. Because that's the only way I can think of now that could cause this bloat.

Maybe both .sort and .updateSingleFilter should by "synchronized(this)"?

 

[lostcalpolydude]

I remember thinking a while ago that there's probably a better List type by now (through Java 5) that could replace LockableListModel, but I didn't really look into it because I doubt I would understand what was needed in a replacement, and also the fact that switching it out would require lots of code updates all over the place even if I had an idea for what to replace it with.

 

[Darzil]

xViv that sound horribly like what I've been seeing. Are you also on Java 7, as my system was stable yesterday on Java 6 (was slow in the evening, but it was either KoL or comms with KoL that was slow, not Mafia).

I suspect that ConcoctionDatabase might deserve some looking at at some point. When it was designed I suspect it was very stable through a session, but now there are skills and items and places to unlock which change it, and at the moment that is done by refreshing the lot, rather than just affected items. Also it builds an array of states for certain consumption helpers, but only some of them, presumably to avoid having to rebuild it, but now it is being rebuilt that might be wasted effort. Might be worth a redesign to for example make a stable database for things that are consistent throughout a session, and flags or data fields to cover certain aspects that won't change (eg base turns for crafting, turns saved by smith, turns saved by inigos, min turns to craft, turns saved by jackhammer, Booleans for affected by milk, affected by ode, affected by . . . etc) and add a display layer which uses those fields to calculate and pass on the results, rather than rebuilding the whole database. Also add functions to recalculate only those pieces that need to be recalculated, when conditions change (and/or also include autoXXXX preferences, which assume if you can get what you need, if appropriate, and assumes them in the figures, thus eliminating the need to recalculate at all - eg autoMilk, in aftercore or with Milk or with resources to make Milk, will assume Milk is always on for calculation purposes).

 

[zarqon]

@darkcodelagsniper: Prior to r12646 I had the same problem, despite clearing browser cache and restarting mafia. The majority of images weren't loading. However, after updating to r12646, clearing Opera's cache (which I discovered must be done with the tab closed), and restarting mafia, all my images are loading fine.

Veracity, I personally support the idea of making image caching non-optional. My images folder -- having cached images for years without ever deleting -- now contains quite a lot of KoL history. It's also useful when writing relay scripts for finding appropriate images to use.

 

[Bale]

My images folder -- having cached images for years without ever deleting -- now contains quite a lot of KoL history.

Does that mean you are resistant to using the "cache clear" command? If so, I'd suggest you change lastImageCacheClear property before KoLmafia is set to automatically clear the cache if it is 0 to ensure proper function. Though it is probably better for you to clear it now so that the image's Last-Modified and Expires headers will be correct.

 

[xKiv]

I remember thinking a while ago that there's probably a better List type by now (through Java 5) that could replace LockableListModel, but I didn't really look into it because I doubt I would understand what was needed in a replacement, and also the fact that switching it out would require lots of code updates all over the place even if I had an idea for what to replace it with.

I don't think you will find a better "list type". You want it to stay sorted, you want it to implement ComboBoxModel (remember selected item, be able to select previous/next), you probably want it to be able to fire "changed" events.
I am also not quite sure about the distinction between LockableListModel and SortedListModel.

I tried substituting a TreeMap based solution. I got a bit of work done, then I needed to implement ComboBoxModel and just couldn't.

xViv that sound horribly like what I've been seeing. Are you also on Java 7, as my system was stable yesterday on Java 6 (was slow in the evening, but it was either KoL or comms with KoL that was slow, not Mafia).

Java 7, but the corruption only happens some days, and it seems that it only happens during first login in the day (or the following "breakfast" custom script I have).
Java 7 might have changed some things or optimizations around, but it's not to blame - the buggy synchronization of LockableListModel needs to be fixed. Or worked around.

I suspect that ConcoctionDatabase might deserve some looking at at some point.

I think it would be fine if the corruption didn't happen. Sorting an already sorted list (with a couple thousand elements) isn't that bad, even when it happens a couple extra times. LockableListModel even has an "optimized" O(log(N)) binary search algorithgm for getIndexOf() and contains(), which might not be (too much?) worse than using a hashmap to do the same.

What I *did* do on my local workspace is that I introduced a special AdventureResultKey class that keeps a static cache of all used AdventureResult.name values (pointing to a common AdventureResultKey for all names that compare the same after normalization and ignoring case), in a TreeMap (so they are all sorted "by name, ignoring case"), with an "order" attribute that I update on change, and then compare(k1,k2) boils down to returning k1.order - k2.order, instead of k1.name.compareIgnoreCase(k2.name). That might have sped up things for me a bit.

By the way, when I put breakpoints in LockableListModel on lines that add elements to visibleElements, and repeated "step out of" a few times, I often ended up in ChatRequest.run, which explains why the issue was worse for people with chat open.
I didn't investigate why that happens.

 

[lostcalpolydude]

Now that I think about it, my issue with LockableListModel was the inability to add generics without changing stuff everywhere, but that has nothing to do with this thread.

 

[Captain Kirk]

Chiming in with I like the idea of making image caching mandatory. People don't really understand what it does, and I think it makes mafia more friendly towards the servers, and it makes for better performance on the client end too.

 

[fronobulax]

I turned caching on. Not sure why I had it off but figured it was time to go with the flow. I was amused that Dropbox found over 3000 files to update when I switched computers and it updated my mafia directories

 

[Bale]

I turned caching on. Not sure why I had it off but figured it was time to go with the flow. I was amused that Dropbox found over 3000 files to update when I switched computers and it updated my mafia directories

Yeah.... I just have dropbox set to ignore my /images folder.

 

[Veracity]

Actually, I think I now see a pretty big synchronization issue in LockableListModel.

There are a heck of a lot of issues with synchronization in that package. I actually think that most of the methods should just be synchronized on "this", even if they are trying to operate on just one of the lists, much less both the actual and visible lists - not to mention the mirrored copies of those lists.

I have an experimental version which synchronizes a lot of methods. I'll check it in and we'll see if it resolves corruption issues.

 

[Fluxxdog]

Yeah.... I just have dropbox set to ignore my /images folder.

And I have mine set to ignore images except of relayimages thanks to you ^^ (No really.)