Bug - Fixed Performance issues

[fronobulax]

Thank you for sharing your thinking, especially what you observe, what you expect and what you think might cause the difference. I usually learn from your posts but it is much more fun when the topic is not something boneheaded that I have said or done ;-)

 

[xKiv]

So, why is the browser deciding to cache this - and for how long?

I don't know. I might have something set that causes my FF to cache more aggressively?

Also, now it's not caching localhost/images for me either. If it ever was, because I can no longer see any evidence that it was.
In the same trace file where I saw it yesterday.
Maybe I was just looking wrong.

 

[xKiv]

Also - separate thing: today I run with jprofiler, which gives more useful information than yesterday's visualvm ...
Looks like ~15% of mafia's time is spent in:
AdventureResult.equals, called from
net.java.dev.spellcast.utilities.LockableListModel.contains, called from
ItemDatabase.getAdventureRange, called from
Concoction.compareTo (repeats in the list), called from
Colletions.sort, called from
net.java.dev.spellcast.utilities.LockableListModel.sort, called from
ConcoctionDatabase.refreshConcoctions and ConcoctionDatabase.resetConcoctionStatGains

and
AdventureResult.equals, called from
List.contains, called from
GearChangeFrame.addItem and GearChangeFrame.validOffhandItems

(it's also called from other places, but these overwhelm the rest by two orders of magnitude).

Maybe some caching is in order here? Number of concoctions and number of items will only grow ... AdventureResult.equals is already being called ~20 million times per adventure for me ...

 

[Veracity]

I noticed that the Relay Browser is repeatedly asking for our local .js and .css files. Revision 12638 allows the Browser to cache such files.

- I added a version number - a "fingerprint", as the Google article I referenced above puts it - to each such file.
- When we fetch such files, we add a Last-Modified header with the date of the file and a Expires header of one month in the future.

Sure enough, my browser now fetches those files and doesn't ask for them again. Presumably it will ask again in a month - or when we change one of them and bump the version number in the filename.

I am still pondering what to do about caching and the image server.

 

[Veracity]

Hmm. I'm going to have to undo (some of) that, since we actually modify some of those .js files on the fly. Damn.

 

[Veracity]

And revision 12639 undoes the versioning for the three affected .js files.

 

[Darzil]

Hmm. I'm going to have to undo (some of) that, since we actually modify some of those .js files on the fly. Damn.

Do we modify them in the local cache?

If so I guess that's why relayUsesCachedImages cached them even when images weren't cached.

 

[Veracity]

What is "the local cache"?

And this has nothing to do with "relayUsesCachedImages" since these are files from the relay folder, not the image folder.

 

[Darzil]

Sorry, misunderstood.

Currently investigating my current performance, using the new debug trace, and seeing that any time I get an item or finish a fight the display in the relay browser is really slow, but the rest of the time the performance isn't too bad. I've had Mafia open most of the day, but have only run 87 turns, 40 automatically, and the rest in the browser. Seems to have got much slower in the last few hours where I've not been playing at all. Currently taking around 10 seconds from getting the data from KoL to sending it to the browser.

For example - pickpocket gets an item (cut out all bar fight.php and charpane.php, fight.php takes over 10 seconds from arriving at mafia to being sent to browser, but charpane takes 0.7 seconds)

1379362266917: Requesting: [url]http://www.kingdomofloathing.com/fight.php?action=steal[/url]
1379362267219: Retrieved: [url]http://www.kingdomofloathing.com/fight.php?action=steal[/url]
1379362277675: To Browser: HTTP/1.1 200 OK: /fight.php
1379362277793: Requesting: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362278497: Retrieved: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362279227: To Browser: HTTP/1.1 200 OK: /charpane.php

A pickpocket that fails is much faster: (0.7 seconds)

1379365269660: Requesting: http://www.kingdomofloathing.com/fight.php?action=steal
1379365269942: Retrieved: http://www.kingdomofloathing.com/fight.php?action=steal
1379365270642: To Browser: HTTP/1.1 200 OK: /fight.php

Then attack doesn't get an item, but ends fight (fight takes 0.07s to get to browser, charpane takes over 10 seconds)

1379362279539: Requesting: [url]http://www.kingdomofloathing.com/fight.php?action=attack[/url]
1379362279809: Retrieved: [url]http://www.kingdomofloathing.com/fight.php?action=attack[/url]
1379362279878: To Browser: HTTP/1.1 200 OK: /fight.php
1379362280076: Requesting: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362280331: Retrieved: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362291198: To Browser: HTTP/1.1 200 OK: /charpane.php

Another example, choice displays pretty fast in browser (0.25s), then when I get an item after selecting something, it's slow again, around 10 seconds for choice.php, and then again for charpane.php.

1379362314366: From Browser: GET /choice.php?forceoption=0 HTTP/1.1
1379362314366: Requesting: [url]http://www.kingdomofloathing.com/choice.php?forceoption=0[/url]
1379362314606: Retrieved: [url]http://www.kingdomofloathing.com/choice.php?forceoption=0[/url]
1379362314856: To Browser: HTTP/1.1 200 OK: /choice.php?forceoption=0
1379362318378: From Browser: POST /choice.php HTTP/1.1
1379362318378: Requesting: [url]http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=3[/url]
1379362318648: Retrieved: [url]http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=3[/url]
1379362329618: To Browser: HTTP/1.1 200 OK: /choice.php
1379362329747: Requesting: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362330460: Retrieved: [url]http://www.kingdomofloathing.com/charpane.php[/url]
1379362341388: To Browser: HTTP/1.1 200 OK: /charpane.php

Once it's running slowly, really doesn't matter whether you are automating or not. Mana burning on some spellcasting also takes ages, the piece being from getting api request back up to asking for the next skill cast, around 13 seconds each time.

1379365182190: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=88&quantity=3	
1379365182460: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=88&quantity=3	
1379365182700: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365182952: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365196190: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=1015&quantity=2	
1379365196900: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=1015&quantity=2	
1379365197360: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365197610: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365210528: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=2009&specificplayer=2013921&bufftimes=4	
1379365211218: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=2009&specificplayer=2013921&bufftimes=4	
1379365211658: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365211898: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365225855: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=3010&quantity=2	
1379365226565: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=3010&quantity=2	
1379365227015: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365227255: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365240817: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=6010&specificplayer=2013921&bufftimes=2	
1379365241527: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=6010&specificplayer=2013921&bufftimes=2	
1379365241967: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia	
1379365242237: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia

After a restart, all different.

Successful pickpocket: (0.7 seconds for fight, much faster, 0.7 seconds for charpane, same as before)

1379366574025: Requesting: http://www.kingdomofloathing.com/fight.php?action=steal
1379366574307: Retrieved: http://www.kingdomofloathing.com/fight.php?action=steal
1379366575037: To Browser: HTTP/1.1 200 OK: /fight.php
1379366575222: Requesting: http://www.kingdomofloathing.com/charpane.php
1379366575469: Retrieved: http://www.kingdomofloathing.com/charpane.php
1379366576199: To Browser: HTTP/1.1 200 OK: /charpane.php

Unsuccessful pickpocket: (0.7 sec - same as before restart)

1379366166757: Requesting: http://www.kingdomofloathing.com/fight.php?action=steal
1379366167027: Retrieved: http://www.kingdomofloathing.com/fight.php?action=steal
1379366167717: To Browser: HTTP/1.1 200 OK: /fight.php

Winning a fight : (0.4 sec for fight.php, 0.6 for charpane)

1379366582447: Requesting: http://www.kingdomofloathing.com/fight.php?action=attack
1379366582727: Retrieved: http://www.kingdomofloathing.com/fight.php?action=attack
1379366583167: To Browser: HTTP/1.1 200 OK: /fight.php
1379366583363: Requesting: http://www.kingdomofloathing.com/charpane.php
1379366583639: Retrieved: http://www.kingdomofloathing.com/charpane.php
1379366584019: To Browser: HTTP/1.1 200 OK: /charpane.php

Casting spells, now down to a much more reasonable 0.2 seconds from api.php to next spell request:

1379366565819: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=1015&quantity=3
1379366566099: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=1015&quantity=3
1379366566559: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366566809: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366567041: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=2009&specificplayer=2013921&bufftimes=4
1379366567311: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=2009&specificplayer=2013921&bufftimes=4
1379366567551: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366567801: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366568033: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=3010&quantity=2
1379366568463: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=3010&quantity=2
1379366568923: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366569183: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366569395: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=88&quantity=2
1379366569665: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=88&quantity=2
1379366569905: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366570155: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366570357: Requesting: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=6007&specificplayer=2013921&bufftimes=4
1379366570837: Retrieved: http://www.kingdomofloathing.com/skills.php?action=Skillz.&whichskill=6007&specificplayer=2013921&bufftimes=4
1379366571287: Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1379366571527: Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia

I think the only really new thing from this is that the performance hit only affects certain pieces of processing, which is more clear with the more accurate timestamps. Some are the same speed for both before and after restart, others are much faster after restart.

The areas that look affected :
Processing fight.php if an item is gained.
Processing charpane.php after a fight.
Processing choice.php if an item is gained.
Processing api.php after casting a spell.

The areas that don't look affected :
Processing fight.php if an item is not gained.
Processing charpane.php after a pickpocket success.

Getting late again, any ideas of next steps welcomed.

 

[Veracity]

OK, I figured out how to make relayUsesCachedImages work correctly.

- We munge http://images.kingdomofloathing.com to /images
- The browser asks KoLmafia for the local image.
- When we fetch it from KoL, if comes back with a Last-Modified header. We set the lastModified attribute of the file to that value.
- When we serve to local image file to the browser, we, in turn, pass down a Last-Modified header with the local file's lastModified time - which should match KoL's
- The browser then caches the file in exactly the same way as it caches the equivalent file it gets from images.kingdomofloathing.com

With this change, I see the browser fetch images from KoLmafia, which in turn fetches and caches them from KoL. The browser's cache kicks in and it never requests those images again.

I'm still a little unclear about how long the browser will keep its cache - and there is no mechanism for KoLmafia to clear its cache, either.

Further thought is required, but revision 12640 should work much better with cached images.

 

[Captain Kirk]

So in order to get the new image caching to work (without broken images using the relay browser prefence option "Cache kol images to conserve bandwidth"). I had to
quit kolmafia
delete everything in the images directory (except for relayimages/chit).
Restart kolmafia

 

[Veracity]

If I decide to make this the default behavior, I expect I'll make KoLmafia forcibly clear the image cache when you first start it after I do so.

I am not aware of relayimages. It makes me unhappy, since I was under the impression that I could remove "images/*" recursively to get rid of what we download from KoL. If "relayimages" is under "images", I guess I will have to exclude that.

Is that documented somewhere?

 

[Captain Kirk]

Also, I'm noticing some broken familiar images.. such as smimic.gif ... and others... don't know why most of the familiars work and some don't.

you can ask Bale about relayimages/chit

 

[Veracity]

Clear your browser cache. That will force it to ask KoLmafia to refetch the images.

That is one thing I cannot do via a KoLmafia change in isolation...

 

[Captain Kirk]

Yeah, I just cleared the cache, and a different set of familiar images were broken (I'm using chrome). So the smimic.gif worked, but others didn't.

Edit:
Ok you have to do it this way:

Quit mafia:
Clear image cache in browser
Delete image directory (again) except for relayimages/chit
Restart mafia

After that all the familiar images were good. (but sometimes a random image here or there isn't)

So then if you clear the image cache, and reload a frame, you get a page of broken links.

 

[Veracity]

I cannot reproduce that. With r12640, it loads every image, every time, reliably.
I'll have to think about what to suggest to help debug your issue.
Maybe if it happens to someone else, I'll get more info.

(I have never even downloaded Chrome. I cannot imagine what would induce me to download it, much less actually try executing it. Oh, well!)

 

[Veracity]

OK, even though I trust Google about as far as I can throw a neutron star, I installed Chrome.
I am completely unable to get KoLmafia to open the Relay Browser in it.
I really, really, really do not want to waste my time figuring that out.
Sorry!

 

[lostcalpolydude]

With our old relay browser loader, you had to use "-b com.browser.Google" if Chrome wasn't set as your default browser. I have no idea if that's the same now, and I don't have a mac to check.

 

[Veracity]

That didn't work.

There is zero chance that I will ever set Chrome as my default browser.

If somebody can tell me what to type in the Browser field of Preferences/External Programs to get Google Chrome on a Mac, I'm all ears.

Thanks.

 

[Bale]

It's actually /images/chit not /images/relayimages/chit

Perhaps those images should be relocated to the /data directory if they mess with your schema. I can do that. I just left them there because that's where the original author of ChiIT put them before I took over.