MC-1101Unexplained Lag with Debug Profiling
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 ---
Environment
- 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: 918602576 bytes (876 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: 34241 (1917496 bytes; 1 MB) allocated, 0 (0 bytes; 0 MB) used
Created Issue:
Unexplained Lag with Debug Profiling
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 ---Environment
- 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: 918602576 bytes (876 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: 34241 (1917496 bytes; 1 MB) allocated, 0 (0 bytes; 0 MB) used
Changed Description:
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 ---
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:
Resolving since lag is explained.