[jira] [Commented] (MNG-6474) Maven intermittently hanging at end of multithreaded build

["Michael Osipov (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/MNG-6474?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16611144#comment-16611144 ] 

Michael Osipov commented on MNG-6474:
-------------------------------------

Please reformat the strace as it is outputted by Java. It is very hard to read.

A quick look says me that this is incomplete. There is a Resolver thread waiting for something, likely an HTTP reponse. I miss what {{0x000000006038e000}} and {{0x00000000814b9900}} are. Can you provide more details? Attach to the VM with VisualVM and check for this ref?

> Maven intermittently hanging at end of multithreaded build
> ----------------------------------------------------------
>
>                 Key: MNG-6474
>                 URL: https://issues.apache.org/jira/browse/MNG-6474
>             Project: Maven
>          Issue Type: Bug
>    Affects Versions: 3.5.2
>            Reporter: Beirtí Ó'Nunáin
>            Priority: Major
>
> I can't reproduce this with a small skeleton project. It has only started happening since we upgraded from 3.3 to 3.5.
>  
> I have a multithreaded multi-module build which builds a number of large (300mb+) artifacts upon SVN commits. I'm running the following goals:
>  
> mvn clean deploy -T 1C
>  
> Reasonably often, perhaps 1 in 10 builds, the build hangs just before where I'd expect the build to have finished. I'm guessing that maven is attempting to install an artifact to the local repository (looking at the stack trace) while the build is about to complete as when I compare the build log from the hung build to a successful build, the following line is the "Reactor Summary"
> This issue happens both on my local machine  and on our TeamCity server (Both multi-processor, multi-core 14 vs 32 cores)
> The Thread dump isn't indicating any kind of DeadLock. Our sysadmins have checked the box for any antivirus scanning which may be impacting the file copy indicated in the log but can't see anything going on at that time.
> Here's the thread dump from TeamCity when it times out:
>  
> {quote}
> Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode): "resolver-5" #63 daemon prio=5 os_prio=0 tid=0x00000000596ff800 nid=0x1e98 waiting on condition [0x000000006038e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000814b9900> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "resolver-4" #62 daemon prio=5 os_prio=0 tid=0x00000000596fe800 nid=0x134c waiting on condition [0x000000005f42e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000814b9900> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "resolver-3" #61 daemon prio=5 os_prio=0 tid=0x00000000596fe000 nid=0x17c0 waiting on condition [0x000000005fa4e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000814b9900> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "resolver-2" #60 daemon prio=5 os_prio=0 tid=0x00000000596fc800 nid=0x135c waiting on condition [0x000000005ff2f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000814b9900> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "resolver-1" #59 daemon prio=5 os_prio=0 tid=0x00000000596fb800 nid=0x1538 waiting on condition [0x000000005fd9f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000814b9900> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 5" #22 prio=5 os_prio=0 tid=0x000000005ca94800 nid=0x11b4 waiting on condition [0x000000005f54f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000082020030> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 4" #21 prio=5 os_prio=0 tid=0x000000005cb4f800 nid=0x1278 waiting on condition [0x000000005f26f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000082020030> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 3" #20 prio=5 os_prio=0 tid=0x000000005c83f800 nid=0xfc4 waiting on condition [0x000000005dddf000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000082020030> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 2" #19 prio=5 os_prio=0 tid=0x000000005d059800 nid=0x1c08 waiting on condition [0x000000005dfdf000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000082020030> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 1" #18 prio=5 os_prio=0 tid=0x000000005d458800 nid=0x1e7c runnable [0x00000000599ae000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.open0(Native Method) at java.io.FileOutputStream.open(FileOutputStream.java:270) at java.io.FileOutputStream.<init>(FileOutputStream.java:213) at java.io.FileOutputStream.<init>(FileOutputStream.java:162) at org.eclipse.aether.internal.impl.DefaultFileProcessor.copy(DefaultFileProcessor.java:166) at org.eclipse.aether.internal.impl.DefaultFileProcessor.copy(DefaultFileProcessor.java:150) at org.eclipse.aether.internal.impl.DefaultInstaller.install(DefaultInstaller.java:267) at org.eclipse.aether.internal.impl.DefaultInstaller.install(DefaultInstaller.java:195) at org.eclipse.aether.internal.impl.DefaultInstaller.install(DefaultInstaller.java:152) at org.eclipse.aether.internal.impl.DefaultRepositorySystem.install(DefaultRepositorySystem.java:377) at org.apache.maven.artifact.installer.DefaultArtifactInstaller.install(DefaultArtifactInstaller.java:107) at org.apache.maven.plugin.install.InstallMojo.execute(InstallMojo.java:115) at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117) at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:200) at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder$1.call(MultiThreadedBuilder.java:196) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "BuilderThread 0" #11 prio=5 os_prio=0 tid=0x0000000059f2f000 nid=0x1fac waiting on condition [0x000000005c27e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000082020030> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) "Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00000000575b9800 nid=0x1ca4 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x000000005752b000 nid=0x1128 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000057524800 nid=0x1918 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x00000000565dd000 nid=0x1c94 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x00000000565dc000 nid=0x199c waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x00000000565db000 nid=0x16bc runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000000f5d800 nid=0x1f34 in Object.wait() [0x000000005817f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x000000008176afe0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143) - locked <0x000000008176afe0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209) "Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000000f55000 nid=0xf40 in Object.wait() [0x000000005846f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000081aa4ce0> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) - locked <0x0000000081aa4ce0> (a java.lang.ref.Reference$Lock) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "main" #1 prio=5 os_prio=0 tid=0x0000000000eb7800 nid=0x958 waiting on condition [0x000000000116e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000081d86ec8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at java.util.concurrent.ExecutorCompletionService.take(ExecutorCompletionService.java:193) at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder.multiThreadedProjectTaskSegmentBuild(MultiThreadedBuilder.java:140) at org.apache.maven.lifecycle.internal.builder.multithreaded.MultiThreadedBuilder.build(MultiThreadedBuilder.java:101) at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:309) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:194) at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:107) at org.apache.maven.cli.MavenCli.execute(MavenCli.java:955) at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:290) at org.apache.maven.cli.MavenCli.main(MavenCli.java:194) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289) at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229) at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415) at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356) "VM Thread" os_prio=2 tid=0x00000000574e1800 nid=0x18e4 runnable "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000000ece000 nid=0x8e8 runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000000ecf800 nid=0x155c runnable "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000000ed1000 nid=0x1e90 runnable "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000000ed4800 nid=0x1afc runnable "GC task thread#4 (ParallelGC)" os_prio=0 tid=0x0000000000ed5800 nid=0x44c runnable "GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000000ed8000 nid=0x1e14 runnable "VM Periodic Task Thread" os_prio=2 tid=0x00000000575c1800 nid=0x1d68 waiting on condition JNI global references: 231_
> {quote}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)