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:
Code:
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