Unresponsive Program

[fronobulax]

Windows 7, 64 bit.
java version "1.6.0_20"
Java(TM) SE Runtime Environment (build 1.6.0_20-b02)
Java HotSpot(TM) 64-Bit Server VM (build 16.3-b01, mixed mode)

On several occasions mafia has become unresponsive, in the sense that Windows uses the term. If often happened when fetching Buffbot information so I really wanted to relate the unresponsiveness to that. However I don't believe that is the case. Several people reporting similar problems have noted it happens with chat open but I almost never use chat.

Memory use stays static and CPU drops to zero. Did not fire up a smarter task manager to see thread counts, waits and whatever else it tells me that I have previously ignored.

It happened to me today while auto adventuring with nothing but mafia and the relay browser in use. I was annoyed enough to try and connect a debugger but I failed.

My current suspicion is that it the problem is related to threading although I confess that I am just seizing on that because it it is an area I do not understand well.

Any hints or suggestions about things I could do or data I could gather that might lead to a solution?

My fallback will be to run in a debugger and/or monitor it with a better Procees Monitor.

 

[Fluxxdog]

I've had this experience plenty of times. It's been happening a lot less recently though. The bBS script I use if about 5kB in size, but when you add in all the files that I import to run the functions, it's well up in to the 150kB range, maybe more. One of the problems I noticed was as mafia was auto-adventuring, whether through the tab or the adventure() function, it seemed like it had to load all of those files, run it, dump it, adventure, reload... It took roughly about 25-30 second to do one adventure and it wasn't uncommon to have 2 or 3 freezes a day.

The time was my focus because I thought I simply had a bad operating environment causing the freezes. So, to reduce the time, I sought to develop a substitute for adventure() and came up with investigate.ash, which provided investigate(). When imported, it would also import my bBS (and all of its imports) and keep it in memory and skip the reloading adventure() would do by going after areas via visit_url(). String detection would use run_combat() and my own version of run_choice() to process the encounters. Once everything imported, mafia would run a hell of a lot faster. Something else I eventually noticed is the freezes stopped. I haven't had one a single freeze since I started using investigate() before Crimbo.

Then I had my first freeze last night. I didn't think much until you mentioned this. The freeze occurred while I was running macguffin.ash, a script made by Zarqon that uses adventure(). I hadn't used normal auto-adventuring until them by using the CLi and some ASH to set up my goals without touching the conditions. My theory is the freezes were being caused by the bBS and associated script being loaded, dumped, reloaded, etc. over and over again. (Java has been known to have problems with memory in the past.) However, I don't know enough to find out if this could be the case.

 

[fronobulax]

Interesting. The character who was running when the problem occurred is not using FTF, SmartStasis, BBS or even UR. I do load and run scripts but they are all from the menu or CLI and they are not running while I am autoadventuring. I'll ponder and see if there might be something I'm forgetting.

 

[Veracity]

My theory is the freezes were being caused by the bBS and associated script being loaded, dumped, reloaded, etc. over and over again.

That all sounds plausible except for the "loaded, dumped, reloaded" part; once an ASH script has been read and compiled into a parse tree, KoLmafia saves and reuses the parse tree from then on to execute the file, as long as the file and anything it includes has not changed on your disk. That means it does have to ask the OS for the modification dates of all the included file before each execution. That may or may not actually go to the disk, depending on what the OS caches.

Eliminating a between battle script and simply doing it in your outer script will certainly eliminate all the (potential) disk access to check the modification dates. But, in the absence of a between battle script, using visit_url() & run_combat() in place of adventure() seems like a red herring.

 

[Veracity]

And regarding "Unresponsive Program", I posted the following on the dev forum on June 26, 2010, titled "Swing Deadlocks". Nobody there responded and the issue remains undebugged and unresolved; it happened to me yesterday. Perhaps somebody here knows more how debug Swing issues.

---
Does anybody have any expertise in debugging these? A couple times a week, I get KoLmafia to hang when I am consuming stuff from the Item Manager and then click around and back to the Item Manager. A spinning beach ball appears whenever my mouse is over any KoLmafia frame and I have to ^C KoLmafia from the Terminal to get out of it.

Today, I started running under Eclipse, because I am tired of having my Store Manager get screwed up when it gets a stack trace, somewhere, which happens multiple times a day for me. I was unable to get that stack trace to happen, although I will continue looking, but I did get the Swing deadlock.

Here are three tasks that seem to be deadlocked.

This is the Swing Event Queue. Notice that a Button was pressed on the UseItemEnqueuePanel, which calls ConcoctionDatabase.consumeItem, which at line 790 invokes RequestThread.postRequest on the Use Item Request. Since this is the event queue, that posts the task to Foxtrot. That send the request over to the workerThread and waits for events.

PostEventQueue.this is id = 69

Thread [AWT-EventQueue-0] (Suspended)	
	PostEventQueue.flush() line: 2099 [local variables unavailable]	
	SunToolkit.flushPendingEvents() line: 611 [local variables unavailable]	
	ConditionalEventPump.peekEvent(EventQueue) line: 234	
	ConditionalEventPump.waitForEvent() line: 212	
	ConditionalEventPump.pumpEvent(Task) line: 139	
	ConditionalEventPump.access$300(ConditionalEventPump, Task) line: 32	
	ConditionalEventPump$Conditional.invoke(Object, Method, Object[]) line: 259	
	$Proxy1.evaluate() line: not available	
	EventDispatchThread.pumpEventsForFilter(int, Conditional, EventFilter) line: 210	
	EventDispatchThread.pumpEventsForHierarchy(int, Conditional, Component) line: 201	
	EventDispatchThread.pumpEvents(int, Conditional) line: 196	
	EventDispatchThread.pumpEvents(Conditional) line: 188	
	NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]	
	NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39	
	DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25	
	Method.invoke(Object, Object...) line: 597	
	ConditionalEventPump.pumpEvents(Task) line: 99	
	Worker(AbstractSyncWorker).post(Task, WorkerThread, EventPump) line: 94	
	Worker(AbstractSyncWorker).post(Job, WorkerThread, EventPump) line: 120	
	Worker.post(Job) line: 143	
	RequestThread.postRequest(GenericRequest) line: 77	
	ConcoctionDatabase.consumeItem(Concoction, int) line: 790	
	ConcoctionDatabase.handleQueue(boolean, boolean, boolean, int) line: 769	
	UseItemEnqueuePanel$ExecuteListener.run() line: 224	
	UseItemEnqueuePanel$ExecuteListener(ThreadedListener).actionPerformed(ActionEvent) line: 59	
	JButton(AbstractButton).fireActionPerformed(ActionEvent) line: 2028	
	AbstractButton$Handler.actionPerformed(ActionEvent) line: 2351	
	DefaultButtonModel.fireActionPerformed(ActionEvent) line: 387	
	DefaultButtonModel.setPressed(boolean) line: 242	
	AquaButtonUI$AquaButtonListener(BasicButtonListener).mouseReleased(MouseEvent) line: 236	
	JButton(Component).processMouseEvent(MouseEvent) line: 6348	
	JButton(JComponent).processMouseEvent(MouseEvent) line: 3267	
	JButton(Component).processEvent(AWTEvent) line: 6113	
	JButton(Container).processEvent(AWTEvent) line: 2085	
	JButton(Component).dispatchEventImpl(AWTEvent) line: 4714	
	JButton(Container).dispatchEventImpl(AWTEvent) line: 2143	
	JButton(Component).dispatchEvent(AWTEvent) line: 4544	
	LightweightDispatcher.retargetMouseEvent(Component, int, MouseEvent) line: 4618	
	LightweightDispatcher.processMouseEvent(MouseEvent) line: 4282	
	LightweightDispatcher.dispatchEvent(AWTEvent) line: 4212	
	ItemManageFrame(Container).dispatchEventImpl(AWTEvent) line: 2129	
	ItemManageFrame(Window).dispatchEventImpl(AWTEvent) line: 2478	
	ItemManageFrame(Component).dispatchEvent(AWTEvent) line: 4544	
	EventQueue.dispatchEvent(AWTEvent) line: 635	
	EventDispatchThread.pumpOneEventForFilters(int) line: 296	
	EventDispatchThread.pumpEventsForFilter(int, Conditional, EventFilter) line: 211	
	EventDispatchThread.pumpEventsForHierarchy(int, Conditional, Component) line: 201	
	EventDispatchThread.pumpEvents(int, Conditional) line: 196	
	EventDispatchThread.pumpEvents(Conditional) line: 188	
	EventDispatchThread.run() line: 122

Here is the Worker thread.

It is in UseItemRequest and is updating the status line via KoLmafia.updateDisplay. It happens to be hung trying to update the MallSearchFrame.

Both this task and the other are inside SunToolkit.flushPendingEvents() at line 611. Neither is proceeding.

PostEventQueue.this is id = 69
EventQueue.this is id = 68 and we are synchronized on "this"

Daemon Thread [Foxtrot Single Worker Thread #3] (Suspended)	
	EventQueue.postEventPrivate(AWTEvent) line: 212	
	EventQueue.postEvent(AWTEvent) line: 198	
	PostEventQueue.flush() line: 2107	
	SunToolkit.flushPendingEvents() line: 611	
	EventQueue.postEvent(AWTEvent) line: 197	
	EventQueue.invokeLater(Runnable) line: 991	
	SwingUtilities.invokeLater(Runnable) line: 1261	
	JButton(JComponent).revalidate() line: 4798	
	JButton(AbstractButton).setText(String) line: 296	
	ActionPanel$VerifyButtonPanel.setEnabled(boolean) line: 139	
	MallSearchFrame$MallSearchPanel(ActionVerifyPanel).setEnabled(boolean) line: 345	
	MallSearchFrame$MallSearchPanel(GenericPanel).setEnabled(boolean) line: 261	
	KoLmafia.updateDisplayState(int, String) line: 653	
	KoLmafia.updateDisplay(int, String) line: 634	
	KoLmafia.updateDisplay(String) line: 609	
	UseItemRequest.useOnce(int, int, String) line: 1261	
	UseItemRequest.run() line: 877	
	AbstractWorkerThread$AbstractWorkerAction.run() line: 84	
	AccessController.doPrivileged(PrivilegedExceptionAction<T>, AccessControlContext) line: not available [native method]	
	SingleWorkerThread(AbstractWorkerThread).runTask(Task) line: 41	
	SingleWorkerThread.run(Task) line: 235	
	SingleWorkerThread.run() line: 216	
	Thread.run() line: 637

Here is another thread which seems to be posting to the event queue. Looking at the arguments, it is a Mouse event. The "source" is "ItemManageFrame". Presumably, this is the task that detected and dispatched my mouse click.

PostEventQueue.this is id = 69

Daemon Thread [AWT-AppKit] (Suspended)	
	PostEventQueue.postEvent(AWTEvent) line: 2121	
	SunToolkit.postEvent(AppContext, AWTEvent) line: 585	
	CToolkit.postEvent(AWTEvent) line: 1086	
	EventFactoryProxy.forwardEvent(AWTEvent) line: 53

I don't know how to find who has the lock on the object. I have no idea how to proceed. I'm going to kill this and continue my day. If anybody has any advice on what to do to debug this better next time, I'm all ears.

 

[fronobulax]

Thanks. I don't know any more about debugging Swing when I failed to respond to that post originally but I guess I am more motivated several months later. It does seem to me that changing focus or opening up another tab or window seems to be a common trigger so Swing may be implicated.

Today, I started running under Eclipse, because I am tired of having my Store Manager get screwed up when it gets a stack trace, somewhere, which happens multiple times a day for me. I was unable to get that stack trace to happen

Gee, I get what is probably the same stack trace daily and I couldn't catch it in NetBeans.

I go forth, as ignorant as always, but more motivated than usual.

 

[Fluxxdog]

That all sounds plausible except for the "loaded, dumped, reloaded" part; once an ASH script has been read and compiled into a parse tree, KoLmafia saves and reuses the parse tree from then on to execute the file, as long as the file and anything it includes has not changed on your disk. That means it does have to ask the OS for the modification dates of all the included file before each execution. That may or may not actually go to the disk, depending on what the OS caches.

Eliminating a between battle script and simply doing it in your outer script will certainly eliminate all the (potential) disk access to check the modification dates. But, in the absence of a between battle script, using visit_url() & run_combat() in place of adventure() seems like a red herring.

I understand what you're saying. The reason it takes such a long time between each adventure() is because it's waiting for a response from the OS. Huh. Which would mean all the waiting is because of all the files I have in use which IIRC is about 20-25 different imports.

Question then: Why, when automatically adventuring or using adventure() in the middle of an active script, does it have to recheck the disk? I could understand one check at the start of the script/clicking the begin button, but a check in between each single adventure during automation? (Sorry if this is a little off track, but this is interesting!)

 

[fronobulax]

Question then: Why, when automatically adventuring or using adventure() in the middle of an active script, does it have to recheck the disk?

Why are you certain it is mafia hitting the disk? (I'd love a simple, easy to use utility that told me what process was accessing my disk at the moment. I can answer that question in Windows (and never asked it in Linux) but I have a Swiss Army Knife and wouldn't mind a simple screwdriver, if you have one).


Any chance that the disk hit is a write to the session log rather than something checking on the script file?

 

[Fluxxdog]

Why are you certain it is mafia hitting the disk?

Point, but considering this is consistent behavior, quack and whatnot.

Any chance that the disk hit is a write to the session log rather than something checking on the script file?

Army knife, screwdriver, I'm the guy with the blowtorch. Don't know how to answer. Though nothing seemed to speed up when logging was disabled.

 

[fronobulax]

Ran in Netbeans today. Got unresponsive behavior. Debugger detected a deadlock between a Foxtrot Single Worker Thread and an AWT Event Queue thread. I was not able to capture all of the details (operator incompetence) but it looks very similar to what Veracity reported above. Just FYI since I am still digesting all of this.

 

[Theraze]

Could try out this patch to update Foxtrot from 1.3 to 3.0. Or could try this zip of the updated Foxtrot files. Mafia did compile and run with this patch. Not certain if the patch is complete... I reverted the folder to approved, but it didn't seem the same as I remembered.

 

[fronobulax]

Since the discussion is getting somewhat technical, part of it has migrated to the Developer's board. I've got something that I need to try and if it doesn't work or solve the problem then Theraze has some ideas.

 

[fronobulax]

I basically just updated Foxtrot from 2005 to 2008 and mafia seems much better behaved. My notes about what I did:

• Changed name of package in foxtrot files from foxtrot.* to net.sourceforge.foxtrot.*
  
• Changed import in foxtrot files to be net.sourceforge.foxtrot.
  
• Changed void run to Object run and added return(null) as required to compile.
  
• Changed a couple instances of Runnable to Job

I have attached a patch file although there is no guarantee that I actually created it in a way that is usable by someone else.

My expectation is that I will commit this in a day or two.

 

[Veracity]

One comment: KoLmafia source conventions would have "return null;" instead of "return(null);"
(And even if we wanted "return(null)", we'd do "return( null )")

Did you change the indentation of the foxtrot sources, or did that come with the new version? I mean, the following change looks sort of weird, for example:

 	/**
-	 * Returns whether this WorkerThread is alive. It is not enough to return whether this WorkerThread has been
-	 * started, because Applets can stop threads used by implementations of this WorkerThread in any moment. If this
-	 * WorkerThread is not alive, it must be restarted.
+     * Returns whether this WorkerThread is alive. It is not enough to return
+     * whether this WorkerThread has been started, because Applets can stop threads
+     * used by implementations of this WorkerThread in any moment.
+     * If this WorkerThread is not alive, it must be restarted.
 	 * 
 	 * @see #start
 	 */

All the deleted lines start with a tab and the lines which replace them start with 5 spaces. That looks like something your editor (or IDE) did to the sources. Don't do that.

Edit:, OK, I downloaded the new version myself and answered that question. The sourceforge source has:

    /**
     * Returns whether this WorkerThread is alive. It is not enough to return
     * whether this WorkerThread has been started, because Applets can stop threads
     * used by implementations of this WorkerThread in any moment.
     * If this WorkerThread is not alive, it must be restarted.
     *
     * @see #start
     */

Note that the comment block start and end lines have spaces in front of them, not a tab, like in your source, so the comment blocks line up. Weird. This just may be an artifact of the "diff" file created by your IDE.

 

[fronobulax]

Thanks for checking on the tabs. My IDE is set to not expand tabs to spaces but I don't really trust the setting.

I'll replace return(null) with return null. Easy to do and I have this nasty habit of forgetting mafia code and formatting conventions so the exercise will do me good.

 

[fronobulax]

r8919

I figured it was better to push it out before the exponentiation change and the new release. As they say in all the tech support cartoons "But it is working here!".

 

[apenny]

Hi folks,

I've been having this problem, and I'm not sure it's associated with mafia but it seems possible. I've been having numerous hangs with firefox (or chrome, doesn't seem to matter what browser I'm using and I've tried using firefox in safe mode, still happens) waiting and hanging. I believe that it's waiting on mafia to respond but I'm not sure and I don't know what to do do to fix it. Any suggestions you might have would be welcome.

Mary (apenny)

 

[Veracity]

What version of KoLmafia are you using?

 

[apenny]

Hi - I have had this trouble with many recent versions of mafia. It seems to be occurring in the version I have now which is 8934.

It seems like killing mafia then eventually resolves the browser hang. Additionally is there some way to observe the traffic between mafia and the browser?

Thanks a lot,

apenny

 

[icon315]

Happened again, but not always with the browser, although usually; Today it happened when creating items