Deadlocks on IO in jdk1.5.0_06

[commie]

This problem has me totally perplexed. It's in regards to my CoffeeMud
package, the full source is available on sourceforge or from
coffeemud.zimmers.net if you are interested.

Anyway, I'm getting periodic deadlocked threads, which Java5
brilliantly allows me to do a stacktrace dump on from a "watcher"
thread. Here's a trace dump:

6/8/2006 8:26 PM Debug UtiliDump java.io.PrintWriter:
write(PrintWriter.java: 352)
6/8/2006 8:26 PM Debug UtiliDump java.io.PrintWriter:
write(PrintWriter.java: 371)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
out(DefaultSession.java: 352)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
onlyPrint(DefaultSession.java: 444)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
print(DefaultSession.java: 457)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
showPrompt(DefaultSession.java: 1295)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
run(DefaultSession.java: 1465)
6

In the above case, it was only trying to display the dadgum prompt --
it never came back; the UtiliThread detected the deadlocked thread, and
displayed the stack dump. There were no other competing threads that
also deadlocked at the same time -- this was a loner.

Unfortunately, this happens perhaps once per day among hundreds of
logins, so it's not an easy one to reproduce.

The line in PrintWriter is a synchronize(lock) line, but this suggests
that somehow the lock was never released by a previous call, no?

Any advice is appreciated.

- Bo Zimmerman

 

[EJP]

You can't always trust the line numbers in Java source code. Are you
sure it isn't just stalled in a socket write?

 

[Matt Humphrey]

This problem has me totally perplexed. It's in regards to my CoffeeMud
package, the full source is available on sourceforge or from
coffeemud.zimmers.net if you are interested.

In the above case, it was only trying to display the dadgum prompt --
it never came back; the UtiliThread detected the deadlocked thread, and
displayed the stack dump. There were no other competing threads that
also deadlocked at the same time -- this was a loner.

Unfortunately, this happens perhaps once per day among hundreds of
logins, so it's not an easy one to reproduce.

The line in PrintWriter is a synchronize(lock) line, but this suggests
that somehow the lock was never released by a previous call, no?

Probably not--a key advantage of the synchronize operation is the assurance
of pairing lock with unlock. Unfortunately, that's not enough to prevent
deadlock.

PrintWriter has an internal lock that it synchronizes on before writing to
the inner Writer, so it really only blocks when the underlying writer
blocks. I would say first that you have another threading writing to the
PrintWriter which owns the outer lock but which is blocked on the writer.
What would make that inner writer block? Is it a socket? A file on a
networked file system or otherwise exotic communications or messaging
system?

It seems unlikely, but if your code that calls the PrintWriter is within
another synchronized block that is based on this inner writer and the other
thread is writing to the Print Writer and has the PW lock (but is waiting on
the inner writer) you will have deadlock. This seems highly contrived,
however. It all depends on what that inner writer is and how you're using
it.

Writer innerWriter is a some kind of unusual writer that internally
synchronizes on itself...

PrintWriter pw = new PrintWriter (innerWriter);

In thread 1
synchronized (innerWriter) {
....
pw.println ("Foo");
}

In thread 2
pw.println ("Bar");

Cheers,
Matt Humphrey (e-mail address removed) http://www.iviz.com/

 

[Chris Uppal]

Anyway, I'm getting periodic deadlocked threads, which Java5
brilliantly allows me to do a stacktrace dump on from a "watcher"
thread. Here's a trace dump:

6/8/2006 8:26 PM Debug UtiliDump java.io.PrintWriter:
write(PrintWriter.java: 352)
6/8/2006 8:26 PM Debug UtiliDump java.io.PrintWriter:
write(PrintWriter.java: 371)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
out(DefaultSession.java: 352)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
onlyPrint(DefaultSession.java: 444)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
print(DefaultSession.java: 457)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
showPrompt(DefaultSession.java: 1295)
6/8/2006 8:26 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
run(DefaultSession.java: 1465)

I can't see anything in the above information to indicate which /pair/ of
threads are deadlocked (and it always will be a pair -- at least -- unless you
are playing bad games with JNI or bytecode modification). Unless you have that
information, your only hope of diagnosing the deadlock is by wracking your
brains over the source code.

You should be able to find out more using the new management concole, JConsole.
See
http://java.sun.com/developer/technicalArticles/J2SE/jconsole.html
and scroll down to the bit about deadlock detection.

Also you are supposed to be able to press <Ctrl>\ to ask the running JVM to
print out a dump of the currently deadlocked threads. I have never made this
work myself, for some reason, so I don't know whether it kills the JVM as a
side effect, so don't try it on a live server until you know for sure ;-)

It would also be possible for some other thread to have taken out a lock on the
PrintWriter's lock object, but then stalled (but not deadlocked) for some
reason. That would look similar, but the tools wouldn't detect it directly.
For instance the other thread might be using a mis-written wait()/notify[All]()
sleep (using a different object as the focus of that pattern). But whether
real deadlock is involved or not, you have to find out which other threads are
holding the lock object at the time when your first thread stops.

-- chris

 

[Thomas Hawtin]

This problem has me totally perplexed. It's in regards to my CoffeeMud
package, the full source is available on sourceforge or from
coffeemud.zimmers.net if you are interested.

No web interface onto CVS/SVN?

Anyway, I'm getting periodic deadlocked threads, which Java5
brilliantly allows me to do a stacktrace dump on from a "watcher"
thread. Here's a trace dump:

You get better deadlock information with ctrl-\ (of ctrl-break for
Windows) or jstack.

The line in PrintWriter is a synchronize(lock) line, but this suggests
that somehow the lock was never released by a previous call, no?

Very difficult to do that.

Looking back at the 1.5 source of PrintWriter println(Object) calls
toString on the object under the writer lock. That's generally a very
bad idea. 1.6 (b86) fixes that. However, the formatting methods are
still dangerous.

Tom Hawtin

 

[Stephen Kellett]

Anyway, I'm getting periodic deadlocked threads, which Java5
brilliantly allows me to do a stacktrace dump on from a "watcher"
thread. Here's a trace dump:

May I suggest Java Thread Validator

http://www.softwareverify.com/javaThreadValidator/index.html

Stephen

 

[Chris Uppal]

May I suggest Java Thread Validator

http://www.XXXX.com/javaThreadValidator/index.html

It seems they have an interesing twist to purchasing. You enter your name,
email, credit card number, and all the usual stuff -- but there's nothing to
say how much you will be charged...

-- chris

 

[Stephen Kellett]

It seems they have an interesing twist to purchasing. You enter your name,
email, credit card number, and all the usual stuff -- but there's nothing to
say how much you will be charged...

Look on the prices page - where you would expect the prices to be
listed. Accessible from every page on the web site via a link on the
left hand side.

http://www.softwareverify.com/prices.php

Stephen

 

[Chris Uppal]

Look on the prices page - where you would expect the prices to be
listed. Accessible from every page on the web site via a link on the
left hand side.

I did look all over for the prices -- I didn't find them. Their problem, not
mine.

Also, in many cases going to the purchase page is the last resort to discover
products' prices -- not /not even there/ do they show them. And that is more
than merely incompetent. IANAL, but I think that in the UK, at least, it's
illegal.

I have no idea of how good or bad the product's themselves are (if I had to
guess, I would guess that they were probably pretty good), but the website is,
um, unimpressive.

-- chris

 

[Stephen Kellett]

Also, in many cases going to the purchase page is the last resort to discover
products' prices -- not /not even there/ do they show them.

Until you've chosen your product and quantity the site can't do that.
There is a deliberate effort to avoid JavaScript so you need to click
the Submit button to move to the confirmation page, where the price and
product are displayed.

And that is more
than merely incompetent. IANAL, but I think that in the UK, at least, it's
illegal.

It is illegal not to display the prices - SVL do display the prices. The
prices are listed on the prices page, which is linked to from every page
on the site.

....

but the website is,
um, unimpressive.

What would do to improve it? Seriously I'd like to know as you are not
the first person that couldn't see the Prices link even though it is
there on every page. I'm dumbfounded by how that is miss-able, so I'd
like your input.

If you'd like to reply via email thats fine. I hope you will take the
trouble to explain what you don't like.

Stephen

 

[Chris Uppal]

If you'd like to reply via email thats fine. I hope you will take the
trouble to explain what you don't like.

I've replied off-line.

-- chris

 

[Stephen Kellett]

I've replied off-line.

And a very nice and detailed reply it is.

Thanks

Stephen

 

[commie]

Thank you all for your suggestions. It is on a Socket-write, and my
thread-watcher thread is set up to scan all other threads in one swoop
and report all deadlocked threads at the same time (based on a simple
timeout), and yet these problems always come up alone. Wierd...

I'll look around for bad wait/notifies or sleeps -- no chance on the
former, unlikely on the later, but worth a shot. Other threads wanting
to write on the same socket is rather necessary, so I need that to be
perfect. Different threads intermingle their access to the each others
sockets in a rather chaotic manner, I'm afraid. I suppose I could also
simplify my problem by trying to ditch PrintWriter and leave myself
with one less sync to worry about.

As for SVN, I've never felt a need for the web features, but I suppose
it couldn't hurt if it pleases those who might help me solve this
bewildering delima.

- Bo

 

[EJP]

Thank you all for your suggestions. It is on a Socket-write

You need to consider the possibility that you are deadlocked at the
application protocol level rather than the Java synchronization level. I
saw an application a few years ago which froze because everybody was
trying to write to everybody else and nobody was reading, so all the
writes were blocked waiting for the reader to read.

 

[commie]

You need to consider the possibility that you are deadlocked at the
application protocol level rather than the Java synchronization level. I
saw an application a few years ago which froze because everybody was
trying to write to everybody else and nobody was reading, so all the
writes were blocked waiting for the reader to read.

Hello EJP -- this sounds like a distinct possibility, since the
client-readers are all subject to dropping at any time. Do you have
any other information about this? For instance, is there some way to
check the printwriter or the socket to find out if it is "safe" to
write to it?

- Bo

 

[commie]

I've got another stack dump of my deadlocked Socket-write threads, if
its helpful. To me, it's all just perplexing. This one occurs during
a flush of the output stream, which I do after every PrintStream.write
(can't use autoflush, since there are non-eoln prompts and such).

- Bo

6/12/2006 12:23 PM Debug UtiliDump java.net.SocketOutputStream:
socketWrite0(SocketOutputStream.java: -2)
6/12/2006 12:23 PM Debug UtiliDump java.net.SocketOutputStream:
socketWrite(SocketOutputStream.java: 92)
6/12/2006 12:23 PM Debug UtiliDump java.net.SocketOutputStream:
write(SocketOutputStream.java: 136)
6/12/2006 12:23 PM Debug UtiliDump
sun.nio.cs.StreamEncoder$CharsetSE: writeBytes(StreamEncoder.java: 336)
6/12/2006 12:23 PM Debug UtiliDump
sun.nio.cs.StreamEncoder$CharsetSE: implFlushBuffer(StreamEncoder.java:
404)
6/12/2006 12:23 PM Debug UtiliDump
sun.nio.cs.StreamEncoder$CharsetSE: implFlush(StreamEncoder.java: 408)
6/12/2006 12:23 PM Debug UtiliDump sun.nio.cs.StreamEncoder:
flush(StreamEncoder.java: 152)
6/12/2006 12:23 PM Debug UtiliDump java.iutputStreamWriter:
flush(OutputStreamWriter.java: 213)
6/12/2006 12:23 PM Debug UtiliDump java.io.PrintWriter:
flush(PrintWriter.java: 270)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
out(DefaultSession.java: 353)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
onlyPrint(DefaultSession.java: 444)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
rawPrint(DefaultSession.java: 452)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
rawPrint(DefaultSession.java: 449)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Common.DefaultSession:
stdPrintln(DefaultSession.java: 513)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.MOBS.StdMOB: tell(StdMOB.java: 2077)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.MOBS.StdMOB: tell(StdMOB.java: 2083)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Libraries.CommonMsgs:
lookAtExits(CommonMsgs.java: 1380)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Commands.Look: execute(Look.java: 140)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Libraries.CommonMsgs:
doStandardCommand(CommonMsgs.java: 52)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Libraries.CommonMsgs:
postLook(CommonMsgs.java: 133)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Behaviors.Patroller: tick(Patroller.java:
416)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.Items.Basic.StdItem: tick(StdItem.java: 446)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.core.threads.Tick: tickTicker(Tick.java: 273)
6/12/2006 12:23 PM Debug UtiliDump
com.planet_ink.coffee_mud.core.threads.Tick: run(Tick.java: 313)

 

[EJP]

Hello EJP -- this sounds like a distinct possibility, since the
client-readers are all subject to dropping at any time. Do you have
any other information about this? For instance, is there some way to
check the printwriter or the socket to find out if it is "safe" to
write to it?

No there isn't, short of the full NIO circus. You'd have to analyze your
application protocol and usage of threads. Basically you have to make
sure that a reading thread is always reading, and that if it drops out
it closes the socket or at least does shutdownInput() on the way, or
does something else to inhibit the application at both peers.

The case I encountered before was complex and I've forgotten the details
but there were several threads writing to the same socket which is
generally an unwanted disaster waiting to happen.