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

Unexplained Lag with Debug Profiling

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Invalid
    • None
    • Minecraft 1.4.2
    • Unconfirmed

      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 ---

            Unassigned Unassigned
            inertia Anthony Martin
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: