Uploaded image for project: 'Minecraft: Java Edition'
  1. Minecraft: Java Edition
  2. MC-131739

Data generators sometimes hang forever (and always wait to exit after finishing) due to data fixers

XMLWordPrintable

    • Unconfirmed

      When running one of the data generators (net.minecraft.data.Main), it takes a long time for the game to terminate.

      The cause seems to be the Bootstrap 0 thread used by data fixers (however, I'm not entirely sure what it does); jstack shows that the main thread has terminated but that thread has not. The jvm will not exit until that thread terminates, and that means that it waits until this thread has finished whatever it's doing... even though it serves no purpose for data generators.

      The delay first appeared in 18w19a after the major data fixer cleanup. However, on my machine the delay for that version is only around 5 seconds; it's gotten much worse in newer versions though.

      Timing sample

      Via date; java -cp minecraft_server.1.13-pre2.jar net.minecraft.data.Main --all; date:

      Wed, Jun 20, 2018  6:31:00 PM
[18:31:24] [main/INFO]: Starting provider: SNBT -> NBT
[18:31:24] [main/INFO]: SNBT -> NBT finished after 0 ms
[18:31:24] [main/INFO]: Starting provider: Fluid Tags
[18:31:24] [main/INFO]: Fluid Tags finished after 158 ms
[18:31:24] [main/INFO]: Starting provider: Block Tags
[18:31:24] [main/INFO]: Block Tags finished after 92 ms
[18:31:24] [main/INFO]: Starting provider: Item Tags
[18:31:24] [main/INFO]: Item Tags finished after 85 ms
[18:31:24] [main/INFO]: Starting provider: Recipes
[18:31:26] [main/INFO]: Recipes finished after 1857 ms
[18:31:26] [main/INFO]: Starting provider: Advancements
[18:31:27] [main/INFO]: Advancements finished after 646 ms
[18:31:27] [main/INFO]: Starting provider: NBT to SNBT
[18:31:27] [main/INFO]: NBT to SNBT finished after 0 ms
[18:31:27] [main/INFO]: Starting provider: Block List
[18:31:28] [main/INFO]: Block List finished after 1626 ms
[18:31:28] [main/INFO]: Starting provider: Item List
[18:31:29] [main/INFO]: Item List finished after 118 ms
[18:31:29] [main/INFO]: Starting provider: Command Syntax
[18:31:32] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[18:31:32] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[18:31:32] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[18:31:32] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[18:31:32] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[18:31:32] [main/INFO]: Loaded 0 recipes
[18:31:32] [main/INFO]: Loaded 0 advancements
[18:31:32] [main/INFO]: Command Syntax finished after 3808 ms
Wed, Jun 20, 2018  6:32:38 PM

      A ~25 second startup time for the JVM, then about 10 seconds of actually working, and then one minute of nothing useful.

      Complete hang

      Sometimes, instead of just taking a long time to exit, it completely deadlocks. I'm not entirely sure why, and it is inconsistent.

      Here is a jstack result for a complete freeze, from 1.13-pre2. Note that Bootstrap 0 is the data fixer thread.

      Confirmed through 22a.

      2018-06-20 11:42:22
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.162-b12 mixed mode):

"DestroyJavaVM" #16 prio=5 os_prio=0 tid=0x0000000002f22800 nid=0x1a28 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Server Infinisleeper" #15 daemon prio=5 os_prio=0 tid=0x000000001d221800 nid=0x23c4 waiting on condition [0x000000002023f000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at ry$1.run(SourceFile:91)

"Snooper Timer" #14 daemon prio=5 os_prio=0 tid=0x000000001bf7c000 nid=0x1cec in Object.wait() [0x000000002013f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000070b497098> (a java.util.TaskQueue)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	- locked <0x000000070b497098> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

"Bootstrap 0" #13 prio=5 os_prio=0 tid=0x000000001ce36000 nid=0x261c waiting on condition [0x000000001f93e000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007096f4678> (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:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x0000000019d1d800 nid=0x26d4 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000000019cc8000 nid=0x1970 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000019cc4000 nid=0x2598 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000000019cc1800 nid=0x10f4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x0000000019cc0000 nid=0x22bc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x0000000019cbd000 nid=0x1798 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000000301e800 nid=0x19c4 in Object.wait() [0x000000001b00f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000708f77820> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x0000000708f77820> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000003013000 nid=0x1ac8 in Object.wait() [0x000000001af0f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000709248c50> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x0000000709248c50> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=2 tid=0x0000000019c87800 nid=0x12ec runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002f38000 nid=0x1a30 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002f3a000 nid=0x14fc runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000002f3b800 nid=0x2544 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000002f3d000 nid=0x12cc runnable 

"VM Periodic Task Thread" os_prio=2 tid=0x000000001b633800 nid=0x1808 waiting on condition 

JNI global references: 2029

      To reproduce the hang

      Run the exporter on a loop. In bash:

      while true; do date; time java -cp minecraft_server.1.13-pre2.jar net.minecraft.data.Main --all; done

      On my machine, it took about 10 minutes for it to freeze, at about 1-1.5 minutes per attempt. However, it can theoretically take longer as this seems to be a race condition of some kind.

      Possible fixes

      • Fix whatever makes this thread take so long. Since I have no idea what it's actually for, I can't advise on this.
      • Make the Bootstrap thread a daemon by adding setDaemon(true) after setNameFormat("Bootstrap %d"). That way the JVM will still be able to terminate even if this thread isn't done.

            Unassigned Unassigned
            pokechu22 [Mod] Pokechu22
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: