partest still deadlocking

I've been trying to reproduce it by running partest for the last 2-3
hours non-stop, unfortunately without success. I only have a dual-core
machine under my desk, though, but I'll try again on more cores.

Thread dumps are certainly helpful-- I couldn't find a deadlock
situation in there, though. Another very useful piece of output is what
the scheduler says if partest.debug is enabled.

Another thing: you seem to be running on a 1.5 JVM (since it uses
ResizableThreadPoolScheduler instead of ForkJoinScheduler). I was
wondering whether the behavior is different on 1.6.

I noticed that there is a certain delay between different test sets like
pos/neg, so that it's possible that one takes the thread dump before the
system is actually in a true deadlocked state.

Philipp

Paul Phillips wrote:
> I am still dealing with frustrating deadlocks. Twice today the test
> suite has frozen between "pos" and "neg". Here is a dump trimmed to the
> two threads which looked like they might be saying something
> interesting.
>
> Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.3-b01-101 mixed mode):
>
> "Thread-57" prio=5 tid=0x000000015730e800 nid=0x15b40a000 runnable [0x000000015b408000]
> java.lang.Thread.State: RUNNABLE
> at java.util.zip.ZipFile.getNextEntry(Native Method)
> at java.util.zip.ZipFile.access$400(ZipFile.java:29)
> at java.util.zip.ZipFile$2.nextElement(ZipFile.java:313)
> - locked <0x0000000123f617b0> (a java.util.zip.ZipFile)
> at java.util.zip.ZipFile$2.nextElement(ZipFile.java:299)
> at scala.collection.JavaConversions$JEnumerationWrapper.next(JavaConversions.scala:358)
> at scala.collection.Iterator$class.toStream(Iterator.scala:1143)
> at scala.collection.JavaConversions$JEnumerationWrapper.toStream(JavaConversions.scala:356)
> at scala.collection.Iterator$$anonfun$toStream$1.apply(Iterator.scala:1143)
> at scala.collection.Iterator$$anonfun$toStream$1.apply(Iterator.scala:1143)
> at scala.collection.immutable.Stream$Cons.tail(Stream.scala:490)
> at scala.collection.immutable.Stream$Cons.tail(Stream.scala:484)
> at scala.collection.immutable.Stream.foreach(Stream.scala:192)
> at scala.tools.nsc.io.ZipArchive$$anon$1.foreach(ZipArchive.scala:244)
> at scala.tools.nsc.io.ZipContainer$ZipRootCreator.apply(ZipArchive.scala:136)
> at scala.tools.nsc.io.ZipArchive.root(ZipArchive.scala:199)
> - locked <0x000000011f2b1158> (a scala.tools.nsc.io.ZipArchive)
> at scala.tools.nsc.io.ZipContainer$class.iterator(ZipArchive.scala:164)
> at scala.tools.nsc.io.ZipArchive.iterator(ZipArchive.scala:191)
> at scala.collection.IterableLike$class.foreach(IterableLike.scala:83)
> at scala.tools.nsc.io.AbstractFile.foreach(AbstractFile.scala:86)
> at scala.collection.TraversableLike$class.partialMap(TraversableLike.scala:303)
> at scala.tools.nsc.io.AbstractFile.partialMap(AbstractFile.scala:86)
> at scala.tools.nsc.util.DirectoryClassPath.classes(ClassPath.scala:304)
> - locked <0x000000011f2b11e8> (a scala.tools.nsc.util.DirectoryClassPath)
> at scala.tools.nsc.util.MergedClassPath$$anonfun$classes$3.apply(ClassPath.scala:330)
> at scala.tools.nsc.util.MergedClassPath$$anonfun$classes$3.apply(ClassPath.scala:330)
> at scala.collection.LinearSeqLike$class.foreach(LinearSeqLike.scala:97)
> at scala.collection.immutable.List.foreach(List.scala:46)
> at scala.tools.nsc.util.MergedClassPath.classes(ClassPath.scala:330)
> - locked <0x000000011f2b1230> (a scala.tools.nsc.util.JavaClassPath)
> at scala.tools.nsc.symtab.SymbolLoaders$PackageLoader.doComplete(SymbolLoaders.scala:150)
> at scala.tools.nsc.symtab.SymbolLoaders$SymbolLoader.complete(SymbolLoaders.scala:62)
> at scala.tools.nsc.symtab.SymbolLoaders$SymbolLoader.complete(SymbolLoaders.scala:36)
> at scala.tools.nsc.symtab.Symbols$Symbol.info(Symbols.scala:732)
> at scala.tools.nsc.symtab.Definitions$definitions$.init(Definitions.scala:759)
> at scala.tools.nsc.Global$Run.(Global.scala:594)
> at scala.tools.partest.nest.DirectCompiler.compile(CompileManager.scala:123)
> at scala.tools.partest.nest.CompileManager.shouldCompile(CompileManager.scala:188)
> at scala.tools.partest.nest.Worker$$anonfun$runTestCommon$1$1$$anonfun$8.apply(Worker.scala:419)
> at scala.tools.partest.nest.Worker$$anonfun$runTestCommon$1$1$$anonfun$8.apply(Worker.scala:419)
> at scala.tools.partest.nest.Worker$$anonfun$runTestCommon$1$1.apply(Worker.scala:421)
> at scala.tools.partest.nest.Worker$$anonfun$runTestCommon$1$1.apply(Worker.scala:410)
> at scala.tools.partest.nest.Worker.runInContext$1(Worker.scala:356)
> at scala.tools.partest.nest.Worker.runTestCommon$1(Worker.scala:410)
> at scala.tools.partest.nest.Worker.processSingleFile$1(Worker.scala:476)
> at scala.tools.partest.nest.Worker$$anonfun$runTests$2$$anonfun$apply$6.apply(Worker.scala:992)
> at scala.tools.partest.nest.Worker$$anonfun$runTests$2$$anonfun$apply$6.apply(Worker.scala:983)
> at scala.actors.Actor$$anon$1.act(Actor.scala:108)
> at scala.actors.Reaction$$anonfun$$init$$1.apply(Reaction.scala:31)
> at scala.actors.Reaction$$anonfun$$init$$1.apply(Reaction.scala:29)
> at scala.actors.ReactorTask.run(ReactorTask.scala:32)
> at scala.actors.threadpool.ThreadPoolExecutor.runWorker(Unknown Source)
> at scala.actors.threadpool.ThreadPoolExecutor$Worker.run(Unknown Source)
> at java.lang.Thread.run(Thread.java:637)
>
>
> "main" prio=5 tid=0x0000000101800800 nid=0x100501000 in Object.wait() [0x00000001004fe000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on <0x000000010f3d5e88> (a scala.actors.ActorProxy)
> at java.lang.Object.wait(Object.java:485)
> at scala.actors.Actor$class.liftedTree1$1(Actor.scala:649)
> at scala.actors.Actor$class.scala$actors$Actor$$suspendActor(Actor.scala:648)
> - locked <0x000000010f3d5e88> (a scala.actors.ActorProxy)
> at scala.actors.Actor$blocker$.block(Actor.scala:639)
> at scala.actors.scheduler.ResizableThreadPoolScheduler.managedBlock(ResizableThreadPoolScheduler.scala:169)
> at scala.actors.scheduler.DelegatingScheduler$class.managedBlock(DelegatingScheduler.scala:73)
> at scala.actors.Scheduler$.managedBlock(Scheduler.scala:22)
> at scala.actors.Actor$class.receiveWithin(Actor.scala:507)
> - locked <0x000000010f3d5e88> (a scala.actors.ActorProxy)
> at scala.actors.ActorProxy.receiveWithin(ActorProxy.scala:22)
> at scala.actors.Actor$.receiveWithin(Actor.scala:179)
> at scala.tools.partest.nest.DirectRunner$$anonfun$runTestsForFiles$1.apply(DirectRunner.scala:53)
> at scala.tools.partest.nest.DirectRunner$$anonfun$runTestsForFiles$1.apply(DirectRunner.scala:52)
> at scala.collection.LinearSeqLike$class.foreach(LinearSeqLike.scala:97)
> at scala.collection.immutable.List.foreach(List.scala:46)
> at scala.tools.partest.nest.DirectRunner$class.runTestsForFiles(DirectRunner.scala:52)
> at scala.tools.partest.nest.AntRunner.runTestsForFiles(AntRunner.scala:16)
> at scala.tools.partest.nest.AntRunner.reflectiveRunTestsForFiles(AntRunner.scala:27)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at scala.tools.partest.PartestTask.invokeMethod(PartestTask.scala:183)
> at scala.tools.partest.PartestTask.runTestsForFiles$1(PartestTask.scala:215)
> at scala.tools.partest.PartestTask.runSet$1(PartestTask.scala:257)
> at scala.tools.partest.PartestTask$$anonfun$8.apply(PartestTask.scala:277)
> at scala.tools.partest.PartestTask$$anonfun$8.apply(PartestTask.scala:277)
> at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:238)
> at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:238)
> at scala.collection.LinearSeqLike$class.foreach(LinearSeqLike.scala:97)
> at scala.collection.immutable.List.foreach(List.scala:46)
> at scala.collection.TraversableLike$class.map(TraversableLike.scala:238)
> at scala.collection.immutable.List.map(List.scala:46)
> at scala.tools.partest.PartestTask.execute(PartestTask.scala:277)
> at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
> at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:106)
> at org.apache.tools.ant.Task.perform(Task.java:348)
> at org.apache.tools.ant.Target.execute(Target.java:357)
> at org.apache.tools.ant.Target.performTasks(Target.java:385)
> at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1337)
> at org.apache.tools.ant.Project.executeTarget(Project.java:1306)
> at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
> at org.apache.tools.ant.Project.executeTargets(Project.java:1189)
> at org.apache.tools.ant.Main.runBuild(Main.java:758)
> at org.apache.tools.ant.Main.startAnt(Main.java:217)
> at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
> at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)
>

On Fri, Feb 26, 2010 at 02:24:40PM +0100, Philipp Haller wrote:
> Another thing: you seem to be running on a 1.5 JVM (since it uses
> ResizableThreadPoolScheduler instead of ForkJoinScheduler). I was
> wondering whether the behavior is different on 1.6.

Actually I'm on 1.6, snow leopard doesn't even have a 1.5 jvm. It looks
like I broke that selection a few days ago when I did a bunch of work on
properties. Looking at it I think I must have lost my mind because it's
wrong at least two different ways. Sorry about that, I'll fix it
shortly.

> I noticed that there is a certain delay between different test sets
> like pos/neg, so that it's possible that one takes the thread dump
> before the system is actually in a true deadlocked state.

There is no question it was hung. I can't say for sure it was
deadlocked as opposed to waiting for a single hung test to time out.
Anyway it sounds good that it's a result of me breaking the scheduler
selection.

Paul Phillips wrote:
> On Fri, Feb 26, 2010 at 02:24:40PM +0100, Philipp Haller wrote:
>> Another thing: you seem to be running on a 1.5 JVM (since it uses
>> ResizableThreadPoolScheduler instead of ForkJoinScheduler). I was
>> wondering whether the behavior is different on 1.6.
>
> Actually I'm on 1.6, snow leopard doesn't even have a 1.5 jvm. It looks
> like I broke that selection a few days ago when I did a bunch of work on
> properties. Looking at it I think I must have lost my mind because it's
> wrong at least two different ways. Sorry about that, I'll fix it
> shortly.

Ah, OK, good to know.

>> I noticed that there is a certain delay between different test sets
>> like pos/neg, so that it's possible that one takes the thread dump
>> before the system is actually in a true deadlocked state.
>
> There is no question it was hung. I can't say for sure it was
> deadlocked as opposed to waiting for a single hung test to time out.
> Anyway it sounds good that it's a result of me breaking the scheduler
> selection.

Yeah, it would be nice to find out more easily whether a test hangs or not.

I've now got a setup on an 8-core machine; I'll run partest in a loop
over night on there.

Cheers,
Philipp

On Fri, Feb 26, 2010 at 04:58:22PM +0100, Philipp Haller wrote:
> Ah, OK, good to know.

Interesting. We'll have to go 50/50 on this one, because although I
definitely totally broke the logic had it been working, once I undid my
damage it still gave me the 1.5 scheduler, because it was:

// on IBM J9 1.6 do not use ForkJoinPool
(jvmVendor.indexOf("Sun") != -1)

but

scala> scala.util.Properties.javaVmVendor
res1: java.lang.String = Apple Inc.

It's horrifyingly fragile (although I realize often necessary) to make
correctness decisions in this way, and this at least illustrates why I
was running around centralizing it so at least we don't have multiple
variations each doing their own local parsing of the vendor string.

Anyone know what an "IBM J9" vendor string looks like?

 Welcome to Scala version 2.8.0.Beta1-prerelease (IBM J9 VM, Java 1.6.0).
 Type in expressions to have them evaluated.
 Type :help for more information.
 
 scala> System.getProperty("java.vendor")
 res0: java.lang.String = IBM Corporation
 

- Colin

On Fri, Feb 26, 2010 at 11:14:02AM -0600, Colin Bullock wrote:
> Welcome to Scala version 2.8.0.Beta1-prerelease (IBM J9 VM, Java 1.6.0).
> Type in expressions to have them evaluated.
> Type :help for more information.
>
> scala> System.getProperty("java.vendor")
> res0: java.lang.String = IBM Corporation

Can you look up java.vm.vendor? That's the one being checked. (I do not
know where/when/how they differ or which is the right one, only going
with what was there.)

>  scala> System.getProperty("java.vendor")
>  res0: java.lang.String = IBM Corporation

I get the same ("IBM Corporation") for both.

- Colin

On 10-02-26 09:45 AM, Paul Phillips wrote:
> Can you look up java.vm.vendor? That's the one being checked. (I do not
> know where/when/how they differ or which is the right one, only going
> with what was there.)
>
Sorry if this is well-trodden ground, but why not try something more
like this?

// In a static initializer
val defaultScheduler = try {
val clazz = Class.forName("SchedulerThatRequiresJDK1_6")
val ctor = clazz.getConstructor(...)
ctor.newInstance(...).asInstanceOf[AwesomeScheduler]
} catch {
case ie @ (_: InstantiationException | _: ClassNotFoundException) =>
new BackwardCompatibleScheduler(...)
case _ =>
error("O NOES!!!")
}

-0xe1a