Anthony Martin
- inertia
- inertia
- America/Los_Angeles
- Yes
- No
MC-48![[Mojang] Grum (Erik Broes)](../../../data/assets/gravatar/grum.png){kind=small}
In every version of Minecraft, third party (hacked) clients come along and manage to instantly lock multiplayer (i.e. cause SMP to freeze/go unresponsive). I assume this is a result of some kind of buffer overrun defect.
I have no proof that the behavior is actually caused by a buffer overrun, it's just what I call it when it happens.
Although managed languages such as Java and C# do not actually have buffer overruns, the specific virtual machines (JVM/CLR/etc) which actually run the code may.
Whatever it really is, something in a third party client is capable of generating a packet that can instantly choke the server, leaving it completely unresponsive, even to OS signals.
Analysis of the log usually gives the SMP staff clues and patterns of behavior to help mitigate the problem after the fact. Players using these techniques tend to announce they are about to crash the server, then do so. Banning the player and their IP helps reduce further occurrences.
The server does not typically generate a crash report for this situation. It just freezes, although the garbage collector appears to continue running.
The following is a log segment of it occurring today. The staff did not notice the problem for forty minutes (note the time stamp). In this example, the player (name redacted because I'm sure they love publicity) performed the same attack less than 24 hours prior. Their player name and IP was banned based on this pattern.
{{monospaced}}2012-10-24 05:06:16 [INFO] ##REDACTED##[/##REDACTED##:21404] logged in with entity id 1155260 at (-928.1505147866586, 45.0, -104.012543085556)
2012-10-24 05:06:59 [INFO] ##REDACTED##[/##REDACTED##:21438] logged in with entity id 1155662 at (-916.5, 45.0, -111.6215497774692)
2012-10-24 05:46:01 [INFO] Starting minecraft server version 1.4.1
2012-10-24 05:46:01 [INFO] Loading properties
2012-10-24 05:46:01 [INFO] Default game type: SURVIVAL
2012-10-24 05:46:01 [INFO] Generating keypair
2012-10-24 05:46:01 [INFO] Starting Minecraft server on *:25565
2012-10-24 05:46:02 [INFO] Preparing level "swim2"
2012-10-24 05:46:02 [INFO] Preparing start region for level 0
2012-10-24 05:46:02 [INFO] Done (0.716s)! For help, type "help" or "?"
2012-10-24 05:46:02 [INFO] Starting GS4 status listener
2012-10-24 05:46:03 [INFO] Starting remote control listener
2012-10-24 05:46:03 [INFO] Query running on 0.0.0.0:25565
2012-10-24 05:46:03 [INFO] RCON running on 0.0.0.0:25575{{monospaced}}In every version of Minecraft, third party (hacked) clients come along and manage to instantly lock multiplayer (i.e. cause SMP to freeze/go unresponsive). I assume this is a result of some kind of buffer overrun defect.
I have no proof that the behavior is actually caused by a buffer overrun, it's just what I call it when it happens.
Although managed languages such as Java and C# do not actually have buffer overruns, the specific virtual machines (JVM/CLR/etc) which actually run the code may.
Whatever it really is, something in a third party client is capable of generating a packet that can instantly choke the server, leaving it completely unresponsive, even to OS signals.
Analysis of the log usually gives the SMP staff clues and patterns of behavior to help mitigate the problem after the fact. Players using these techniques tend to announce they are about to crash the server, then do so. Banning the player and their IP helps reduce further occurrences.
The server does not typically generate a crash report for this situation. It just freezes, although the garbage collector appears to continue running.
The following is a log segment of it occurring today. The staff did not notice the problem for forty minutes (note the time stamp). In this example, the player (name redacted because I'm sure they love publicity) performed the same attack less than 24 hours prior. Their player name and IP was banned based on this pattern.
monospaced
2012-10-24 05:06:16 [INFO] ##REDACTED##[/##REDACTED##:21404] logged in with entity id 1155260 at (-928.1505147866586, 45.0, -104.012543085556) 2012-10-24 05:06:59 [INFO] ##REDACTED##[/##REDACTED##:21438] logged in with entity id 1155662 at (-916.5, 45.0, -111.6215497774692) 2012-10-24 05:46:01 [INFO] Starting minecraft server version 1.4.1 2012-10-24 05:46:01 [INFO] Loading properties 2012-10-24 05:46:01 [INFO] Default game type: SURVIVAL 2012-10-24 05:46:01 [INFO] Generating keypair 2012-10-24 05:46:01 [INFO] Starting Minecraft server on *:25565 2012-10-24 05:46:02 [INFO] Preparing level "swim2" 2012-10-24 05:46:02 [INFO] Preparing start region for level 0 2012-10-24 05:46:02 [INFO] Done (0.716s)! For help, type "help" or "?" 2012-10-24 05:46:02 [INFO] Starting GS4 status listener 2012-10-24 05:46:03 [INFO] Starting remote control listener 2012-10-24 05:46:03 [INFO] Query running on 0.0.0.0:25565 2012-10-24 05:46:03 [INFO] RCON running on 0.0.0.0:25575monospaced
In every version of Minecraft, third party (hacked) clients come along and manage to instantly lock multiplayer (i.e. cause SMP to freeze/go unresponsive). I assume this is a result of some kind of buffer overrun defect.
I have no proof that the behavior is actually caused by a buffer overrun, it's just what I call it when it happens.
Although managed languages such as Java and C# do not actually have buffer overruns, the specific virtual machines (JVM/CLR/etc) which actually run the code may.
Whatever it really is, something in a third party client is capable of generating a packet that can instantly choke the server, leaving it completely unresponsive, even to OS signals.
Analysis of the log usually gives the SMP staff clues and patterns of behavior to help mitigate the problem after the fact. Players using these techniques tend to announce they are about to crash the server, then do so. Banning the player and their IP helps reduce further occurrences.
The server does not typically generate a crash report for this situation. It just freezes, although the garbage collector appears to continue running.
The following is a log segment of it occurring today. The staff did not notice the problem for forty minutes (note the time stamp). In this example, the player (name redacted because I'm sure they love publicity) performed the same attack less than 24 hours prior. Their player name and IP was banned based on this pattern.
monospaced
2012-10-24 05:06:16 [INFO] ##REDACTED##[/##REDACTED##:21404] logged in with entity id 1155260 at (-928.1505147866586, 45.0, -104.012543085556) 2012-10-24 05:06:59 [INFO] ##REDACTED##[/##REDACTED##:21438] logged in with entity id 1155662 at (-916.5, 45.0, -111.6215497774692) 2012-10-24 05:46:01 [INFO] Starting minecraft server version 1.4.1 2012-10-24 05:46:01 [INFO] Loading properties 2012-10-24 05:46:01 [INFO] Default game type: SURVIVAL 2012-10-24 05:46:01 [INFO] Generating keypair 2012-10-24 05:46:01 [INFO] Starting Minecraft server on *:25565 2012-10-24 05:46:02 [INFO] Preparing level "swim2" 2012-10-24 05:46:02 [INFO] Preparing start region for level 0 2012-10-24 05:46:02 [INFO] Done (0.716s)! For help, type "help" or "?" 2012-10-24 05:46:02 [INFO] Starting GS4 status listener 2012-10-24 05:46:03 [INFO] Starting remote control listener 2012-10-24 05:46:03 [INFO] Query running on 0.0.0.0:25565 2012-10-24 05:46:03 [INFO] RCON running on 0.0.0.0:25575monospaced
In every version of Minecraft, third party (hacked) clients come along and manage to instantly lock multiplayer (i.e. cause SMP to freeze/go unresponsive). I assume this is a result of some kind of buffer overrun defect.
I have no proof that the behavior is actually caused by a buffer overrun, it's just what I call it when it happens.
Although managed languages such as Java and C# do not actually have buffer overruns, the specific virtual machines (JVM/CLR/etc) which actually run the code may.
Whatever it really is, something in a third party client is capable of generating a packet that can instantly choke the server, leaving it completely unresponsive, even to OS signals.
Analysis of the log usually gives the SMP staff clues and patterns of behavior to help mitigate the problem after the fact. Players using these techniques tend to announce they are about to crash the server, then do so. Banning the player and their IP helps reduce further occurrences.
The server does not typically generate a crash report for this situation. It just freezes, although the garbage collector appears to continue running.
The following is a log segment of it occurring today. The staff did not notice the problem for forty minutes (note the time stamp). In this example, the player (name redacted because I'm sure they love publicity) performed the same attack less than 24 hours prior. Their player name and IP was banned based on this pattern.
2012-10-24 05:06:16 [INFO] ##REDACTED##[/##REDACTED##:21404] logged in with entity id 1155260 at (-928.1505147866586, 45.0, -104.012543085556) 2012-10-24 05:06:59 [INFO] ##REDACTED##[/##REDACTED##:21438] logged in with entity id 1155662 at (-916.5, 45.0, -111.6215497774692) 2012-10-24 05:46:01 [INFO] Starting minecraft server version 1.4.1 2012-10-24 05:46:01 [INFO] Loading properties 2012-10-24 05:46:01 [INFO] Default game type: SURVIVAL 2012-10-24 05:46:01 [INFO] Generating keypair 2012-10-24 05:46:01 [INFO] Starting Minecraft server on *:25565 2012-10-24 05:46:02 [INFO] Preparing level "swim2" 2012-10-24 05:46:02 [INFO] Preparing start region for level 0 2012-10-24 05:46:02 [INFO] Done (0.716s)! For help, type "help" or "?" 2012-10-24 05:46:02 [INFO] Starting GS4 status listener 2012-10-24 05:46:03 [INFO] Starting remote control listener 2012-10-24 05:46:03 [INFO] Query running on 0.0.0.0:25565 2012-10-24 05:46:03 [INFO] RCON running on 0.0.0.0:25575
It was not obvious what precipitated this crash. There were several cheaters attempting to fly, but they would get automatically kicked and nothing obvious seemed to go wrong after that. Then, out of nowhere, the server crashed.
An administrator did perform an RCON command right before the exception. This may or may not be related. The RCON command was:
noformat}}give <player name> 394 16{{noformat
noformat---- Minecraft Crash Report ----
// Don't be sad, have a hug! <3Time: 10/25/12 9:46 AM
Description: Exception in server tick loopjava.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextEntry(HashMap.java:894)
at java.util.HashMap$KeyIterator.next(HashMap.java:928)
at hz.a(SourceFile:90)
at net.minecraft.server.MinecraftServer.r(SourceFile:721)
at hg.r(SourceFile:233)
at net.minecraft.server.MinecraftServer.q(SourceFile:661)
at net.minecraft.server.MinecraftServer.run(SourceFile:595)
at fp.run(SourceFile:818)Relevant Details:
- Minecraft Version: 1.4.2
- Operating System: Mac OS X (x86_64) version 10.8.1
- Java Version: 1.7.0_07, Oracle Corporation
- Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation
- Memory: 703529376 bytes (670 MB) / 3221225472 bytes (3072 MB) up to 3221225472 bytes (3072 MB)
- JVM Flags: 5 total; -Xmx3G -Xms3G -Xloggc:server_gc.log -XX:+UseG1GC -XX:+DisableExplicitGC
- AABB Pool Size: 24234 (1357104 bytes; 1 MB) allocated, 20708 (1159648 bytes; 1 MB) used
- Is Modded: Unknown (can't tell)
- Profiler Position: N/A (disabled)
- Vec3 Pool Size: 37661 (2109016 bytes; 2 MB) allocated, 19642 (1099952 bytes; 1 MB) used
- Player Count: 9 / 20
- World swim2 Players: 0 total; []
- World swim2 Chunk Stats: ServerChunkCache: 0 Drop: 0
- Type: Dedicated Server{{noformat}}
It was not obvious what precipitated this crash. There were several cheaters attempting to fly, but they would get automatically kicked and nothing obvious seemed to go wrong after that. Then, out of nowhere, the server crashed.
An administrator did perform an RCON command right before the exception. This may or may not be related. The RCON command was:
give <player name> 394 16{noformat}}---- Minecraft Crash Report ----
// Don't be sad, have a hug! <3Time: 10/25/12 9:46 AM
Description: Exception in server tick loopjava.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextEntry(HashMap.java:894)
at java.util.HashMap$KeyIterator.next(HashMap.java:928)
at hz.a(SourceFile:90)
at net.minecraft.server.MinecraftServer.r(SourceFile:721)
at hg.r(SourceFile:233)
at net.minecraft.server.MinecraftServer.q(SourceFile:661)
at net.minecraft.server.MinecraftServer.run(SourceFile:595)
at fp.run(SourceFile:818)Relevant Details:
- Minecraft Version: 1.4.2
- Operating System: Mac OS X (x86_64) version 10.8.1
- Java Version: 1.7.0_07, Oracle Corporation
- Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation
- Memory: 703529376 bytes (670 MB) / 3221225472 bytes (3072 MB) up to 3221225472 bytes (3072 MB)
- JVM Flags: 5 total; -Xmx3G -Xms3G -Xloggc:server_gc.log -XX:+UseG1GC -XX:+DisableExplicitGC
- AABB Pool Size: 24234 (1357104 bytes; 1 MB) allocated, 20708 (1159648 bytes; 1 MB) used
- Is Modded: Unknown (can't tell)
- Profiler Position: N/A (disabled)
- Vec3 Pool Size: 37661 (2109016 bytes; 2 MB) allocated, 19642 (1099952 bytes; 1 MB) used
- Player Count: 9 / 20
- World swim2 Players: 0 total; []
- World swim2 Chunk Stats: ServerChunkCache: 0 Drop: 0
- Type: Dedicated Server
It was not obvious what precipitated this crash. There were several cheaters attempting to fly, but they would get automatically kicked and nothing obvious seemed to go wrong after that. Then, out of nowhere, the server crashed.
An administrator did perform an RCON command right before the exception. This may or may not be related. The RCON command was:
give <player name> 394 16{noformat}}---- Minecraft Crash Report ----
// Don't be sad, have a hug! <3Time: 10/25/12 9:46 AM
Description: Exception in server tick loopjava.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextEntry(HashMap.java:894)
at java.util.HashMap$KeyIterator.next(HashMap.java:928)
at hz.a(SourceFile:90)
at net.minecraft.server.MinecraftServer.r(SourceFile:721)
at hg.r(SourceFile:233)
at net.minecraft.server.MinecraftServer.q(SourceFile:661)
at net.minecraft.server.MinecraftServer.run(SourceFile:595)
at fp.run(SourceFile:818)Relevant Details:
- Minecraft Version: 1.4.2
- Operating System: Mac OS X (x86_64) version 10.8.1
- Java Version: 1.7.0_07, Oracle Corporation
- Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation
- Memory: 703529376 bytes (670 MB) / 3221225472 bytes (3072 MB) up to 3221225472 bytes (3072 MB)
- JVM Flags: 5 total; -Xmx3G -Xms3G -Xloggc:server_gc.log -XX:+UseG1GC -XX:+DisableExplicitGC
- AABB Pool Size: 24234 (1357104 bytes; 1 MB) allocated, 20708 (1159648 bytes; 1 MB) used
- Is Modded: Unknown (can't tell)
- Profiler Position: N/A (disabled)
- Vec3 Pool Size: 37661 (2109016 bytes; 2 MB) allocated, 19642 (1099952 bytes; 1 MB) used
- Player Count: 9 / 20
- World swim2 Players: 0 total; []
- World swim2 Chunk Stats: ServerChunkCache: 0 Drop: 0
- Type: Dedicated Server
It was not obvious what precipitated this crash. There were several cheaters attempting to fly, but they would get automatically kicked and nothing obvious seemed to go wrong after that. Then, out of nowhere, the server crashed.
An administrator did perform an RCON command right before the exception. This may or may not be related. The RCON command was:
give <player name> 394 16---- Minecraft Crash Report ---- // Don't be sad, have a hug! <3 Time: 10/25/12 9:46 AM Description: Exception in server tick loop java.util.ConcurrentModificationException at java.util.HashMap$HashIterator.nextEntry(HashMap.java:894) at java.util.HashMap$KeyIterator.next(HashMap.java:928) at hz.a(SourceFile:90) at net.minecraft.server.MinecraftServer.r(SourceFile:721) at hg.r(SourceFile:233) at net.minecraft.server.MinecraftServer.q(SourceFile:661) at net.minecraft.server.MinecraftServer.run(SourceFile:595) at fp.run(SourceFile:818) Relevant Details: - Minecraft Version: 1.4.2 - Operating System: Mac OS X (x86_64) version 10.8.1 - Java Version: 1.7.0_07, Oracle Corporation - Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation - Memory: 703529376 bytes (670 MB) / 3221225472 bytes (3072 MB) up to 3221225472 bytes (3072 MB) - JVM Flags: 5 total; -Xmx3G -Xms3G -Xloggc:server_gc.log -XX:+UseG1GC -XX:+DisableExplicitGC - AABB Pool Size: 24234 (1357104 bytes; 1 MB) allocated, 20708 (1159648 bytes; 1 MB) used - Is Modded: Unknown (can't tell) - Profiler Position: N/A (disabled) - Vec3 Pool Size: 37661 (2109016 bytes; 2 MB) allocated, 19642 (1099952 bytes; 1 MB) used - Player Count: 9 / 20 - World swim2 Players: 0 total; [] - World swim2 Chunk Stats: ServerChunkCache: 0 Drop: 0 - Type: Dedicated Server
The pattern seems to be that at first, everything is fine, then more players log in and things get extremely laggy. The number of players doesn't seem unusual. Then, one of the players gets disconnected:
2012-10-28 17:07:37 [INFO] ##REDACTED## lost connection: disconnect.genericReason
Before he got disconnected, the players all see extreme lag. This lag is detected by the debug profiler. Here is the profile output during the problem:
---- Minecraft Profiler Results ---- // I'm working as hard as I can! Time span: 32806 ms Tick span: 10 ticks // This is approximately 0.30 ticks per second. It should be 20 ticks per second --- BEGIN PROFILE DUMP --- [00] levels - 99.19%/99.19% [01] swim2 - 100.00%/100.00% [02] tick - 99.90%/99.90% [03] entities - 99.57%/99.57% [04] regular - 99.95%/99.95% [05] tick - 99.41%/99.41% [06] move - 94.70%/94.70% [06] unspecified - 2.83%/2.83% [06] entityBaseTick - 0.69%/0.69% [06] ai - 0.64%/0.64% [07] newAi - 92.19%/0.64% [08] goalSelector - 30.32%/0.20% [09] unspecified - 70.02%/0.14% [09] canUse - 13.30%/0.03% [09] pathfind - 5.94%/0.01% [09] goalStart - 5.72%/0.01% [10] ng - 54.68%/0.01% [11] pathfind - 95.03%/0.01% [11] unspecified - 4.97%/0.00% [10] unspecified - 41.68%/0.00% [10] nf - 2.62%/0.00% [10] mj - 0.46%/0.00% [10] mw - 0.24%/0.00% [10] nj - 0.21%/0.00% [10] mr - 0.06%/0.00% [10] nh - 0.03%/0.00% [09] goalTick - 4.30%/0.01% [10] unspecified - 77.40%/0.01% [10] pathfind - 21.18%/0.00% [10] canSee - 1.42%/0.00% [09] canContinue - 0.73%/0.00% [08] unspecified - 23.58%/0.15% [08] controls - 22.13%/0.14% [09] unspecified - 44.26%/0.06% [09] look - 32.48%/0.05% [09] move - 15.11%/0.02% [09] jump - 8.15%/0.01% [08] targetSelector - 14.21%/0.09% [09] unspecified - 87.43%/0.08% [09] goalStart - 5.32%/0.00% [10] unspecified - 98.53%/0.00% [10] nq - 1.47%/0.00% [09] goalTick - 4.26%/0.00% [09] canUse - 2.26%/0.00% [09] canSee - 0.49%/0.00% [09] canContinue - 0.24%/0.00% [10] canSee - 66.15%/0.00% [10] unspecified - 33.85%/0.00% [08] navigation - 4.43%/0.03% [08] checkDespawn - 2.41%/0.02% [08] sensing - 1.76%/0.01% [08] mob tick - 1.15%/0.01% [07] unspecified - 5.39%/0.04% [07] oldAi - 2.42%/0.02% [08] unspecified - 57.40%/0.01% [08] ai - 20.96%/0.00% [08] stroll - 17.22%/0.00% [09] pathfind - 88.98%/0.00% [09] unspecified - 11.02%/0.00% [08] followpath - 4.42%/0.00% [06] rest - 0.60%/0.60% [06] travel - 0.29%/0.29% [07] move - 44.20%/0.14% [07] unspecified - 33.92%/0.11% [07] rest - 21.88%/0.07% [06] chunkCheck - 0.11%/0.11% [06] mobBaseTick - 0.08%/0.08% [06] push - 0.03%/0.03% [06] headTurn - 0.01%/0.01% [06] looting - 0.01%/0.01% [06] jump - 0.01%/0.01% [06] rangeChecks - 0.00%/0.00% [06] checkLight - 0.00%/0.00% [07] checkedPosition < toCheckCount - 66.65%/0.00% [07] unspecified - 18.70%/0.00% [07] getBrightness - 14.65%/0.00% [06] getBrightness - 0.00%/0.00% [06] checkedPosition < toCheckCount - 0.00%/0.00% [05] unspecified - 0.56%/0.56% [05] remove - 0.03%/0.03% [04] remove - 0.03%/0.03% [04] tileEntities - 0.02%/0.02% [05] unspecified - 99.31%/0.02% [05] move - 0.43%/0.00% [05] checkLight - 0.18%/0.00% [06] getBrightness - 50.00%/0.00% [06] unspecified - 41.67%/0.00% [06] checkedPosition < toCheckCount - 8.33%/0.00% [05] rest - 0.09%/0.00% [04] unspecified - 0.00%/0.00% [04] pendingTileEntities - 0.00%/0.00% [04] global - 0.00%/0.00% [03] tickTiles - 0.27%/0.27% [04] unspecified - 59.94%/0.18% [04] tickTiles - 21.00%/0.06% [04] getChunk - 6.92%/0.02% [04] iceandsnow - 2.65%/0.01% [04] tickChunk - 2.26%/0.01% [05] unspecified - 77.10%/0.01% [05] recheckGaps - 22.90%/0.00% [06] unspecified - 57.47%/0.00% [06] getBrightness - 40.35%/0.00% [06] checkedPosition < toCheckCount - 2.19%/0.00% [04] thunder - 1.86%/0.01% [04] checkLight - 1.86%/0.01% [04] moodSound - 1.54%/0.00% [04] buildList - 1.43%/0.00% [04] playerCheckLight - 0.53%/0.00% [05] unspecified - 64.53%/0.00% [05] getBrightness - 33.97%/0.00% [05] checkedPosition < toCheckCount - 1.50%/0.00% [03] mobSpawner - 0.09%/0.09% [03] chunkSource - 0.04%/0.04% [03] tickPending - 0.02%/0.02% [04] checkLight - 81.84%/0.02% [05] checkedPosition < toCheckCount - 56.16%/0.01% [05] getBrightness - 43.17%/0.01% [05] unspecified - 0.67%/0.00% [04] unspecified - 18.16%/0.00% [03] village - 0.00%/0.00% [03] unspecified - 0.00%/0.00% [03] chunkMap - 0.00%/0.00% [03] checkLight - 0.00%/0.00% [04] getBrightness - 54.51%/0.00% [04] unspecified - 45.49%/0.00% [04] checkedPosition < toCheckCount - 0.00%/0.00% [02] tracker - 0.10%/0.10% [02] unspecified - 0.00%/0.00% [02] pools - 0.00%/0.00% [01] unspecified - 0.00%/0.00% [00] connection - 0.81%/0.81% [01] packetflow - 96.52%/0.88% [02] unspecified - 70.32%/0.62% [02] travel - 12.17%/0.11% [03] move - 42.38%/0.05% [03] unspecified - 36.40%/0.04% [03] rest - 21.22%/0.02% [02] move - 4.14%/0.04% [02] mobBaseTick - 3.18%/0.03% [02] entityBaseTick - 2.86%/0.03% [02] rest - 2.69%/0.02% [02] ai - 1.79%/0.02% [03] unspecified - 80.67%/0.01% [03] oldAi - 19.33%/0.00% [02] push - 1.78%/0.02% [02] headTurn - 0.43%/0.00% [02] jump - 0.21%/0.00% [02] looting - 0.19%/0.00% [02] rangeChecks - 0.15%/0.00% [02] chunkCheck - 0.09%/0.00% [01] playerTick - 2.37%/0.02% [02] travel - 45.90%/0.01% [03] move - 97.31%/0.01% [03] unspecified - 1.35%/0.00% [03] rest - 1.34%/0.00% [02] push - 27.21%/0.01% [02] unspecified - 25.94%/0.01% [02] entityBaseTick - 0.43%/0.00% [02] mobBaseTick - 0.22%/0.00% [02] headTurn - 0.13%/0.00% [02] ai - 0.11%/0.00% [03] unspecified - 71.43%/0.00% [03] oldAi - 28.57%/0.00% [02] rangeChecks - 0.03%/0.00% [02] looting - 0.02%/0.00% [02] jump - 0.02%/0.00% [01] unspecified - 1.09%/0.01% [01] keepAlive - 0.03%/0.00% [00] tallying - 0.00%/0.00% [00] players - 0.00%/0.00% [00] tickables - 0.00%/0.00% [00] snooper - 0.00%/0.00% --- END PROFILE DUMP ---And here is the debug profiler after the problem has gone away (when "disconnect.genericReason" is logged):
---- Minecraft Profiler Results ---- // You should add flames to things, it makes them go faster! Time span: 42520 ms Tick span: 850 ticks // This is approximately 19.99 ticks per second. It should be 20 ticks per second --- BEGIN PROFILE DUMP --- [00] levels - 96.13%/96.13% [01] swim2 - 99.97%/96.19% [02] tick - 98.41%/94.66% [03] entities - 80.71%/76.40% [04] regular - 98.19%/75.02% [05] tick - 95.22%/71.43% [06] ai - 34.74%/24.82% [07] newAi - 92.46%/22.95% [08] goalSelector - 40.15%/9.21% [09] unspecified - 53.27%/4.91% [09] pathfind - 22.34%/2.06% [09] goalTick - 11.74%/1.08% [10] pathfind - 78.81%/0.85% [10] unspecified - 20.44%/0.22% [10] canSee - 0.71%/0.01% [10] checkLight - 0.05%/0.00% [11] unspecified - 64.54%/0.00% [11] getBrightness - 33.72%/0.00% [11] checkedPosition < toCheckCount - 1.74%/0.00% [09] canUse - 9.29%/0.86% [09] goalStart - 2.93%/0.27% [10] unspecified - 60.07%/0.16% [10] ng - 34.71%/0.09% [11] pathfind - 95.32%/0.09% [11] unspecified - 4.68%/0.00% [10] nf - 3.96%/0.01% [10] mj - 0.32%/0.00% [10] mh - 0.26%/0.00% [10] mq - 0.20%/0.00% [10] nj - 0.13%/0.00% [10] mu - 0.12%/0.00% [10] mw - 0.09%/0.00% [10] mr - 0.08%/0.00% [10] mp - 0.06%/0.00% [10] nh - 0.00%/0.00% [09] canContinue - 0.42%/0.04% [08] unspecified - 24.22%/5.56% [08] targetSelector - 14.57%/3.34% [09] unspecified - 88.28%/2.95% [09] goalStart - 4.51%/0.15% [10] unspecified - 99.99%/0.15% [10] nr - 0.01%/0.00% [09] goalTick - 3.62%/0.12% [09] canUse - 2.41%/0.08% [09] canSee - 1.10%/0.04% [09] canContinue - 0.08%/0.00% [10] unspecified - 63.84%/0.00% [10] canSee - 36.16%/0.00% [08] controls - 14.49%/3.32% [09] unspecified - 76.36%/2.54% [09] look - 13.82%/0.46% [09] move - 6.14%/0.20% [09] jump - 3.67%/0.12% [08] checkDespawn - 2.71%/0.62% [08] sensing - 1.50%/0.34% [08] navigation - 1.45%/0.33% [08] mob tick - 0.91%/0.21% [07] unspecified - 5.50%/1.37% [07] oldAi - 2.03%/0.50% [08] unspecified - 70.06%/0.35% [08] ai - 21.68%/0.11% [08] stroll - 6.83%/0.03% [09] pathfind - 93.94%/0.03% [09] unspecified - 6.06%/0.00% [08] followpath - 1.43%/0.01% [06] unspecified - 29.88%/21.34% [06] travel - 17.70%/12.64% [07] move - 48.49%/6.13% [07] unspecified - 30.72%/3.88% [07] rest - 20.79%/2.63% [06] entityBaseTick - 8.05%/5.75% [06] mobBaseTick - 4.17%/2.98% [06] move - 1.65%/1.18% [06] push - 1.40%/1.00% [06] headTurn - 0.68%/0.49% [06] rest - 0.58%/0.41% [06] chunkCheck - 0.42%/0.30% [06] looting - 0.27%/0.19% [06] rangeChecks - 0.26%/0.18% [06] jump - 0.21%/0.15% [06] checkLight - 0.00%/0.00% [07] checkedPosition < toCheckCount - 38.51%/0.00% [07] unspecified - 32.82%/0.00% [07] getBrightness - 28.67%/0.00% [06] getBrightness - 0.00%/0.00% [06] checkedPosition < toCheckCount - 0.00%/0.00% [05] unspecified - 4.43%/3.32% [05] remove - 0.35%/0.26% [04] tileEntities - 1.62%/1.24% [05] unspecified - 95.89%/1.19% [05] checkLight - 3.99%/0.05% [06] checkedPosition < toCheckCount - 73.03%/0.04% [06] getBrightness - 24.50%/0.01% [06] unspecified - 2.47%/0.00% [05] move - 0.09%/0.00% [05] rest - 0.03%/0.00% [04] remove - 0.15%/0.11% [04] unspecified - 0.04%/0.03% [04] pendingTileEntities - 0.00%/0.00% [04] global - 0.00%/0.00% [03] tickTiles - 14.39%/13.62% [04] unspecified - 54.76%/7.46% [04] tickTiles - 17.63%/2.40% [05] unspecified - 99.13%/2.38% [05] checkLight - 0.85%/0.02% [06] unspecified - 58.19%/0.01% [06] getBrightness - 26.21%/0.01% [06] checkedPosition < toCheckCount - 15.60%/0.00% [05] getBrightness - 0.01%/0.00% [05] checkedPosition < toCheckCount - 0.01%/0.00% [04] moodSound - 7.81%/1.06% [04] getChunk - 6.90%/0.94% [04] tickChunk - 4.95%/0.67% [05] recheckGaps - 70.18%/0.47% [06] unspecified - 71.30%/0.34% [06] getBrightness - 25.78%/0.12% [06] checkedPosition < toCheckCount - 2.92%/0.01% [05] unspecified - 29.82%/0.20% [04] iceandsnow - 2.55%/0.35% [04] buildList - 1.86%/0.25% [04] thunder - 1.69%/0.23% [04] checkLight - 1.45%/0.20% [04] playerCheckLight - 0.39%/0.05% [05] unspecified - 65.56%/0.03% [05] getBrightness - 32.60%/0.02% [05] checkedPosition < toCheckCount - 1.85%/0.00% [03] mobSpawner - 4.16%/3.94% [03] tickPending - 0.43%/0.41% [04] checkLight - 67.16%/0.27% [05] checkedPosition < toCheckCount - 75.51%/0.21% [05] getBrightness - 23.30%/0.06% [05] unspecified - 1.19%/0.00% [04] unspecified - 32.84%/0.13% [03] village - 0.10%/0.09% [03] chunkSource - 0.09%/0.09% [04] unspecified - 99.37%/0.08% [04] checkLight - 0.63%/0.00% [05] unspecified - 55.85%/0.00% [05] getBrightness - 32.58%/0.00% [05] checkedPosition < toCheckCount - 11.58%/0.00% [03] unspecified - 0.06%/0.06% [03] checkLight - 0.04%/0.04% [04] checkedPosition < toCheckCount - 95.74%/0.04% [04] unspecified - 2.82%/0.00% [04] getBrightness - 1.44%/0.00% [03] chunkMap - 0.02%/0.02% [02] tracker - 1.55%/1.49% [02] unspecified - 0.03%/0.03% [02] pools - 0.00%/0.00% [02] timeSync - 0.00%/0.00% [01] unspecified - 0.03%/0.03% [00] connection - 3.75%/3.75% [01] packetflow - 93.76%/3.52% [02] unspecified - 93.67%/3.30% [02] travel - 2.70%/0.09% [03] move - 46.72%/0.04% [03] unspecified - 33.99%/0.03% [03] rest - 19.29%/0.02% [02] entityBaseTick - 0.89%/0.03% [02] move - 0.69%/0.02% [02] mobBaseTick - 0.67%/0.02% [02] rest - 0.48%/0.02% [02] ai - 0.30%/0.01% [03] unspecified - 73.92%/0.01% [03] oldAi - 26.08%/0.00% [02] checkLight - 0.23%/0.01% [03] checkedPosition < toCheckCount - 61.73%/0.01% [03] getBrightness - 23.97%/0.00% [03] unspecified - 14.30%/0.00% [02] push - 0.19%/0.01% [02] headTurn - 0.09%/0.00% [02] rangeChecks - 0.04%/0.00% [02] jump - 0.03%/0.00% [02] looting - 0.03%/0.00% [02] getBrightness - 0.00%/0.00% [02] checkedPosition < toCheckCount - 0.00%/0.00% [01] playerTick - 4.75%/0.18% [02] unspecified - 49.16%/0.09% [02] travel - 26.77%/0.05% [03] move - 49.96%/0.02% [03] unspecified - 32.77%/0.02% [03] rest - 17.27%/0.01% [02] entityBaseTick - 11.83%/0.02% [02] mobBaseTick - 5.92%/0.01% [02] ai - 3.07%/0.01% [03] unspecified - 69.86%/0.00% [03] oldAi - 30.14%/0.00% [02] push - 1.81%/0.00% [02] headTurn - 0.83%/0.00% [02] rangeChecks - 0.25%/0.00% [02] looting - 0.19%/0.00% [02] jump - 0.18%/0.00% [01] unspecified - 1.42%/0.05% [01] keepAlive - 0.06%/0.00% [00] save - 0.11%/0.11% [00] players - 0.00%/0.00% [00] tallying - 0.00%/0.00% [00] tickables - 0.00%/0.00% [00] snooper - 0.00%/0.00% --- END PROFILE DUMP ---The pattern seems to be that at first, everything is fine, then more players log in and things get extremely laggy. The number of players doesn't seem unusual. Then, one of the players gets disconnected:
2012-10-28 17:07:37 [INFO] ##REDACTED## lost connection: disconnect.genericReasonBefore he got disconnected, the players all see extreme lag. This lag is detected by the debug profiler. Here is the profile output during the problem:
---- Minecraft Profiler Results ---- // I'm working as hard as I can! Time span: 32806 ms Tick span: 10 ticks // This is approximately 0.30 ticks per second. It should be 20 ticks per second --- BEGIN PROFILE DUMP --- [00] levels - 99.19%/99.19% [01] swim2 - 100.00%/100.00% [02] tick - 99.90%/99.90% [03] entities - 99.57%/99.57% [04] regular - 99.95%/99.95% [05] tick - 99.41%/99.41% [06] move - 94.70%/94.70% [06] unspecified - 2.83%/2.83% [06] entityBaseTick - 0.69%/0.69% [06] ai - 0.64%/0.64% [07] newAi - 92.19%/0.64% [08] goalSelector - 30.32%/0.20% [09] unspecified - 70.02%/0.14% [09] canUse - 13.30%/0.03% [09] pathfind - 5.94%/0.01% [09] goalStart - 5.72%/0.01% [10] ng - 54.68%/0.01% [11] pathfind - 95.03%/0.01% [11] unspecified - 4.97%/0.00% [10] unspecified - 41.68%/0.00% [10] nf - 2.62%/0.00% [10] mj - 0.46%/0.00% [10] mw - 0.24%/0.00% [10] nj - 0.21%/0.00% [10] mr - 0.06%/0.00% [10] nh - 0.03%/0.00% [09] goalTick - 4.30%/0.01% [10] unspecified - 77.40%/0.01% [10] pathfind - 21.18%/0.00% [10] canSee - 1.42%/0.00% [09] canContinue - 0.73%/0.00% [08] unspecified - 23.58%/0.15% [08] controls - 22.13%/0.14% [09] unspecified - 44.26%/0.06% [09] look - 32.48%/0.05% [09] move - 15.11%/0.02% [09] jump - 8.15%/0.01% [08] targetSelector - 14.21%/0.09% [09] unspecified - 87.43%/0.08% [09] goalStart - 5.32%/0.00% [10] unspecified - 98.53%/0.00% [10] nq - 1.47%/0.00% [09] goalTick - 4.26%/0.00% [09] canUse - 2.26%/0.00% [09] canSee - 0.49%/0.00% [09] canContinue - 0.24%/0.00% [10] canSee - 66.15%/0.00% [10] unspecified - 33.85%/0.00% [08] navigation - 4.43%/0.03% [08] checkDespawn - 2.41%/0.02% [08] sensing - 1.76%/0.01% [08] mob tick - 1.15%/0.01% [07] unspecified - 5.39%/0.04% [07] oldAi - 2.42%/0.02% [08] unspecified - 57.40%/0.01% [08] ai - 20.96%/0.00% [08] stroll - 17.22%/0.00% [09] pathfind - 88.98%/0.00% [09] unspecified - 11.02%/0.00% [08] followpath - 4.42%/0.00% [06] rest - 0.60%/0.60% [06] travel - 0.29%/0.29% [07] move - 44.20%/0.14% [07] unspecified - 33.92%/0.11% [07] rest - 21.88%/0.07% [06] chunkCheck - 0.11%/0.11% [06] mobBaseTick - 0.08%/0.08% [06] push - 0.03%/0.03% [06] headTurn - 0.01%/0.01% [06] looting - 0.01%/0.01% [06] jump - 0.01%/0.01% [06] rangeChecks - 0.00%/0.00% [06] checkLight - 0.00%/0.00% [07] checkedPosition < toCheckCount - 66.65%/0.00% [07] unspecified - 18.70%/0.00% [07] getBrightness - 14.65%/0.00% [06] getBrightness - 0.00%/0.00% [06] checkedPosition < toCheckCount - 0.00%/0.00% [05] unspecified - 0.56%/0.56% [05] remove - 0.03%/0.03% [04] remove - 0.03%/0.03% [04] tileEntities - 0.02%/0.02% [05] unspecified - 99.31%/0.02% [05] move - 0.43%/0.00% [05] checkLight - 0.18%/0.00% [06] getBrightness - 50.00%/0.00% [06] unspecified - 41.67%/0.00% [06] checkedPosition < toCheckCount - 8.33%/0.00% [05] rest - 0.09%/0.00% [04] unspecified - 0.00%/0.00% [04] pendingTileEntities - 0.00%/0.00% [04] global - 0.00%/0.00% [03] tickTiles - 0.27%/0.27% [04] unspecified - 59.94%/0.18% [04] tickTiles - 21.00%/0.06% [04] getChunk - 6.92%/0.02% [04] iceandsnow - 2.65%/0.01% [04] tickChunk - 2.26%/0.01% [05] unspecified - 77.10%/0.01% [05] recheckGaps - 22.90%/0.00% [06] unspecified - 57.47%/0.00% [06] getBrightness - 40.35%/0.00% [06] checkedPosition < toCheckCount - 2.19%/0.00% [04] thunder - 1.86%/0.01% [04] checkLight - 1.86%/0.01% [04] moodSound - 1.54%/0.00% [04] buildList - 1.43%/0.00% [04] playerCheckLight - 0.53%/0.00% [05] unspecified - 64.53%/0.00% [05] getBrightness - 33.97%/0.00% [05] checkedPosition < toCheckCount - 1.50%/0.00% [03] mobSpawner - 0.09%/0.09% [03] chunkSource - 0.04%/0.04% [03] tickPending - 0.02%/0.02% [04] checkLight - 81.84%/0.02% [05] checkedPosition < toCheckCount - 56.16%/0.01% [05] getBrightness - 43.17%/0.01% [05] unspecified - 0.67%/0.00% [04] unspecified - 18.16%/0.00% [03] village - 0.00%/0.00% [03] unspecified - 0.00%/0.00% [03] chunkMap - 0.00%/0.00% [03] checkLight - 0.00%/0.00% [04] getBrightness - 54.51%/0.00% [04] unspecified - 45.49%/0.00% [04] checkedPosition < toCheckCount - 0.00%/0.00% [02] tracker - 0.10%/0.10% [02] unspecified - 0.00%/0.00% [02] pools - 0.00%/0.00% [01] unspecified - 0.00%/0.00% [00] connection - 0.81%/0.81% [01] packetflow - 96.52%/0.88% [02] unspecified - 70.32%/0.62% [02] travel - 12.17%/0.11% [03] move - 42.38%/0.05% [03] unspecified - 36.40%/0.04% [03] rest - 21.22%/0.02% [02] move - 4.14%/0.04% [02] mobBaseTick - 3.18%/0.03% [02] entityBaseTick - 2.86%/0.03% [02] rest - 2.69%/0.02% [02] ai - 1.79%/0.02% [03] unspecified - 80.67%/0.01% [03] oldAi - 19.33%/0.00% [02] push - 1.78%/0.02% [02] headTurn - 0.43%/0.00% [02] jump - 0.21%/0.00% [02] looting - 0.19%/0.00% [02] rangeChecks - 0.15%/0.00% [02] chunkCheck - 0.09%/0.00% [01] playerTick - 2.37%/0.02% [02] travel - 45.90%/0.01% [03] move - 97.31%/0.01% [03] unspecified - 1.35%/0.00% [03] rest - 1.34%/0.00% [02] push - 27.21%/0.01% [02] unspecified - 25.94%/0.01% [02] entityBaseTick - 0.43%/0.00% [02] mobBaseTick - 0.22%/0.00% [02] headTurn - 0.13%/0.00% [02] ai - 0.11%/0.00% [03] unspecified - 71.43%/0.00% [03] oldAi - 28.57%/0.00% [02] rangeChecks - 0.03%/0.00% [02] looting - 0.02%/0.00% [02] jump - 0.02%/0.00% [01] unspecified - 1.09%/0.01% [01] keepAlive - 0.03%/0.00% [00] tallying - 0.00%/0.00% [00] players - 0.00%/0.00% [00] tickables - 0.00%/0.00% [00] snooper - 0.00%/0.00% --- END PROFILE DUMP ---And here is the debug profiler after the problem has gone away (when "disconnect.genericReason" is logged):
---- Minecraft Profiler Results ---- // You should add flames to things, it makes them go faster! Time span: 42520 ms Tick span: 850 ticks // This is approximately 19.99 ticks per second. It should be 20 ticks per second --- BEGIN PROFILE DUMP --- [00] levels - 96.13%/96.13% [01] swim2 - 99.97%/96.19% [02] tick - 98.41%/94.66% [03] entities - 80.71%/76.40% [04] regular - 98.19%/75.02% [05] tick - 95.22%/71.43% [06] ai - 34.74%/24.82% [07] newAi - 92.46%/22.95% [08] goalSelector - 40.15%/9.21% [09] unspecified - 53.27%/4.91% [09] pathfind - 22.34%/2.06% [09] goalTick - 11.74%/1.08% [10] pathfind - 78.81%/0.85% [10] unspecified - 20.44%/0.22% [10] canSee - 0.71%/0.01% [10] checkLight - 0.05%/0.00% [11] unspecified - 64.54%/0.00% [11] getBrightness - 33.72%/0.00% [11] checkedPosition < toCheckCount - 1.74%/0.00% [09] canUse - 9.29%/0.86% [09] goalStart - 2.93%/0.27% [10] unspecified - 60.07%/0.16% [10] ng - 34.71%/0.09% [11] pathfind - 95.32%/0.09% [11] unspecified - 4.68%/0.00% [10] nf - 3.96%/0.01% [10] mj - 0.32%/0.00% [10] mh - 0.26%/0.00% [10] mq - 0.20%/0.00% [10] nj - 0.13%/0.00% [10] mu - 0.12%/0.00% [10] mw - 0.09%/0.00% [10] mr - 0.08%/0.00% [10] mp - 0.06%/0.00% [10] nh - 0.00%/0.00% [09] canContinue - 0.42%/0.04% [08] unspecified - 24.22%/5.56% [08] targetSelector - 14.57%/3.34% [09] unspecified - 88.28%/2.95% [09] goalStart - 4.51%/0.15% [10] unspecified - 99.99%/0.15% [10] nr - 0.01%/0.00% [09] goalTick - 3.62%/0.12% [09] canUse - 2.41%/0.08% [09] canSee - 1.10%/0.04% [09] canContinue - 0.08%/0.00% [10] unspecified - 63.84%/0.00% [10] canSee - 36.16%/0.00% [08] controls - 14.49%/3.32% [09] unspecified - 76.36%/2.54% [09] look - 13.82%/0.46% [09] move - 6.14%/0.20% [09] jump - 3.67%/0.12% [08] checkDespawn - 2.71%/0.62% [08] sensing - 1.50%/0.34% [08] navigation - 1.45%/0.33% [08] mob tick - 0.91%/0.21% [07] unspecified - 5.50%/1.37% [07] oldAi - 2.03%/0.50% [08] unspecified - 70.06%/0.35% [08] ai - 21.68%/0.11% [08] stroll - 6.83%/0.03% [09] pathfind - 93.94%/0.03% [09] unspecified - 6.06%/0.00% [08] followpath - 1.43%/0.01% [06] unspecified - 29.88%/21.34% [06] travel - 17.70%/12.64% [07] move - 48.49%/6.13% [07] unspecified - 30.72%/3.88% [07] rest - 20.79%/2.63% [06] entityBaseTick - 8.05%/5.75% [06] mobBaseTick - 4.17%/2.98% [06] move - 1.65%/1.18% [06] push - 1.40%/1.00% [06] headTurn - 0.68%/0.49% [06] rest - 0.58%/0.41% [06] chunkCheck - 0.42%/0.30% [06] looting - 0.27%/0.19% [06] rangeChecks - 0.26%/0.18% [06] jump - 0.21%/0.15% [06] checkLight - 0.00%/0.00% [07] checkedPosition < toCheckCount - 38.51%/0.00% [07] unspecified - 32.82%/0.00% [07] getBrightness - 28.67%/0.00% [06] getBrightness - 0.00%/0.00% [06] checkedPosition < toCheckCount - 0.00%/0.00% [05] unspecified - 4.43%/3.32% [05] remove - 0.35%/0.26% [04] tileEntities - 1.62%/1.24% [05] unspecified - 95.89%/1.19% [05] checkLight - 3.99%/0.05% [06] checkedPosition < toCheckCount - 73.03%/0.04% [06] getBrightness - 24.50%/0.01% [06] unspecified - 2.47%/0.00% [05] move - 0.09%/0.00% [05] rest - 0.03%/0.00% [04] remove - 0.15%/0.11% [04] unspecified - 0.04%/0.03% [04] pendingTileEntities - 0.00%/0.00% [04] global - 0.00%/0.00% [03] tickTiles - 14.39%/13.62% [04] unspecified - 54.76%/7.46% [04] tickTiles - 17.63%/2.40% [05] unspecified - 99.13%/2.38% [05] checkLight - 0.85%/0.02% [06] unspecified - 58.19%/0.01% [06] getBrightness - 26.21%/0.01% [06] checkedPosition < toCheckCount - 15.60%/0.00% [05] getBrightness - 0.01%/0.00% [05] checkedPosition < toCheckCount - 0.01%/0.00% [04] moodSound - 7.81%/1.06% [04] getChunk - 6.90%/0.94% [04] tickChunk - 4.95%/0.67% [05] recheckGaps - 70.18%/0.47% [06] unspecified - 71.30%/0.34% [06] getBrightness - 25.78%/0.12% [06] checkedPosition < toCheckCount - 2.92%/0.01% [05] unspecified - 29.82%/0.20% [04] iceandsnow - 2.55%/0.35% [04] buildList - 1.86%/0.25% [04] thunder - 1.69%/0.23% [04] checkLight - 1.45%/0.20% [04] playerCheckLight - 0.39%/0.05% [05] unspecified - 65.56%/0.03% [05] getBrightness - 32.60%/0.02% [05] checkedPosition < toCheckCount - 1.85%/0.00% [03] mobSpawner - 4.16%/3.94% [03] tickPending - 0.43%/0.41% [04] checkLight - 67.16%/0.27% [05] checkedPosition < toCheckCount - 75.51%/0.21% [05] getBrightness - 23.30%/0.06% [05] unspecified - 1.19%/0.00% [04] unspecified - 32.84%/0.13% [03] village - 0.10%/0.09% [03] chunkSource - 0.09%/0.09% [04] unspecified - 99.37%/0.08% [04] checkLight - 0.63%/0.00% [05] unspecified - 55.85%/0.00% [05] getBrightness - 32.58%/0.00% [05] checkedPosition < toCheckCount - 11.58%/0.00% [03] unspecified - 0.06%/0.06% [03] checkLight - 0.04%/0.04% [04] checkedPosition < toCheckCount - 95.74%/0.04% [04] unspecified - 2.82%/0.00% [04] getBrightness - 1.44%/0.00% [03] chunkMap - 0.02%/0.02% [02] tracker - 1.55%/1.49% [02] unspecified - 0.03%/0.03% [02] pools - 0.00%/0.00% [02] timeSync - 0.00%/0.00% [01] unspecified - 0.03%/0.03% [00] connection - 3.75%/3.75% [01] packetflow - 93.76%/3.52% [02] unspecified - 93.67%/3.30% [02] travel - 2.70%/0.09% [03] move - 46.72%/0.04% [03] unspecified - 33.99%/0.03% [03] rest - 19.29%/0.02% [02] entityBaseTick - 0.89%/0.03% [02] move - 0.69%/0.02% [02] mobBaseTick - 0.67%/0.02% [02] rest - 0.48%/0.02% [02] ai - 0.30%/0.01% [03] unspecified - 73.92%/0.01% [03] oldAi - 26.08%/0.00% [02] checkLight - 0.23%/0.01% [03] checkedPosition < toCheckCount - 61.73%/0.01% [03] getBrightness - 23.97%/0.00% [03] unspecified - 14.30%/0.00% [02] push - 0.19%/0.01% [02] headTurn - 0.09%/0.00% [02] rangeChecks - 0.04%/0.00% [02] jump - 0.03%/0.00% [02] looting - 0.03%/0.00% [02] getBrightness - 0.00%/0.00% [02] checkedPosition < toCheckCount - 0.00%/0.00% [01] playerTick - 4.75%/0.18% [02] unspecified - 49.16%/0.09% [02] travel - 26.77%/0.05% [03] move - 49.96%/0.02% [03] unspecified - 32.77%/0.02% [03] rest - 17.27%/0.01% [02] entityBaseTick - 11.83%/0.02% [02] mobBaseTick - 5.92%/0.01% [02] ai - 3.07%/0.01% [03] unspecified - 69.86%/0.00% [03] oldAi - 30.14%/0.00% [02] push - 1.81%/0.00% [02] headTurn - 0.83%/0.00% [02] rangeChecks - 0.25%/0.00% [02] looting - 0.19%/0.00% [02] jump - 0.18%/0.00% [01] unspecified - 1.42%/0.05% [01] keepAlive - 0.06%/0.00% [00] save - 0.11%/0.11% [00] players - 0.00%/0.00% [00] tallying - 0.00%/0.00% [00] tickables - 0.00%/0.00% [00] snooper - 0.00%/0.00% --- END PROFILE DUMP ---
NPE: Tried to go boating with a boat in a boat while in a boat
Although it seems like the problem is compounded by minute network conditions, could it be related to the new /setidletimeout functionality, even when it is set to zero?
The reason I suspect this is because a) every player is disconnected at the same moment, perhaps the same tick and b) they do not disconnect with an error flag detected on the server, i.e., they disconnect "gracefully" as if the player logged out (though the player sees an error).
To further explain what I mean, if the player is disconnected "ungracefully," the server usually reports "disconnect.genericReason." But with this situation, instead the server reports "Disconnected" exactly the same way it would report a player just logging out.
So it seems like perhaps the server is erroneously instructing the clients to disconnect. Maybe the server is trying to evaluate if the players are idle, getting into a false positive situation.
By the way, at its worse, I've observed it disconnect every player almost exactly one minute apart for several minutes. It seems too regular, so I suspect something like the idle timeout going haywire, even when it's set to zero. Maybe part of its preparation phase is still invoking no matter what it's set to.
I have a script that runs when people log in. It attempts to clear player inventory of contraband blocks that users might somehow obtain.
Usually, it runs without error, but I'm seeing intermittent errors in the console like the following, that are probably due to a race condition:
[19:57:34] RCON Client #744/ERROR: Couldn't process command: 'clear @a[m=0] minecraft:sponge'
java.util.ConcurrentModificationException
at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:819) ~[?:1.7.0_07]
at java.util.ArrayList$Itr.next(ArrayList.java:791) ~[?:1.7.0_07]
at aht.a(SourceFile:2208) ~[minecraft_server.jar:?]
at ab.b(SourceFile:283) ~[minecraft_server.jar:?]
at x.a(SourceFile:46) [minecraft_server.jar:?]
at net.minecraft.server.MinecraftServer.g(SourceFile:709) [minecraft_server.jar:?]
at ov.run(SourceFile:80) [minecraft_server.jar:?]
at java.lang.Thread.run(Thread.java:722) [?:1.7.0_07]I have a script that runs when people log in. It attempts to clear player inventory of contraband blocks that users might somehow obtain.
Usually, it runs without error, but I'm seeing intermittent errors in the console like the following, that are probably due to a race condition:
[19:57:34] [RCON Client #744/ERROR]: Couldn't process command: 'clear @a[m=0] minecraft:sponge' java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:819) ~[?:1.7.0_07] at java.util.ArrayList$Itr.next(ArrayList.java:791) ~[?:1.7.0_07] at aht.a(SourceFile:2208) ~[minecraft_server.jar:?] at ab.b(SourceFile:283) ~[minecraft_server.jar:?] at x.a(SourceFile:46) [minecraft_server.jar:?] at net.minecraft.server.MinecraftServer.g(SourceFile:709) [minecraft_server.jar:?] at ov.run(SourceFile:80) [minecraft_server.jar:?] at java.lang.Thread.run(Thread.java:722) [?:1.7.0_07]
From rcon, this command also recreates a book with missing textures:
/give $player minecraft:written_book 1 1 {author:Carl,title:\"Rules\",pages:[\"1. No abusive chat 2. No annoying chat 3. Do not intentionally cause lag or crash the server nor threaten to do so.\"],ench:[{id:6,lvl:1},{id:5,lvl:1},{id:61,lvl:1},{id:8,lvl:3}]}This command is too long for the in-game chat window, so to see the missing textures, here's a smaller command:
/give @a minecraft:written_book 1 1 {author:Carl,ench:[{id:6,lvl:1}]}The enchantments are meant to be a joke. Removing the enchantments is a workaround for the missing textures. But it seems like a bug that Minecraft would accept the command and display broken textures. Either the texture should be fixed or the command should be rejected.
SMP: Failed to save chunk
com.google.common.collect.Lists.newArrayList.pdf
Set max-tick-time in server.properties to a value higher than 60000 or to -1
https://minecraft.fandom.com/wiki/Server.properties#max-tick-time
The server crashes randomly. Most recent crash report attached.
Description: Watching Server java.lang.Error at java.util.ArrayList.indexOf(ArrayList.java:298) at java.util.ArrayList.contains(ArrayList.java:281) at java.util.ArrayList.batchRemove(ArrayList.java:700) at java.util.ArrayList.removeAll(ArrayList.java:671) at aqa.i(SourceFile:1339) at ql.i(SourceFile:470) at net.minecraft.server.MinecraftServer.y(SourceFile:605) at ph.y(SourceFile:303) at net.minecraft.server.MinecraftServer.x(SourceFile:529) at net.minecraft.server.MinecraftServer.run(SourceFile:445) at java.lang.Thread.run(Thread.java:744)
Update: This crash appears to be caused by a new “feature“ called the Server Watchdog. This is a thread that kills the server when there is too much lag. Sometimes, but by no means always, this is logged accordingly:
2014-07-26 21:06:11 [Server Watchdog/FATAL]: A single server tick took 35.28 seconds (should be max 0.05) 2014-07-26 21:06:11 [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown. 2014-07-26 21:06:13 [Server Watchdog/ERROR]: This crash report has been saved to: /opt/wurstmineberg/server/./crash-reports/crash-2014-07-26_23.06.12-server.txt
Thanks Anthony Martin for finding this.
@Anthony Martin: That's something different.
java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification
vs.
java.util.ConcurrentModificationException
at java.util.TreeMap$PrivateEntryIterator.nextEntry
ConcurrentModificationException means that one thread cannot get a lock on a resource because some other thread has it already (If I do interpret that correctly), but the causes for both exceptions are different.
@Anthony Martin That's MC-2545
@Anthony Martin: Please stop constantly editing your post. 13 people are receiving an email each time you do. The preview feature exists for a reason.
@Anthony Martin: Please update the Affected Versions, you are the author of this ticket...
The original reason Mojang stated for removing stuck arrows was due to enlarged mobs having comically enlarged arrows stuck in them. Rather than fix it or disabling stuck arrows only for enlarged mobs, Mojang opted to just disable it completely.
I can imaging that the code required to fix it right (so that even enlarged mobs have the correct arrow size) is rather complicated. Personally, I'd be happy if just PVP stuck arrows worked. That's the most fun situation for them.
It seems like there's a bunch of these particular bugs being posted. Are they all related? What changed to cause this? My guess is some kind of performance enhancement went a little too far.
For chickens, try seeds.
Thank you, Matthew, but I am not able to initiate the condition. I don't know what third party client these folks are using to initiate their attack. All I know is, it happens often enough for me to suspect it is indeed intentional because they threaten to make the server go unresponsive, and it usually does after that.
They almost never engage in conversation. They just get woody when they down a server, then they move on to their next conquest.
Since 2012-07-18, there have been six separate attacks like this on my server.
It appears that RCON commands do indeed have something to do with it, but only when the server has been up for quite a while.
So it turns out, the player that kept getting disconnected for "genericReason" had recently broken an a great many double chests full of items (accidentally). I am not sure how many chests were involve, but it was an entire storage room. When an op (in creative mode) teleported to the player's location, all of the items were absorbed by the op, thereby solving the issue.
But it would be nice if the Minecraft server could be more descriptive as to the root cause of issues like this. Maybe a warning like:
In another incident, a player claimed:
Shortly after that, the server went unresponsive. Apparently his third party client could overpower the server this way. I checked the region files, and region r.5953.83.mca was never generated (thankfully).
It appears that this is caused by chunks not being read properly by the server. I saw console messages like:
So it appears to me that this problem will eventually work itself out, and there is no bug, per se.
I have not seen this particular behavior in later versions.
I have seen a great many ConcurrentModificationException spamming the console in 1.4.5 while the server is being DDoSed. Likely, this is a side effect of the garbage collector being overworked. This is one of those "tricky-to-re-produce" situations. I can't exactly ask someone to DDoS my server so I can test it.
Your call.
This is still very much a concern in 1.4.5. Lag generated by these players is very disruptive. I believe the players who generate these packets are using a combination of both fly and speed hacks. Many players can "tune" their clients to avoid getting kicked. But others intentionally try to generate packets that the server can't handle specifically to create a denial of service attack.
Confirmed, still an issue in 1.4.6.
Confirmed, this problem is still present in the latest snapeshot: 13w01b.
This behavior is very useful. If it is unintended, it would be nice if this behavior was officially added in some other mechanism.
I've seen this problem come an go on my server. The problem seems to be linked to file io. When the disk is doing heavy reads, the Minecraft Server does a lot of disconnects. The heavy reads don't have to be part of the Minecraft Server process in order for this to take place. It just seems like a hardware limitation on certain platforms.
Thanks for going to so much trouble to try to recreate the issue, Martin.
Unfortunately, the problem is indeed still present in 13w04a. I tested the same rail/hopper configuration, even broke the comparators and placed them back, just in case that made any difference. It did not.
Lag was practically eliminated from this test because the SMP server being tested was accessed directly by the op player on the LAN, no other players were on.
I did manage to simplify the steps to recreate the problem, and even confirmed a new clue: the problem may be directional. Or direction affects it in some way.
I made four pistons activated by button/comparator. Only one of them is affected by this defect right away. The one in my example that has problems is the one in the front left of the picture:
http://imgur.com/GxfZmU2
This screenshot was taken while looking North. So the comparator being affected is the one pointing East. But this behavior seems random. I have another comparator affected by this defect in a completely different circuit pointing South ( the piston is triggered by a block powered from the top).
Just logging out and logging back in triggers the bug, in this case. Subsequent tests did not reveal the same issue each time, so this is highly intermittent.
Also confirmed that block updates do indeed clear the problem temporarily.
This cannot be tested in the snapshots since modded clients are a rare occurrence. If they ever do occur, they rarely generate the kind of packets to cause this behavior.
I am still seeing this on my server with 13w06a. Several players experience this in one degree or another, but not all.
2013-02-10 01:12:21 [INFO] ###REDACTED###[/###REDACTED###:55737] logged in with entity id 5916253 at (-1505480.3407349708, 63.0, 1496955.5039275563) 2013-02-10 01:12:29 [INFO] ###REDACTED### lost connection: disconnect.overflow 2013-02-10 01:12:35 [INFO] ###REDACTED###[/###REDACTED###:55748] logged in with entity id 5918921 at (-1505480.3407349708, 63.0, 1496955.5039275563) java.net.SocketException: Socket closed at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116) at java.net.SocketOutputStream.write(SocketOutputStream.java:153) at aru.write(Unknown Source) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at java.io.DataOutputStream.flush(DataOutputStream.java:123) at cj.run(SourceFile:120) 2013-02-10 01:12:42 [INFO] ###REDACTED### lost connection: disconnect.overflow 2013-02-10 01:12:55 [INFO] ###REDACTED###[/###REDACTED###:55756] logged in with entity id 5922574 at (-1505480.3407349708, 63.48071087633169, 1496955.5039275563)Nothing happens shortly before, at least nothing related to these lost connections. Sometimes they are accompanied by "Took too long to log in" but not always.
For example, here is some of the log file from just now (#REDACTED-IP## is alway the same IP in this short example):
In the above example, ##REDACTED-IP## first appeared on the 19th from a user with an outdated client. Since that time, this one user has generated 63 log entries.
As you can see from the example on the 21t, the log has regular user activity, peppered with mostly unrelated lost connections from random IP addresses. For the 20th, there were about 800 unique IP addresses recorded as lost connections. But in that timeframe, those 800 IP addresses generated 5000+ repeating lost connection messages.
I've looked up a few of the IP addresses and found that many (not all) belong to past users, like the example ##REDACTED-IP##. My current theory is that many of these lost connections are coming from Minecraft clients just looking to see if my server is up (queries to see and what version, motd, etc.). Basically, they are clients pinging my server just because my server is in their multiplayer list. They tried to connect once or twice, then they moved on but never deleted my server from the list.
Many people add my server to their server list who cannot log in because they don't know how to install the snapshot, and they never bother to delete my server. So they have 1.4.7 and they ping my server but never log in. I think the server is logging the pings to some extent as lost connections.
I don't care if they leave my server in their list, that's not a bug. I don't really care if they ping it, that's not a bug either. If pings present a problem in the future, it's my problem, not a problem in code. The bug here is: I just think the lost connections messages are too excessive.
This may or may not be related, but the console reported this around the same time as a lost connection (though it doesn't happen every time and did not get written in the log):
java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:150) at java.net.SocketInputStream.read(SocketInputStream.java:121) at java.net.SocketInputStream.read(SocketInputStream.java:203) at java.io.FilterInputStream.read(FilterInputStream.java:83) at eg.a(SourceFile:184) at ch.i(SourceFile:250) at ch.c(SourceFile:16) at ci.run(SourceFile:94)Behavior still present in 13w09a.
Yes, in 1.5 as well as the snapshot (13w11a), the server seems even more susceptible to this problem.
Not sure if it's related, but right after someone got kicked for flying, the server wouldn't take a /stop command. After ^C, it finally stopped, then spit out a bunch of ConcurrentModification exceptions on the console. I couldn't capture them in time to include them here. They were not logged, must displayed on the console.
Whispers do not appear to echo the color markup. It'd be nice if the log did this for the user names well.
I'm seeing boats consistently cause null pointer exceptions on all clients in SMP.
On 13w16a, two finger right-click works for me on my MBP. But what doesn't work is CTRL-click right-click. Both worked fine in previous versions.
Confirmed on SMP for all players that try it. Unable to recreate in single player.
Whatever the correct key combination is, half-a-stack is very difficult in the snapshots on my MacBook Pro (MBP).
The "place-one-item-from-stack" equally difficult.
Previous to the 1.6 snapshots, half-a-stack was achieved using Ctrl-Click on my MBP. This is because the MBP trackpad has no physical "second mouse button." Thus, Ctrl-Click is Right-Click on the MBP. But Ctrl-Click is completely ignored in the snapshots.
It is possible to use "two-finger-click" on MBP to achieve right-click. But I find this cumbersome for game-play.
Remapping "Use Item" re-enables most game functions. But "half-a-stack" is not enabled by remapping "Use Item."
Chat messages are now not being logged at all in snapshot 12w21a. All chat messages are being recorded to server.log as:
Apparently this has been fixed, though:
MC-16144I also see this, even in snapshot 13w25a. I think it's caused by clients pinging the server to get detail like the motd and connection quality.
I am a "passonate" Mac user and I have adapted my gameplay around using X to place blocks and use items. I have remapped CTRL to bring up the command console (as if I pressed /) to retrain myself not to use CTRL anymore.
I can still split stacks with two finger clicks. I can still place one item from a stack with two finger clicks.
I don't like this, but I am able to play Minecraft at about the same proficiency as I did before the change to LWJGL. I don't think the average player impacted by this will find it very convenient and likely they will stop playing all together. They will probably be even more rude than the people in this thread. It's unfortunate, but true.
I understand Mojang's position that it's not really their bug. I understand the user's frustration at Mojang's assertion that it's not really their bug.
Maybe what Mojang should do is either officially drop Mac Trackpad support or fork LWJGL to fully support it. LWJGL has taken the Mac Trackpad hostage and if Mojang is ok with that, they should make it official.
I have not observed this situation for quite some time. I believe it was finally addressed in 1.6.
This problem has been observed in 1.6.2 when third party clients began to attack the server.
Yes, there are many events that are still no longer being logged in 1.6.2.
Such as /tell (only server /tell events are logged). All failed commands are still no longer being logged. Failed commands are still useful for external scripting.
I have the same issue. This exception occurs several times a day. Yesterday, it happened 7 times and the server was down for several hours. I implemented an auto-restart shell script to minimize the impact.
On one occasion, the exception occurred with no one logged for the entire run session. Here's the log:
[12:22:19] [Server thread/INFO]: Starting minecraft server version 13w41b [12:22:19] [Server thread/INFO]: Loading properties [12:22:19] [Server thread/INFO]: Default game type: SURVIVAL [12:22:19] [Server thread/INFO]: Generating keypair [12:22:20] [Server thread/INFO]: Starting Minecraft server on 192.168.0.3:25565 [12:22:21] [Server thread/INFO]: Preparing level "swim2" [12:22:21] [Server thread/INFO]: Preparing start region for level 0 [12:22:24] [Server thread/INFO]: Preparing spawn area: 0% [12:22:25] [Server thread/INFO]: Done (4.690s)! For help, type "help" or "?" [12:22:25] [Server thread/INFO]: Starting GS4 status listener [12:22:25] [Server thread/INFO]: Starting remote control listener [12:22:25] [Query Listener #1/INFO]: Query running on 192.168.0.3:25565 [12:22:25] [RCON Listener #2/INFO]: RCON running on 192.168.0.3:25575 [12:22:32] [Server thread/ERROR]: Encountered an unexpected exception java.lang.NullPointerException at ml.c(SourceFile:130) ~[minecraft_server.jar:?] at net.minecraft.server.MinecraftServer.u(SourceFile:529) ~[minecraft_server.jar:?] at le.u(SourceFile:259) ~[minecraft_server.jar:?] at net.minecraft.server.MinecraftServer.t(SourceFile:441) ~[minecraft_server.jar:?] at net.minecraft.server.MinecraftServer.run(SourceFile:358) [minecraft_server.jar:?] at kt.run(SourceFile:617) [minecraft_server.jar:?] [12:22:32] [Server thread/ERROR]: This crash report has been saved to: /Users/steve/Minecraft/Swim2/./crash-reports/crash-2013-10-12_12.22.32-server.txtThe related crash log:
---- Minecraft Crash Report ---- // On the bright side, I bought you a teddy bear! Time: 10/12/13 12:22 PM Description: Exception in server tick loop java.lang.NullPointerException: Exception in server tick loop at ml.c(SourceFile:130) at net.minecraft.server.MinecraftServer.u(SourceFile:529) at le.u(SourceFile:259) at net.minecraft.server.MinecraftServer.t(SourceFile:441) at net.minecraft.server.MinecraftServer.run(SourceFile:358) at kt.run(SourceFile:617) A detailed walkthrough of the error, its code path and all known details is as follows: --------------------------------------------------------------------------------------- -- System Details -- Details: Minecraft Version: 13w41b Operating System: Mac OS X (x86_64) version 10.8.4 Java Version: 1.7.0_07, Oracle Corporation Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation Memory: 2387973664 bytes (2277 MB) / 3436183552 bytes (3277 MB) up to 4294967296 bytes (4096 MB) JVM Flags: 17 total; -Xmx4G -Xms3G -Xloggc:server_gc.log -XX:+UseG1GC -XX:+DisableExplicitGC -XX:MaxGCPauseMillis=1000 -XX:+UseFastAccessorMethods -XX:+UseStringCache -XX:+OptimizeStringConcat -XX:+UseCompressedOops -XX:MaxInlineSize=270 -XX:FreqInlineSize=5000 -XX:+UseBiasedLocking -XX:+UseNUMA -Xnoclassgc -XX:OnError=/Users/steve/Minecraft/Swim2/scripts/jvm_on_error.sh -XX:OnOutOfMemoryError=/Users/steve/Minecraft/Swim2/scripts/jvm_on_out_of_memory.sh AABB Pool Size: 3957 (221592 bytes; 0 MB) allocated, 3811 (213416 bytes; 0 MB) used IntCache: cache: 0, tcache: 0, allocated: 12, tallocated: 94 Profiler Position: N/A (disabled) Vec3 Pool Size: 4326 (242256 bytes; 0 MB) allocated, 4190 (234640 bytes; 0 MB) used Player Count: 0 / 20; [] Is Modded: Unknown (can't tell) Type: Dedicated Server (map_server.txt)Observed all the way through latest snapshot (13w42b). I'd be nice if there was a flag in server.properties to optionally reset chunks that have this problem.
Observed all the way through latest snapshot (13w42b). I'd be nice if there was a flag in server.properties to optionally reset chunks that have this problem.
It has gotten progressively worse with each version.
With regards to the above comment, the server should use -XX:+UseG1GC and not -XX:MaxGCPauseMillis=200. That was what fixed our situation.
What is boils down to is it appears that Java's default garbage collector causes too much of a delay on the server for most clients, or at least in my situation. Setting -XX+UseG1GC as a Java option helps avoid this situation. E.g.:
In addition to this option, I attempted to tune it further by adding the -XX:MaxGCPauseMillis=200 option. Supposedly, 200 is the default and I was going to tweak it later. After adding this extra option, the clients started getting ReadTimeoutException. So I removed both options. They continued to get the exception. So I didn't realize until later, in my configuration, I needed G1GC but not the second pause directive.
After enabling only G1GC, everything was much smoother for the clients.
Keep in mind, over time G1GC will experience heap performance issues. On a busy server, it may require periodic restarts. But the G1GC garbage collector can help avoid the "stop the world" situations that netty clients appear to be sensitive to.
Observed in 1.7.2, general release. The map was reset for this release, so everything is completely new, yet we still see these problems on occasion. Example of messages spammed to log:
Also observed in the same log:
Although it seems like the problem is compounded by minute network conditions, could it be related to the new /setidletimeout functionality, even when it is set to zero?
The reason I suspect this is because a) every player is disconnected at the same moment, perhaps the same tick and b) they do not disconnect with an error flag detected on the server, i.e., they disconnect "gracefully" as if the player logged out (though the player sees an error).
To further explain what I mean, if the player is disconnected "ungracefully," the server usually reports "disconnect.genericReason." But with this situation, instead the server reports "Disconnected" exactly the same way it would report a player just logging out.
So it seems like perhaps the server is erroneously instructing the clients to disconnect. Maybe the server is trying to evaluate if the players are idle, getting into a false positive situation.
By the way, at its worse, I've observed it disconnect every player almost exactly one minute apart for several minutes. It seems too regular, so I suspect something like the idle timeout going haywire, even when it's set to zero. Maybe part of its preparation phase is still invoking no matter what it's set to.
Here's the situation I'm seeing:
1. Everything starts off fine. The server has a 20 player limit, it reaches 20 by mid-day.
2. Nothing special is recorded in the log prior to the event.
3. Something happens. <--
4. After that, all users are disconnected at the same time without an error on the server side. They all just log out. User report seeing the Netty timeout error on their end, but the server log says nothing special except that they all logged out together, in the same second.
5. This happens every minute for several minutes.
6. The problem self-corrects after a while, everything is fine again.
7. Repeat.
I looked at the Netty documentation, and there seems to be a 30 second timeout. Maybe this is too short.
http://netty.io/4.0/api/io/netty/handler/timeout/IdleStateHandler.html
Is it my network conditions? Perhaps. Prior to 1.7, we would go through poor network conditions without these constant mass disconnect. Instead, players all had "a bunch of lag" but they could usually still chat.
Sorry I posted that twice. Anyway, I did the opposite, went from 30 (when I had the issue) back to 0 and it also seemed to help, then it happened again 24 hours later. So I think it might be a coincidence. I think network conditions are the major contributor, and netty timeouts are just more sensitive to network conditions than before.
Although server /tell is now being logged, there is still no way for players to privately respond to the console. Prior to 1.3.1, all failed command by the user were logged so two-way private messaging to the console was possible. This is still impossible as of 1.7.2.
I have seen /save-all cause 20+ second pauses, which, combined with existing pauses from a busy server, is enough to cause clients (netty) to timeout.
Observed in 1.7.2.
Even when /save-all does not cause long pauses, I often see the following exception:
java.util.ConcurrentModificationException at java.util.HashMap$HashIterator.nextEntry(HashMap.java:894) at java.util.HashMap$KeyIterator.next(HashMap.java:928) at dg.a(SourceFile:21) at dg.a(SourceFile:314) at dg.a(SourceFile:23) at dg.a(SourceFile:314) at dg.a(SourceFile:23) at dr.a(SourceFile:94) at dr.a(SourceFile:84) at dr.a(SourceFile:23) at ayc.a(SourceFile:93) at ayc.a(SourceFile:75) at mj.a(SourceFile:616) at mj.a(SourceFile:601) at bg.b(SourceFile:36) at z.a(SourceFile:58) at net.minecraft.server.MinecraftServer.g(SourceFile:674) at nn.run(SourceFile:84) at java.lang.Thread.run(Thread.java:722)As well as:
java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:819) at java.util.ArrayList$Itr.next(ArrayList.java:791) at mj.a(SourceFile:455) at aow.a(SourceFile:225) at aow.a(SourceFile:96) at mi.b(SourceFile:146) at mi.a(SourceFile:175) at mj.a(SourceFile:604) at bg.b(SourceFile:36) at z.a(SourceFile:58) at net.minecraft.server.MinecraftServer.g(SourceFile:674) at nn.run(SourceFile:84) at java.lang.Thread.run(Thread.java:722) java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at mj.a(SourceFile:455) at aow.a(SourceFile:225) at aow.a(SourceFile:96) at mi.b(SourceFile:146) at mi.a(SourceFile:175) at mj.a(SourceFile:604) at bg.b(SourceFile:36) at z.a(SourceFile:58) at net.minecraft.server.MinecraftServer.g(SourceFile:674) at nn.run(SourceFile:84) at java.lang.Thread.run(Thread.java:722)The stack traces happen most often when RCON is used to issue the /save-all command. But I suspect they are hidden and happen in the background when /save-all is issued by OP from the Minecraft client.
Loading the region in MCEdit (0.1.8 build 665) and opening World Info, then clicking Repair Regions fixed the problem and now I don't have the error messages.
Guys, it's a save spike. I've all but verified this. If you switch off auto-save (/save-off) then periodically use /save-all (cron job every 15 minutes (with a script that does /save-on, sleep, /save-all, sleep, /save-off)), then disconnects only happen then, and not every time. If my case, I've seen /save-all take as long as 60 seconds, which is plenty of time for the client to time out.
It's NOT safe to use /save-off. Just do it for troubleshooting ONLY. You will lose data if you use /save-off without periodically using /save-all. You will lose data if you stop your server without first doing /save-all. And I've been informed that /save-all doesn't work unless you first use /save-on in a different tick. If you wait too long to use /save-all, you will get an out of memory exception and lose data. *So use with caution.*
Also, see: https://mojang.atlassian.net/browse/MC-33086
If corrupted .dat files are related to the timeouts, I see the following message on occasion at startup on the console (not logged):
s: Loading NBT data at dg.a(SourceFile:335) at dg.a(SourceFile:37) at dg.a(SourceFile:329) at dg.a(SourceFile:37) at dr.a(SourceFile:107) at dr.a(SourceFile:78) at dr.a(SourceFile:14) at ayc.a(SourceFile:45) at afn.a(SourceFile:2484) at atp.a(SourceFile:241) at atp.a(SourceFile:26) at apj.a(SourceFile:30) at aph.e(SourceFile:448) at mi.f(SourceFile:123) at mi.c(SourceFile:72) at mi.d(SourceFile:108) at afn.e(SourceFile:311) at afn.a(SourceFile:249) at ul.f(SourceFile:275) at ul.m(SourceFile:261) at ul.a(SourceFile:61) at uo.a(SourceFile:48) at mj.b(SourceFile:143) at net.minecraft.server.MinecraftServer.u(SourceFile:503) at lj.u(SourceFile:265) at net.minecraft.server.MinecraftServer.t(SourceFile:441) at net.minecraft.server.MinecraftServer.run(SourceFile:358) at ky.run(SourceFile:617) Caused by: java.io.EOFException at java.io.DataInputStream.readByte(DataInputStream.java:267) at dg.a(SourceFile:318) at dg.a(SourceFile:35) at dg.a(SourceFile:329) ... 27 moreI think restarting has more of a benefit than deleting dat files. Since you have to restart to properly delete dat files, it seems like you're doing something beneficial for performance, but in reality, the restart was the thing that actually helped, in the short term. Long running servers have more Full GC cycles and restarting eliminates that for a while. Full GCs contribute to the problem. The more Full GCs there are, the more pauses. Long pauses cause clients to time out. Full GC combined with periodic, random save spikes can cause random disconnects.
The root cause is not specifically saves. The root cause is not Full GCs. Combine the two, however, and can you have pauses greater than 20 seconds, on occasion, which is too long for the clients.
See: https://mojang.atlassian.net/browse/MC-33086
I understand, but note, I didn't say deleting .dat files was excluded from being a solution, I just recognize that restarts are involved, and restarts often help without deletion. I don't have to personally test it to see that some servers do not report benefit from deleting .dat files.
I may be incorrect about the .dat contribution to the problem, or lack thereof, but I'm basing my assumption on the fact that some people have reported that it made no difference. I have verified that restarts often do make a difference, sometimes multiple restarts in succession. Is it beneficial because those particular .dat files don't get loaded after restarts because the player decides they've had enough and do not to reconnect for a while? Perhaps.
But just deleting data is not currently something I'm willing to troubleshoot on my 25 GB server with 16 MB of .dat files from 2600+ players. It would be too much of a disruption and a huge amount of confusion for the players. If I just deleted it all and restored it later, players won't put the server through its paces. They'll stay off the server until the files are all restored from backup. So there's little point.
At the moment, players on my server are only interrupted at most, 4 times an hour from disconnect waves because I concentrate all the saves to once every 15 minutes. Sometimes we go hours without disconnects. Sometimes it's every 15 minutes. But at least it's not completely random or once-per-minute anymore.
I will say this, supporting the idea .dat files have problems: last week, three users found themselves at spawn after an early morning automated restart. It makes me wonder if their .dat files were in fact so corrupt, they couldn't be saved at all. I reviewed the logs, and there were no exceptions or errors of any kind. There was also no indication that there were greater or fewer disconnect waves prior to this or after. In other words, it didn't seem to matter. Maybe that's because there are hundreds of users with these corrupt files, and that three got deleted didn't make any difference.
Also OS 10.8. It started with the lwjgl update of Minecraft 1.6.2.
Still observed in 1.7.2 SMP boats. Big problem for our ocean spawn server.
Problem observed in 1.7.2.
Ok, I've broken down and decided to investigate if I should delete my dat files because Mojang has apparently abandoned us. I know, that's hyperbole, but it sure feels that way.
I have a 11MB mineshaft.dat file. It's been growing for weeks. The /save-all is taking longer and longer every day. Yesterday, the /save-all took 45 seconds. Today, it's up to 50 seconds. I've seen it spike up to 80 seconds.
So I'm going to bite the bullet and delete the mineshaft.dat file. I feel very strongly that this is not something I should have to do. I don't know what the file is for. I have a feeling it isn't important since there are no specific mobs that spawn in mineshafts. But in the future, if mineshaft mobs ever come along, these old mineshafts won't have them.
With no patch on the horizon, it's the only option left. I hope the save spikes at least subside.
It worked.
This is related. In my case, save spikes are indeed caused by minecraft.dat. Client timeouts can occur if a) the server is already behind (Can't keep up!) and b) the save takes long enough. The combination can cause the client to think the server is no longer responding. It is my understanding that the timeout threshold is 20 seconds. So if it takes 10 seconds to do a /save-all (random), and your server is 10 seconds behind (or any combination), you have a high chance of timeouts.
See: https://mojang.atlassian.net/browse/MC-33134
This is related. In my case, save spikes are indeed caused by minecraft.dat. Client timeouts can occur if a) the server is already behind (Can't keep up!) and b) the save takes long enough. The combination can cause the client to think the server is no longer responding. It is my understanding that the timeout threshold is 20 seconds. So if it takes 10 seconds to do a /save-all (random), and your server is 10 seconds behind, you have a high chance of timeouts.
See: https://mojang.atlassian.net/browse/MC-33134
The 1.7 versions of Minecraft have resulted in the most baby sitting I've ever encountered since 1.8 Beta, before I realized I had to delete the Mineshaft.dat file with every restart. After it got to 11MB, it grows to 3MB in less than 24 hours. Not even the worst snapshot needed this much attention.
Before I determined the issue, I tuned the garbage collector, installed several watchdog scripts, did hourly restarts, did metrics based restarts. I troubleshot everything I could think of. Then, one of my regular players suggested deleting a random file. I couldn't believe this was the solution. But it was. The difference is night and day.
I believe any active world over 8GB will be crippled unless they have the resources to just overpower the problem. All I know is, I went from having to restart 15 times a day, down to only one or two restarts required.
MC-33134appears related, and I mentioned it has a stack trace. My gut feeling, looking at the stack trace is that there is some kind of race condition. MC-34947, which is currently ranked as #47 in popularity, is also related, but the comments are all over the place. Obviously, the netty timeout is attracting every kind of connectivity failure, not just ones related to this. But I believe the most common bug-related reason people see a client timeout is related to this .dat growth problem.Ok, hyperbole has no place in a publicly facing bug tracking system with thousands of reports. But I think this might be a near-universal problem.
Well, thanks for looking at it.
Maybe @a makes perfect sense, but it allows players to spam everyone with no log entries. Admin already has a hard time finding people who spam using clever methods. The @a selector just makes it even more annoying.
Also, things like @p[name=!myname] is very bad. Using certain /tell selectors enable players on a survival server to slowly pinpoint the position of other players. All selectors work, including x/y/z/radius. I don't think Any @ selectors should work for non-op. It destroys survival.
Joel Hansen, how big is your data/Mineshaft.dat file?
No, I'm just wondering about your data/Mineshaft.dat file, actually.
Joel Hansen, thanks. I was curious because your symptoms seemed similar to mine, but in my case, my Minecraft.dat literally grows by multiple megabytes each day, which results in the "behind" logging messages getting higher and higher.
Then again, the total size of my SMP world is 36GB, so maybe this is perfectly normal. Mojang hasn't said one way or the other.
I also observed this in 1.7.3 pre-release.
Just last night:
Still have this issue in 1.7.4. When the game saves the world, either automatically by the game, or externally by cron, there is a save spike that continues to increase over the course of time until it is great enough to cause the clients to disconnect.
I have a start script that deletes the Mineshaft.dat file. Every time it deletes the file, the file has grown to about 1MB. It only takes 30 minutes for it to grow to that size. When the file is small, /save-all is always fast. But when it grows to about 512KB to 1MB, the /save-all can take up to 40 seconds.
There is a direct correlation to save spikes and the size of Mineshaft.dat, at least on my server.
Total world size is currently 43GB. The world was restarted when 1.7.0 was released, so there are no legacy chunks from prior versions. And, of course, no mods.
Still having this issue, but deleting the Mineshaft.dat isn't helping as much as it used to because other .dat files are now getting too large as well. Specifically, the Fortress.dat file. It's now 7.5MB. Before, when the Mineshaft.dat file was the issue, it was 11MB. Deleting it was an acceptable workaround because it currently does nothing (that I'm aware of).
My server's total map size is 43GB. I delete the Mineshaft.dat every hour or so, when it gets to about 1MB. But deleting Fortress.dat is completely out of the question. I'd rather restart every 15 minutes.
This is such a known issue, modded server implementations have solutions, like disabling structures:
http://www.spigotmc.org/threads/disabling-structure-saving.8555/
... though this seems like a pretty lousy workaround. In order to find wither skeletons, one must generate new map terrain. Every time these structures are found, once they are unloaded from memory, players have to start over and find new structures. Screw that.
Still an issue in 1.7.4.
Alex, what do you mean "I'm not going to make any friends with this ..."
Verified still happens on 1.7.4.
In fact, it's worst than ever. In 14w02c, @e may now also be used:
Still an issue in 14w02c.
@Talven81, I agree with you, but if the choice is destroy structure data or restart literally every single minute ... I do not exaggerate. The players on my server decided to travel by nether roof to 300,000 blocks. Vanilla has no way of preventing this kind of thing.
I hate deleting these files. I saw a comment on
MC-33086that claims this is an easy fix. I sure hope so, but the damage to my world has been done. Even if MCEdit can rebuild structures, I'm not sure if that's practical for a world over a certain size.Actually, anything that involves .toByteArray() would be a bad workaround. We're talking about a pretty large data set. Without looking at the code myself, I wonder if adding BufferedOutputStream to the chain would help.
On the other hand, I have a hard time believing that all these problems have been caused by what amounts to a one-liner. It has to be a huge mystery to Mojang, so it can't be that simple.
Although server /tell is now being logged, there is still no way for players to privately respond to the console. Prior to 1.3.1, all failed command by the user were logged so two-way private messaging to the console was possible. This is still impossible as of 14w02c.
Very good suggestion. Basically a snowglobe. But prior to 1.6.4, it was never necessary to confine anyone, except to save hard drive space. And it becomes more complicated when we consider Nether travel. Nonetheless, it is nice that there is an option for that if it comes down to it.
Regarding the performance changes, I think having each dimension on its own thread has greatly helped overall performance, even in this situation. Garbage collection is very much improved. Server uptime is very much improved.
As result, I purposefully stopped deleting the Mineshaft.dat files (I did this automatically when the server would start, but I disabled it). However, when I stopped deleting Mineshaft.dat, performance slowly dropped over the days until I had to resume deleting the file once again.
So, the performance changes actually mask part of the issue, perhaps to the point that only very large worlds experience this problem to a crippling degree.
Again, I think
MC-33086is the root cause for this:Yeah, it's stupid for the admin to type /say @e. What are they thinking? I mean, if it crashes your server, you did it yourself. It's not like players can type /me @e to crash the clients in SMP. Oh wait. They can!
Just tested this on 14w03b. Still an issue.
It looks like it just disconnects all of the clients, if it is typed once. But I've had abusive players spam this, causing the server to crash. There is also similar problems with /tell allowing players to use @a @p selectors to locate other player.
See:
MC-40319Try using a third party client to spam selectors on a 53GB world where each player needs 100MB of server memory because they're in a different corners of the map, and see if that server can hold up.
I think it qualifies as a memory leak. Not just your garden variety memory leak. It's a memory leak that is persisted to disc.
Poweruser, I've been testing with the following Java options, which give me the best possible up-time, even with theses non-memory-leak issues:
Desync still observed in 14w04b.
I have not observed it lately.
I believe this is also related, observed in the console running 14w04b:
java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at nm.a(SourceFile:494) at nm.a(SourceFile:474) at arn.a(SourceFile:226) at arn.a(SourceFile:99) at nl.b(SourceFile:160) at nl.a(SourceFile:191) at nm.a(SourceFile:655) at bs.b(SourceFile:36) at x.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:709) at oq.run(SourceFile:80) at java.lang.Thread.run(Thread.java:722) [01:45:00] [RCON Client #24/INFO]: [Rcon: Saved the world]Also confirmed that, while sessions server is down, setting server.properties online-mode=false prevents crash.
I agree with DaMaloma. In addition to what DaMaloma said, if this were related to blocks, setting server.properties online-mode=false would not help, but it does.
When the sessions server goes down or has high latency, down goes the server.
Anyway, I'm not worried about which bug is fixed. NullPointerException is usually an obvious, easy fix. Usually.
While @e no longer works, @a @p and @r still does. This means players can still triangulate other players in survival.
Observed in 14w08a and prior.
Since this thread is very long, I just wanted to point out a solution for certain servers experiencing this issue. YMMV.
Step 1: Stop your server.
Step 2: Look for the file in your server data files called data/Mineshaft.dat.
Step 3: Rename it to Mineshaft.old
Step 4: Start your server.
If this "solves" your problem, you might have to repeat this periodically, as the file grows, depending on how much players explore. But if this does not solve your problem, you should rename Mineshaft.old back to Mineshaft.dat, just in case the file is ever used for anything some day.
Someone from Mojang looked at this less than 24 hours ago and indicated that "this barely even rates" as bugs go. So I take that as in indication that they are not working on this anytime soon.
https://twitter.com/TheMogMiner/status/437689512873828352
So there's a strong suggestion that there's a non-high priority fix. But it's even possible that vanilla non-arena PvP is now not considered universally supported anymore. Yup.
It's funny because on my server, there are a lot of people who are lousy at direct PvP. So they use distance from spawn as their only defense. Those players are now totally screwed.
But I can see how this is an odd situation. Not a lot of servers out there do the anarchy theme with the Mojang server jar.
Observed in 14w08a.
To test if your world is full of wither skulls, use this command:
If the /tp works, then you have at least one instance of the wither skull just hanging out in a loaded chunk. To clear them all, use:
You can also find eternal arrows by using type=Arrow.
This was observed in 14w11b.
So if you find a silverfish block, you can safely destroy it without risking a confrontation with silverfish, if you use silk touch.
This seems like a problem. I can understand not dropping the block, but silverfish should still spawn.
Still observed in 14w11b.
Well, whatever the fix is, there should be no way to avoid a silverfish. It should either be dropped in the block dormant or out of the block alive. No tool should be able to simply erase the silverfish.
Still an issue in 14w11b. I believe this console output is related, because it often occurs when /save-all command is issued over rcon:
java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at nz.a(SourceFile:502) at nz.a(SourceFile:482) at ave.a(SourceFile:226) at ave.a(SourceFile:99) at ny.b(SourceFile:161) at ny.a(SourceFile:192) at nz.a(SourceFile:663) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:733) at qe.run(SourceFile:80) at java.lang.Thread.run(Thread.java:744) java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at nz.a(SourceFile:502) at nz.a(SourceFile:482) at ave.a(SourceFile:226) at ave.a(SourceFile:99) at ny.b(SourceFile:161) at ny.a(SourceFile:192) at nz.a(SourceFile:663) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:733) at qe.run(SourceFile:80) at java.lang.Thread.run(Thread.java:744) java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at nz.a(SourceFile:502) at nz.a(SourceFile:482) at ave.a(SourceFile:226) at ave.a(SourceFile:99) at ny.b(SourceFile:161) at ny.a(SourceFile:192) at nz.a(SourceFile:663) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:733) at qe.run(SourceFile:80) at java.lang.Thread.run(Thread.java:744) [10:00:01] [RCON Client #271/INFO]: [Rcon: Saved the world]Tested in 14w11b. Can still use /tell @a without being op. Using various selectors, it is possible to locate other players, for example:
Using trigonometry, a player can obtain the exact cords of a player in 3 whispers.
Still impossible in 14w11a.
Note,
MC-241has been reopened.Problem still present in 14w11b.
Etho's point of view on item frames:
https://www.youtube.com/watch?v=v6HCy9bvG-c&t=975
I believe we will see a profound reduction of io.netty.handler.timeout.ReadTimeoutException due to the fix of
MC-33086. If there's a snapshot tomorrow, we shall see.I noticed that the server will call Thread.dumpStack() every time it reports "Wrong Location!" which is very expensive (much lag inducing). If would be nice if Mojang would call logger.isDebuggingEnabled() (or whatever they use) before arbitrarily calling Thread.dumpStack().
Still a problem in 14w18b, SMP. Less of a problem when the server isn't busy, but still present.
I verify, the buffer indeed helped a lot. Before, I had a Mineshaft.dat file that was 11,895,844 and back then every player would get kicked every time the server saved. I had a script that would delete this file before every start.
After this fix, I took out the script and now, the same file has grown to 15,640,524 but no one is being kicked when the server saves.
I'm not saying we're lag free. But those spikes are not crippling the server any longer. Thank you [Mojang] Nathan Adams.
Now that Mineshaft.dat has grown to 21,228,624, the server can take up to 10 seconds to save, often results in Full GC event.
To see these events, here's how I launch the server:
Here is what the GC is saying when this occurs:
This means it took > 10 seconds to do a Full GC with only 6 minutes of uptime, 4GB memory. This is unusual. Deleting the Mineshaft.dat eliminates the Full GC events.
It's certainly an improvement, but I think this is still too long and this item should be re-opened.
Also still getting the following stack trace in the console during save (14w20b):
java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at on.a(SourceFile:536) at on.a(SourceFile:516) at ayu.a(SourceFile:226) at ayu.a(SourceFile:99) at om.b(SourceFile:161) at om.a(SourceFile:192) at on.a(SourceFile:697) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:748) at qt.run(SourceFile:80) at java.lang.Thread.run(Thread.java:722) java.util.ConcurrentModificationException at java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1115) at java.util.TreeMap$KeyIterator.next(TreeMap.java:1169) at on.a(SourceFile:536) at on.a(SourceFile:516) at ayu.a(SourceFile:226) at ayu.a(SourceFile:99) at om.b(SourceFile:161) at om.a(SourceFile:192) at on.a(SourceFile:697) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:748) at qt.run(SourceFile:80) at java.lang.Thread.run(Thread.java:722)... and ...
java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:819) at java.util.ArrayList$Itr.next(ArrayList.java:791) at on.a(SourceFile:536) at on.a(SourceFile:516) at ayu.a(SourceFile:226) at ayu.a(SourceFile:99) at om.b(SourceFile:161) at om.a(SourceFile:192) at on.a(SourceFile:697) at bz.b(SourceFile:36) at z.a(SourceFile:65) at net.minecraft.server.MinecraftServer.g(SourceFile:748) at qt.run(SourceFile:80) at java.lang.Thread.run(Thread.java:722)Yes, problem observed in 14w20b.
Step 1: Find a silverfish block (by observing that the stone block doesn't break as quickly as normal stone blocks).
Step 2: Switch to silk touch.
Step 3: Mine silverfish block with silk touch: only smooth stone drops, no silver fish mob entity released.
Conclusion: Silk touch should not allow the player to avoid silver fish mob attack.
Issue persists in 14w21b. It's much worse now because non-op users can now cause the server to halt:
The higher r= is, the more likely the server will completely halt. Why are selectors even allowed by non-op players in the first place?
14w21b
14w21b; Java 1.7.0_60-b19; Mac OS 10.9.2
[08:17:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2416ms behind, skipping 48 tick(s) s: Saving entity NBT at ub.e(SourceFile:1112) at ub.d(SourceFile:1074) at ayx.a(SourceFile:210) at ayx.a(SourceFile:99) at op.b(SourceFile:161) at op.a(SourceFile:192) at oq.a(SourceFile:700) at net.minecraft.server.MinecraftServer.a(SourceFile:339) at net.minecraft.server.MinecraftServer.v(SourceFile:524) at net.minecraft.server.MinecraftServer.run(SourceFile:422) at java.lang.Thread.run(Thread.java:722) Caused by: java.lang.NullPointerException at aku.k(SourceFile:127) at akv.a(SourceFile:128) at acc.b(SourceFile:228) at ub.e(SourceFile:1100) ... 10 more s: Saving entity NBT at ub.e(SourceFile:1112) at ub.d(SourceFile:1074) at ayx.a(SourceFile:210) at ayx.a(SourceFile:99) at op.b(SourceFile:161) at op.a(SourceFile:192) at oq.a(SourceFile:700) at net.minecraft.server.MinecraftServer.a(SourceFile:339) at net.minecraft.server.MinecraftServer.v(SourceFile:524) at net.minecraft.server.MinecraftServer.run(SourceFile:422) at java.lang.Thread.run(Thread.java:722) Caused by: java.lang.NullPointerException at aku.k(SourceFile:127) at akv.a(SourceFile:128) at acc.b(SourceFile:228) at ub.e(SourceFile:1100) ... 10 more s: Saving entity NBT at ub.e(SourceFile:1112) at ub.d(SourceFile:1074) at ayx.a(SourceFile:210) at ayx.a(SourceFile:99) at op.b(SourceFile:161) at op.d(SourceFile:220) at oq.c(SourceFile:179) at net.minecraft.server.MinecraftServer.w(SourceFile:570) at np.w(SourceFile:284) at net.minecraft.server.MinecraftServer.v(SourceFile:506) at net.minecraft.server.MinecraftServer.run(SourceFile:422) at java.lang.Thread.run(Thread.java:722) Caused by: java.lang.NullPointerException at aku.k(SourceFile:127) at akv.a(SourceFile:128) at acc.b(SourceFile:228) at ub.e(SourceFile:1100) ... 11 more [08:17:53] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2468ms behind, skipping 49 tick(s) [08:17:56] [RCON Listener #2/INFO]: Rcon connection from: /192.168.0.3Occasionally observed in snapshot 12w21b.
Related?
Needs to be reopened. Still an issue on Multiplayer:
That procedure is not recommended.
Cross-platform server jar: https://s3.amazonaws.com/Minecraft.Download/versions/14w25b/minecraft_server.14w25b.jar
SMP
I see this as well. Every time a player logs in, the trigger IllegalArgumentException and the server must restart.
Here's a clue: When the server view-distance=10, this exception happens every login. When view-distance=3, doesn't happen, so far.
It took about 5 minutes for it to eventually happen in view-distance=3
Another clue: I have a command block at spawn on my server that automatically does a /spreadplayers for new players. Spawn is very sparse. The area in the spread is also somewhat sparse, typically.
I've seen new players stay connected for 20+ minutes. If this bug is related to specific block ids, apparently those block ids are not naturally present everywhere, thus certain players in unbuilt areas do not cause the crash.
But once an established player logs in, the server crashes.
Workaround:
It's listed as fixed because it has been fixed. Likely, the fix will appear in the next snapshot.
Workaround:
Once the fix comes out, you'll want to switch the tick speed back to the default. Mine was originally 3. Otherwise, plants won't grow.
I've had a few other people try the /gamerule, and it worked for them. Once the fix comes out, you'll want to switch the tick speed back to the default. Mine was originally 3. Otherwise, plants won't grow.
Having the same problem.
I'm seeing this as well. The log reports:
[20:05:23] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 30556ms behind, skipping 611 tick(s) [20:05:26] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2918ms behind, skipping 58 tick(s) [20:05:59] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 3954ms behind, skipping 79 tick(s) [20:06:49] [Server Watchdog/FATAL]: A single server tick took 44.60 seconds (should be max 0.05) [20:06:49] [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown. [20:06:51] [Server Watchdog/ERROR]: This crash report has been saved to: /Users/steve/Minecraft/Swim3/./crash-reports/crash-2014-07-24_20.06.51-server.txt [20:06:51] [Server Shutdown Thread/INFO]: Stopping serverIn my opinion, this "watchdog" thread should be an optional setting. I have external scripts that determine the level of response from the server to determine if it should halt or not. The problem with this watchdog is, it doesn't even attempt to save the world.
Maybe, just add a /save-all right before /stop because /stop can take a while.
Still impossible in 14w30c.
Typical log entry prior to watchdog kicking in:
[20:05:23] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 30556ms behind, skipping 611 tick(s) [20:05:26] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2918ms behind, skipping 58 tick(s) [20:05:59] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 3954ms behind, skipping 79 tick(s) [20:06:49] [Server Watchdog/FATAL]: A single server tick took 44.60 seconds (should be max 0.05) [20:06:49] [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown. [20:06:51] [Server Watchdog/ERROR]: This crash report has been saved to: /Users/steve/Minecraft/Swim3/./crash-reports/crash-2014-07-24_20.06.51-server.txt [20:06:51] [Server Shutdown Thread/INFO]: Stopping serverThe criteria Watchdog is using might be a little overzealous. It'd be nice if instead of arbitrarily stopping the server, if there was a way for it to execute an external script, that'd be cool.
JVM offers such an option, e.g.:
If we were allowed the option to execute our own script, we could kick all of the players, save, then stop the server. Often, when the server is told to just stop during a overloaded condition, it just sits there for a long time. In my experience, kick/save/stop is typically more reliable than just stop, during an overloaded condition.
Also, I don't think it's always appropriate for the server to shut down due to being behind. There are cases where network conditions can cause the server to fall behind. When the network conditions clear up, the server can catch up, if it weren't for the watchdog. Just considering the server crashed because of network conditions seems like an overreaction.
In my case, the chunks near spawn tend to have a lot of wither skulls floating motionless in the sky. On my server, the area about 2,000 around spawn is sometimes full of withers that attack at random, throwing their skulls everywhere. At some point, (not sure if this is still the case) skulls that enter an unloaded chunk freeze in place. I believe some of these chunks take longer to load as result.
Related: https://bugs.mojang.com/browse/MC-4465
Problem encountered often in snapshot 14w30c:
After this happens, the same command may work immediately after the error.
I can no longer recreate the same issue in 14w30c.
I believe as of 14w30c, this problem persists. I'm seeing the following log entries. In the past, this meant that there were corrupt chunks, but whenever I check these locations, the chunks are fine. The server spits out these messages much more often when view-distance=3 is set and more than one player is logged in:
Workaround, first do:
... which dumps them out of the minecart or boat, then do /spreadplayers.
Fenhl, you said:
Are you sure it wasn't caused by something in the Overworld itself? Because I just noticed something. There are two main locations I frequent in my world. One had villagers, one did not. Then I cured a new zombie villager at the location without villagers. Now the watchdog takes down the server when I AFK at both locations. The place without villagers had far fewer crashes, if any (there are other players who may have villagers too). Now it's bad at both locations now that they both have villagers.
So, do you have villagers at the place you refer to as "a specific portal to the Overworld"?
To verify this, I went to The End, where there were never any villagers. I went AFK for quite some time, no watchdog event. Then I spawned a villager in The End, after about 10 minutes, I got a watchdog crash.
I believe it might even have to do with the villager proximity to the player.
Come to think of it, the 10 minute period might be related to the day/night cycle. It might be related to doors placed before 14w30c.
I managed to capture a debug report just before the watchdog thread took the server down:
http://pastebin.com/NqpmH0HC
It's usually a race condition. This report mentions race conditions. So, rather than risk a duplicate report, I just commented here.
I confirm it's still happening in 14w31a:
[09:43:57] [Server Watchdog/FATAL]: A single server tick took 60.00 seconds (should be max 0.05) [09:43:57] [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown. [09:43:59] [RCON Listener #2/INFO]: Rcon connection from: /127.0.0.1 [09:43:59] [Server Watchdog/ERROR]: This crash report has been saved to: /Users/steve/Minecraft/Swim3/./crash-reports/crash-2014-07-30_09.43.59-server.txt [09:43:59] [Server Shutdown Thread/INFO]: Stopping serverHere's the crash report itself: http://pastebin.com/3W4SM6BZ
I hope this is related, but I notice that my max tick is now 60.00, and at the same time, I noticed a new key in server.properties:
I just confirmed that "/gamerule doMobSpawning false" eliminates crashes even when I'm near villagers. I think that points to Zombie AI being the problem.
Absolutely, it's only dependent on the lag. But lag is caused by something, which this feature will help us diagnose. One of those things might be Zombies pathing to Villagers.
I also reverted back to 14w30c after testing 14w31a. Too many crashes for me as well.
I think it's actually worse in 14w31a, for my server anyway. I believe pathfinding is now causing the Watchdog thread to down the server. See
MC-63590I know that error is documented in
MC-2545, and I clarified that there are no corrupt chunks involved here. I believe the server is trying to spawn mobs in unloaded chunks, not corrupt chunks. Prior to 14w30c, there was no indication that mobs were being spawned in unloaded chunks, so I believe it's new logging of old behavior.https://twitter.com/inertia186/status/496310644455374848
Have you tried:
If it's like the other properties, maybe that's how you disable it.
What pisses me off about this so called "works as intended" situation is, about haft the time, when the server considers itself crashed, the java process has to be killed (e.g.: killall -9 java) because this stupid "watchdog" thread doesn't always shutdown cleanly. But of course, it "works as intended" so it will never be fixed, even if I could pry out a crash report.
Net result I get a useless "Considering it to be crashed, server will forcibly shutdown" message and the server sits there for hours on end until I notice it and force kill java. Thanks for that.
And if I create a new bug detailing this, it'll naturally be marked as duplicate of this one.
If it helps, here's the crash report that resulted in a java process that required kill -9 to recover from:
http://pastebin.com/X8q1KgwH
I found the root cause for me. So, think about this. The initial watchdog was 30 seconds. Then the default was changed to 60 seconds. That's how long I had to find and deal with:
http://cl.ly/image/1a2L050t1A08
Yes, those were "natural" spawn. That is to say, no admin purposefully placed them. They spawned during the snapshots. The watchdog didn't help this, it just got in the way.
Instead of a thread that just stops the server when there are problems, it'd be nice if there was a way for admin to be able to disable individual threads that are causing problems. In my case, it would have been nice to have had the ability to toggle mob AI. For example, this would have been nice:
/gamerules doMobAI falseProblem still present in 14w31a:
[Mojang] Nathan Adams, here's an example where System.exit(1) failed and I had to do kill -9 instead. Is it a race condition? (14w32a, java 1.8.0_11, Mac OS X 10.9.4)
And the crash report:
http://pastebin.com/d4w0z0is
I believe this situation now triggers the watchdog thread, by default:
MC-63590This particular example was allowed to sit for about 15 minutes before I killed it. I've seen it sit for hours.
I think it's related to RCON. It seems to happen most if I try to remove massive amounts of entities with RCON. The same commands in-game do not cause it to hang.
Thanks for looking into it.
I just got Couldn't Load Chunks in 14w32d:
Another crash that required kill -9 to stop Java. It was allowed to sit for about 15 minutes before kill -9 was used.
This time in 14w32d:
http://pastebin.com/X88kQctM
That is correct, the crash in my previous comment (comment-187211) has no connection with the watchdog. That's because I disabled it by setting it max-tick-time=-1.
[Mojang] Nathan Adams said that all the watchdog does is send System.exit(1) but the crash I posted in my previous comment required an OS kill signal (kill -9), which the watchdog has not been able to deal with, so far.
What happens if you edit server.properties and disable the watchdog?
Using the new /entitydata command, I was able to pull the entity data for these WitherSkulls:
/entitydata @e[c=1,type=WitherSkull] {} The data tag did not change: {Motion:[0:4.4E-323d,1:4.4E-323d,2:-4.4E-323d,],xTile:-1s,UUIDLeast:-5943542692992487930L,inGround:0b,Invulnerable:0b,Air:300s,OnGround:0b,Dimension:0,PortalCooldown:0,Rotation:[0:45.000008f,1:-89.999985f,],FallDistance:0.0f,inTile:"",UUIDMost:1757454117284302355L,Pos:[0:3615.696000611837d,1:16.4260386987285d,2:-7967.125136944639d,],zTile:-1s,Fire:20s,yTile:-1s,id:"WitherSkull",direction:[0:4.4E-323d,1:4.4E-323d,2:-4.4E-323d,],}This data came from a server on 14w33a.
There are thousands of these projectiles floating about on my server. In order to deal with these problems, I've got some commands that run every so often.
Setup (run once):
Run periodically:
I run scripts similar to this with rcon. If I use /kill directly on the projectiles, I will often get ConcurrentModificationException, but not every time. Using the scoreboard objectives eliminates the Exception.
When I set my server's view distance to 3, my log fills with messages like this:
I have verified this is not chunk corruption. I have seen these messages when the occasional chunk is corrupt. But in this case, every time I see the message, it happens exactly once per mob, then stops. The mob ID is different for every message. Corrupt chunks show the same message over and over for the same mob, so this is not a corrupt chunk.
Not only that, but I visually inspected the location and found no corrupt chunks.
I believe this message is related to mob spawn rates when view distances are low. It appears to be an off-by-one error involving only negative coordinates.
For example:
Seems like it only ever involves negative chunk borders.
Also, spreadplayer at one time would select ocean spawn but not in the 1.8 snapshots. Maybe ocean can be added back as an option?
Observed in 14w34d. Blaze attacks lit netherrack in an area that was completely dark. After putting out the fire, the affected areas were still fully lit.
See property called max-tick-time: http://minecraft.gamepedia.com/Server.properties#section_3
In 1.8, game rules can be made up and set to any value. They only have meaning to map makers. This is intended.
Pierre Waldén, it is true that > 60 seconds to do a gametick is a problem in and of itself. The watchdog does not solve these particular problems, it only masks them. Some of these other problems have been discussed in this very "thread" and [Mojang] Nathan Adams has already said he would look at some of these situations. I assume he has by now and couldn't find the root cause.
The fact that the watchdog can be disabled now is a result of the issue you describe. Disabling the watchdog will pretty much be required in order to avoid "closed as duplicate" of this one.
Still a problem in 1.8.3.
Observed in 1.8.4 on client:
[12:12:48] [Client thread/ERROR]: Item entity 379481 has no item?!
I can say with certainly that this issue is still present (in 1.8.7) with any kind of projectile (e.g., new wither battles and old ones). I have subroutines in my external tool to look specifically for floating projectiles and remove them:
https://github.com/inertia186/cobblebot/blob/master/app/concerns/detectable.rb
Typically, I have these subroutines execute when a player authenticates. Today, it found over 500 floating projectiles, which seems like a lot. I only have about 60 unique players every day on my server.
The way it works is, when a player authenticates, my app tries to determine if there are any projectiles loaded. If it finds any, it marks them with an "isJunk" objective. It then kills any projectile with an isJunk score above 1, which usually means it's frozen.
This is accomplished entirely with RCON in vanilla, not using plug-ins or jar modifications.
Ok, I attached a client crash report while logged into affected server.
Seeing something similar in 1.9 snapshot (15w31a), this appears to also prevent login on servers going from 1.8.8 to snapshot.
Upgraded to 15w31b on both client and server. While there was no corresponding error in the SMP server log, the client cannot connect (see attached screen shot from 15w31b client).
Had a few players on my server who's clients were crashing able to do a 180° and walk away from affected chunks by lowering their view distance to 2 and connect via slow ISP to keep affected chunks from loading while they walked away.
I suspect maybe it has to do with characters that are problematic in JSON like slash (\\\\) and quotes (").
Sorry, I couldn't be sure that the preview was working correctly because slash it problematic in JSON (which is what these previews typically use to communicate with AJAX).
Still seeing this problem in 15w31c:
These "failed to save chunk" messages seem to correlate with high memory usage.
I'm attaching Plumbr reports taken while running 15w31c for many hours.
Still seeing this problem in 15w32a:
Still seeing this problem in 15w32b:
15w32c:
Log:
Server debug:
System Details:
Details: Minecraft Version: 15w32c Operating System: Mac OS X (x86_64) version 10.9.5 Java Version: 1.8.0_05, Oracle Corporation Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation Memory: 2381681512 bytes (2271 MB) / 4225236992 bytes (4029 MB) up to 4225236992 bytes (4029 MB) JVM Flags: 5 total; -Xincgc -Xmx4G -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDetails -Xloggc:server_gc.log15w33c:
I'm also seeing this happen on my server. No crash report. Just the error message in this issue's description.
I lowered the server view distance from 9 to 3, and it happens even faster.
I believe it's possibly related to buttons and pressure-plates.
Issue this command and the problem happens less:
/gamerule reducedDebugInfo trueAlso seem to help, modify server.properties:
I encountered this issue today in 15w45a.
Confirmed in 15w46a, if you time out at the exact right moment (after the portal takes you out of the overworld and when it says Downloading), you end up at the overworld coordinates when you log back in.
Some players on my server have reached the world border and managed to crash the server by trying to go beyond the world border using this technique.
I think it fits the criteria of a private issue because new players on SMP can crash the server with minimal time and resources, but its not an instant process.
I also don't think it will actually help prevent maliciousness so there's no real point in marking this issue private.
In 1.9.1-pre3, squid appear to no longer spawn in this pattern over the ocean. But in The End, Endermen do at about 133 blocks from the ground.
See capture: http://cl.ly/3P2K2P2M0Y31
@WitherBoyMCW This is a good workaround for me as well.
I have observed that when the trackpad pointer becomes visible (without the workaround), the game starts to activate OS elements like the Dock. Even closing Minecraft will not fix the issue, once it begins to happen. I have seen full reboots fix the issue temporarily.
I think one thing that can introduce the issue if you haven’t seen it is to watch a video using Picture in Picture while playing Minecraft. When the video is playing, put the iPad to sleep (i.e., close the lid on the Magic Keyboard).
Once you come back, interacting with the video and Minecraft will probably lead to this pointer issue.