Extremely Low Tickrate

[Danjo]

Hello,

We've been getting a very low tickrate on our server ever since launch. Before this it hosted a 35 man "mod which must not be named" server at a solid 20tps (unless there were thousands of loose entities). Right now its hovering around 3 - 4 ticks per second. We are not hitting maximum RAM usage so that is not an issue. Even with only 10 or so players online we experience crippling tick lag.

Its a dedicated shared server hosted by roxservers.com I believe their specifications are as follows:
2.9Ghz i7, 4Gb Ram, 128Gb SSD.

Here are the profiler results from the server:

---- Minecraft Profiler Results ----
// Will I ever be good enough for you? :(
 
Time span: 10066 ms
Tick span: 41 ticks
// This is approximately 4,07 ticks per second. It should be 20 ticks per second
 
--- BEGIN PROFILE DUMP ---
 
[00] levels - 96,37%/96,37%
[01]  world - 99,90%/98,55%
[02]  tick - 98,74%/97,32%
[03]    entities - 84,19%/81,93%
[04]    regular - 99,03%/81,13%
[05]      tick - 97,52%/79,12%
[06]      unspecified - 44,93%/35,55%
[06]      ai - 25,35%/20,06%
[07]        newAi - 84,78%/17,01%
[08]        goalSelector - 31,26%/5,32%
[09]          unspecified - 80,36%/4,27%
[09]          goalTick - 8,09%/0,43%
[10]          pathfind - 78,60%/0,34%
[10]          unspecified - 20,50%/0,09%
[10]          canSee - 0,90%/0,00%
[09]          canUse - 7,09%/0,38%
[09]          goalStart - 4,12%/0,22%
[10]          ng - 64,15%/0,14%
[11]            pathfind - 98,88%/0,14%
[11]            unspecified - 1,12%/0,00%
[10]          unspecified - 28,82%/0,06%
[10]          nf - 2,47%/0,01%
[10]          mx - 2,33%/0,01%
[11]            pathfind - 79,30%/0,00%
[11]            unspecified - 20,70%/0,00%
[10]          mv - 1,95%/0,00%
[11]            pathfind - 86,06%/0,00%
[11]            unspecified - 13,94%/0,00%
[10]          mj - 0,22%/0,00%
[10]          mr - 0,02%/0,00%
[10]          mp - 0,02%/0,00%
[10]          mu - 0,02%/0,00%
[09]          canContinue - 0,21%/0,01%
[09]          pathfind - 0,07%/0,00%
[09]          canSee - 0,06%/0,00%
[08]        unspecified - 27,69%/4,71%
[08]        targetSelector - 18,57%/3,16%
[09]          unspecified - 96,10%/3,03%
[09]          goalStart - 1,50%/0,05%
[10]          unspecified - 99,86%/0,05%
[10]          nr - 0,14%/0,00%
[09]          goalTick - 1,11%/0,03%
[09]          canUse - 0,87%/0,03%
[09]          canSee - 0,32%/0,01%
[09]          canContinue - 0,10%/0,00%
[10]          canSee - 85,02%/0,00%
[10]          unspecified - 14,98%/0,00%
[08]        controls - 14,62%/2,49%
[09]          unspecified - 75,11%/1,87%
[09]          look - 16,57%/0,41%
[09]          move - 7,08%/0,18%
[09]          jump - 1,23%/0,03%
[08]        checkDespawn - 5,67%/0,96%
[08]        navigation - 1,10%/0,19%
[08]        mob tick - 0,67%/0,11%
[08]        sensing - 0,42%/0,07%
[07]        unspecified - 7,74%/1,55%
[07]        oldAi - 7,48%/1,50%
[08]        ai - 38,85%/0,58%
[09]          unspecified - 98,90%/0,58%
[09]          pathfind - 1,10%/0,01%
[08]        unspecified - 34,69%/0,52%
[08]        stroll - 15,13%/0,23%
[09]          pathfind - 98,96%/0,22%
[09]          unspecified - 1,04%/0,00%
[08]        pathfind - 10,78%/0,16%
[08]        followpath - 0,55%/0,01%
[06]      travel - 15,53%/12,29%
[07]        move - 45,10%/5,54%
[07]        unspecified - 30,23%/3,72%
[07]        rest - 24,67%/3,03%
[06]      entityBaseTick - 6,97%/5,52%
[06]      mobBaseTick - 4,02%/3,18%
[06]      push - 1,38%/1,09%
[06]      move - 0,74%/0,59%
[06]      headTurn - 0,39%/0,31%
[06]      rest - 0,25%/0,19%
[06]      chunkCheck - 0,19%/0,15%
[06]      looting - 0,11%/0,09%
[06]      rangeChecks - 0,07%/0,06%
[06]      jump - 0,07%/0,05%
[06]      checkLight - 0,00%/0,00%
[07]        checkedPosition < toCheckCount - 55,75%/0,00%
[07]        unspecified - 24,36%/0,00%
[07]        getBrightness - 19,89%/0,00%
[05]      unspecified - 2,41%/1,96%
[05]      remove - 0,07%/0,05%
[04]    tileEntities - 0,74%/0,61%
[05]      unspecified - 99,71%/0,61%
[05]      checkLight - 0,26%/0,00%
[06]      unspecified - 44,46%/0,00%
[06]      getBrightness - 42,68%/0,00%
[06]      checkedPosition < toCheckCount - 12,86%/0,00%
[05]      getBrightness - 0,04%/0,00%
[05]      checkedPosition < toCheckCount - 0,00%/0,00%
[04]    unspecified - 0,13%/0,10%
[04]    remove - 0,07%/0,06%
[04]    global - 0,03%/0,02%
[05]      entityBaseTick - 78,11%/0,02%
[05]      unspecified - 21,89%/0,00%
[04]    pendingTileEntities - 0,00%/0,00%
[03]    tickTiles - 13,41%/13,05%
[04]    unspecified - 54,31%/7,09%
[04]    tickTiles - 30,82%/4,02%
[05]      unspecified - 99,96%/4,02%
[05]      checkLight - 0,03%/0,00%
[06]      unspecified - 71,41%/0,00%
[06]      getBrightness - 27,74%/0,00%
[06]      checkedPosition < toCheckCount - 0,85%/0,00%
[05]      getBrightness - 0,01%/0,00%
[05]      checkedPosition < toCheckCount - 0,00%/0,00%
[04]    getChunk - 5,13%/0,67%
[04]    buildList - 3,08%/0,40%
[04]    tickChunk - 2,54%/0,33%
[05]      unspecified - 96,95%/0,32%
[05]      recheckGaps - 3,05%/0,01%
[06]      unspecified - 58,80%/0,01%
[06]      getBrightness - 40,56%/0,00%
[06]      checkedPosition < toCheckCount - 0,64%/0,00%
[04]    iceandsnow - 1,75%/0,23%
[04]    thunder - 1,00%/0,13%
[04]    checkLight - 0,87%/0,11%
[04]    moodSound - 0,36%/0,05%
[04]    playerCheckLight - 0,13%/0,02%
[05]      unspecified - 70,76%/0,01%
[05]      getBrightness - 28,62%/0,01%
[05]      checkedPosition < toCheckCount - 0,63%/0,00%
[03]    mobSpawner - 1,39%/1,35%
[03]    tickPending - 0,31%/0,30%
[04]    unspecified - 99,05%/0,30%
[04]    checkLight - 0,94%/0,00%
[05]      checkedPosition < toCheckCount - 62,34%/0,00%
[05]      getBrightness - 21,46%/0,00%
[05]      unspecified - 16,20%/0,00%
[03]    village - 0,26%/0,25%
[03]    chunkSource - 0,22%/0,21%
[03]    unspecified - 0,21%/0,21%
[03]    chunkMap - 0,01%/0,01%
[02]  tracker - 1,21%/1,20%
[02]  unspecified - 0,04%/0,04%
[02]  pools - 0,00%/0,00%
[02]  timeSync - 0,00%/0,00%
[01]  unspecified - 0,10%/0,10%
[00] connection - 3,62%/3,62%
[01]  packetflow - 96,78%/3,59%
[02]  unspecified - 66,29%/2,38%
[02]  travel - 14,31%/0,51%
[03]    move - 39,99%/0,21%
[03]    unspecified - 34,33%/0,18%
[03]    rest - 25,69%/0,13%
[02]  entityBaseTick - 5,37%/0,19%
[02]  move - 3,92%/0,14%
[02]  rest - 3,90%/0,14%
[02]  mobBaseTick - 3,83%/0,14%
[02]  push - 1,04%/0,04%
[02]  ai - 0,89%/0,03%
[03]    unspecified - 79,36%/0,03%
[03]    oldAi - 20,64%/0,01%
[02]  headTurn - 0,27%/0,01%
[02]  rangeChecks - 0,06%/0,00%
[02]  looting - 0,04%/0,00%
[02]  checkLight - 0,03%/0,00%
[03]    getBrightness - 36,57%/0,00%
[03]    checkedPosition < toCheckCount - 36,33%/0,00%
[03]    unspecified - 27,10%/0,00%
[02]  jump - 0,03%/0,00%
[01]  unspecified - 2,71%/0,10%
[01]  playerTick - 0,49%/0,02%
[02]  unspecified - 63,09%/0,01%
[02]  travel - 16,88%/0,00%
[03]    move - 41,34%/0,00%
[03]    unspecified - 37,36%/0,00%
[03]    rest - 21,30%/0,00%
[02]  entityBaseTick - 12,55%/0,00%
[02]  mobBaseTick - 4,41%/0,00%
[02]  ai - 1,56%/0,00%
[03]    unspecified - 80,00%/0,00%
[03]    oldAi - 20,00%/0,00%
[02]  push - 1,09%/0,00%
[02]  headTurn - 0,28%/0,00%
[02]  rangeChecks - 0,08%/0,00%
[02]  looting - 0,03%/0,00%
[02]  jump - 0,03%/0,00%
[01]  keepAlive - 0,03%/0,00%
[00] dim_unloading - 0,00%/0,00%
[00] players - 0,00%/0,00%
[00] tallying - 0,00%/0,00%
[00] snooper - 0,00%/0,00%
[00] tickables - 0,00%/0,00%
--- END PROFILE DUMP ---

We haven't added any mods to the server and we're running the FTB server version provided at launch. I'll gladly say the exact version if someone tells me how.

Thanks for looking over the problem.

 

[BrickedKeyboard]

This chart doesn't quite make sense. Nothing totals to 100%, etc. It looks, however, like hugely excessive numbers of entities...that have an AI. It looks like your problem is too many monsters/NPCs. This is pretty surprising - this isn't usually the problem.

 

[Danjo]

Here is another profile result with a tickrate of 14 from the same server:

---- Minecraft Profiler Results ----
// Now with the same numbers
 
Time span: 10995 ms
Tick span: 162 ticks
// This is approximately 14,73 ticks per second. It should be 20 ticks per second
 
--- BEGIN PROFILE DUMP ---
 
[00] levels - 97,31%/97,31%
[01]  world - 99,98%/97,89%
[02]  tick - 99,14%/97,04%
[03]    entities - 83,84%/81,36%
[04]    regular - 97,65%/79,44%
[05]      tick - 96,35%/76,54%
[06]      unspecified - 34,88%/26,70%
[06]      ai - 32,49%/24,87%
[07]        newAi - 93,80%/23,32%
[08]        goalSelector - 30,29%/7,07%
[09]          unspecified - 81,23%/5,74%
[09]          goalTick - 7,78%/0,55%
[10]          unspecified - 99,07%/0,54%
[10]          pathfind - 0,91%/0,01%
[10]          checkLight - 0,02%/0,00%
[11]            unspecified - 51,40%/0,00%
[11]            getBrightness - 48,60%/0,00%
[11]            checkedPosition < toCheckCount - 0,00%/0,00%
[09]          canUse - 6,52%/0,46%
[09]          goalStart - 4,09%/0,29%
[10]          ng - 54,27%/0,16%
[11]            pathfind - 98,19%/0,15%
[11]            unspecified - 1,81%/0,00%
[10]          unspecified - 37,82%/0,11%
[10]          mx - 3,58%/0,01%
[11]            pathfind - 90,92%/0,01%
[11]            unspecified - 9,08%/0,00%
[10]          nf - 2,44%/0,01%
[10]          mv - 1,25%/0,00%
[11]            pathfind - 80,93%/0,00%
[11]            unspecified - 19,07%/0,00%
[10]          mj - 0,39%/0,00%
[10]          nj - 0,08%/0,00%
[10]          mr - 0,05%/0,00%
[10]          nc - 0,05%/0,00%
[10]          mp - 0,04%/0,00%
[10]          mh - 0,02%/0,00%
[10]          ml - 0,01%/0,00%
[09]          canContinue - 0,38%/0,03%
[08]        unspecified - 30,07%/7,01%
[08]        targetSelector - 17,64%/4,11%
[09]          unspecified - 95,64%/3,93%
[09]          goalStart - 1,94%/0,08%
[09]          goalTick - 1,30%/0,05%
[09]          canUse - 1,04%/0,04%
[09]          canSee - 0,08%/0,00%
[08]        controls - 17,45%/4,07%
[09]          unspecified - 80,06%/3,26%
[09]          look - 12,97%/0,53%
[09]          move - 5,76%/0,23%
[09]          jump - 1,21%/0,05%
[08]        checkDespawn - 2,71%/0,63%
[08]        mob tick - 0,76%/0,18%
[08]        navigation - 0,73%/0,17%
[08]        sensing - 0,35%/0,08%
[07]        unspecified - 4,45%/1,11%
[07]        oldAi - 1,75%/0,44%
[08]        unspecified - 57,86%/0,25%
[08]        ai - 34,42%/0,15%
[08]        stroll - 6,92%/0,03%
[09]          pathfind - 97,03%/0,03%
[09]          unspecified - 2,97%/0,00%
[08]        followpath - 0,80%/0,00%
[06]      travel - 17,96%/13,75%
[07]        move - 42,61%/5,86%
[07]        unspecified - 34,62%/4,76%
[07]        rest - 22,77%/3,13%
[06]      entityBaseTick - 6,81%/5,21%
[06]      mobBaseTick - 4,14%/3,17%
[06]      push - 1,30%/1,00%
[06]      move - 0,97%/0,74%
[06]      rest - 0,47%/0,36%
[06]      headTurn - 0,44%/0,33%
[06]      chunkCheck - 0,23%/0,18%
[06]      looting - 0,12%/0,09%
[06]      rangeChecks - 0,09%/0,07%
[06]      jump - 0,08%/0,06%
[06]      checkLight - 0,01%/0,01%
[07]        checkedPosition < toCheckCount - 94,19%/0,01%
[07]        unspecified - 2,98%/0,00%
[07]        getBrightness - 2,82%/0,00%
[05]      unspecified - 3,55%/2,82%
[05]      remove - 0,10%/0,08%
[04]    tileEntities - 2,29%/1,86%
[05]      unspecified - 99,81%/1,86%
[05]      checkLight - 0,12%/0,00%
[06]      unspecified - 63,11%/0,00%
[06]      getBrightness - 35,65%/0,00%
[06]      checkedPosition < toCheckCount - 1,24%/0,00%
[05]      getBrightness - 0,05%/0,00%
[05]      checkedPosition < toCheckCount - 0,02%/0,00%
[04]    remove - 0,04%/0,03%
[04]    unspecified - 0,02%/0,02%
[04]    pendingTileEntities - 0,00%/0,00%
[04]    global - 0,00%/0,00%
[03]    tickTiles - 14,91%/14,47%
[04]    unspecified - 57,11%/8,27%
[04]    tickTiles - 30,42%/4,40%
[05]      unspecified - 99,99%/4,40%
[05]      checkLight - 0,01%/0,00%
[06]      unspecified - 62,21%/0,00%
[06]      getBrightness - 36,97%/0,00%
[06]      checkedPosition < toCheckCount - 0,83%/0,00%
[04]    getChunk - 4,15%/0,60%
[04]    tickChunk - 2,58%/0,37%
[05]      unspecified - 99,56%/0,37%
[05]      recheckGaps - 0,44%/0,00%
[06]      unspecified - 55,65%/0,00%
[06]      getBrightness - 43,22%/0,00%
[06]      checkedPosition < toCheckCount - 1,13%/0,00%
[04]    iceandsnow - 2,31%/0,33%
[04]    buildList - 1,53%/0,22%
[04]    thunder - 0,81%/0,12%
[04]    checkLight - 0,48%/0,07%
[04]    moodSound - 0,41%/0,06%
[04]    playerCheckLight - 0,19%/0,03%
[05]      unspecified - 66,45%/0,02%
[05]      getBrightness - 32,06%/0,01%
[05]      checkedPosition < toCheckCount - 1,49%/0,00%
[03]    mobSpawner - 0,90%/0,88%
[03]    unspecified - 0,15%/0,15%
[03]    village - 0,10%/0,10%
[03]    chunkSource - 0,07%/0,06%
[03]    tickPending - 0,02%/0,02%
[04]    unspecified - 99,54%/0,02%
[04]    checkLight - 0,46%/0,00%
[05]      unspecified - 58,08%/0,00%
[05]      getBrightness - 39,46%/0,00%
[05]      checkedPosition < toCheckCount - 2,46%/0,00%
[03]    chunkMap - 0,01%/0,01%
[02]  tracker - 0,84%/0,82%
[02]  unspecified - 0,02%/0,02%
[02]  pools - 0,00%/0,00%
[02]  timeSync - 0,00%/0,00%
[01]  unspecified - 0,02%/0,02%
[00] connection - 2,27%/2,27%
[01]  packetflow - 85,93%/1,97%
[02]  unspecified - 82,94%/1,63%
[02]  travel - 7,96%/0,16%
[03]    move - 38,49%/0,06%
[03]    unspecified - 33,05%/0,05%
[03]    rest - 28,46%/0,04%
[02]  entityBaseTick - 2,34%/0,05%
[02]  move - 1,82%/0,04%
[02]  rest - 1,70%/0,03%
[02]  mobBaseTick - 1,43%/0,03%
[02]  ai - 0,87%/0,02%
[03]    unspecified - 67,89%/0,01%
[03]    oldAi - 32,11%/0,01%
[02]  push - 0,44%/0,01%
[02]  checkLight - 0,22%/0,00%
[03]    checkedPosition < toCheckCount - 54,10%/0,00%
[03]    unspecified - 29,74%/0,00%
[03]    getBrightness - 16,16%/0,00%
[02]  headTurn - 0,16%/0,00%
[02]  rangeChecks - 0,03%/0,00%
[02]  checkedPosition < toCheckCount - 0,03%/0,00%
[02]  jump - 0,02%/0,00%
[02]  looting - 0,02%/0,00%
[02]  getBrightness - 0,01%/0,00%
[01]  playerTick - 9,08%/0,21%
[02]  unspecified - 62,25%/0,13%
[02]  travel - 22,27%/0,05%
[03]    move - 45,30%/0,02%
[03]    unspecified - 30,96%/0,01%
[03]    rest - 23,74%/0,01%
[02]  entityBaseTick - 8,25%/0,02%
[02]  mobBaseTick - 3,86%/0,01%
[02]  ai - 1,63%/0,00%
[03]    unspecified - 74,86%/0,00%
[03]    oldAi - 25,14%/0,00%
[02]  push - 1,18%/0,00%
[02]  headTurn - 0,42%/0,00%
[02]  rangeChecks - 0,07%/0,00%
[02]  looting - 0,04%/0,00%
[02]  jump - 0,04%/0,00%
[01]  unspecified - 4,94%/0,11%
[01]  keepAlive - 0,04%/0,00%
[00] save - 0,41%/0,41%
[00] dim_unloading - 0,00%/0,00%
[00] snooper - 0,00%/0,00%
[00] tallying - 0,00%/0,00%
[00] tickables - 0,00%/0,00%
[00] players - 0,00%/0,00%
--- END PROFILE DUMP ---

 

[BrickedKeyboard]

Do you have a readme to this profiler tool? Because I can't read a file that doesn't make sense.

For instance :
[03] entities - 83,84%/81,36%
[04] regular - 97,65%/79,44%

Both these lines have the same number of spaces of indentation. This implies they are on the same level. Then how can they add to more than 100%?

 

[Danjo]

I think its just how the minecraft profiler outputs data. I believe the number on the left in square brackets indicates the level regardless of indentation. So regular is a part of entities. It makes up 97% of entities and 79% of the overall.

At least thats how I've been interpreting it.

 

[BrickedKeyboard]

Sigh. I still am not happy with this file. However, I can say that you need a mod to reduce excess entities. Haven't been able to even figure out if it's mods or excess items.

 

[Danjo]

Here is another output from the built in debug profiler, shows that something is taking far too long to process. Does anyone have any idea how to narrow this down?

16:15:53
STDOUT:
Something's taking too long! 'root.levels' took aprox 101.829675 ms
16:15:53
STDOUT:
Something's taking too long! 'root' took aprox 104.308026 ms
16:15:53
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 101.906501 ms
16:15:53
STDOUT:
Something's taking too long! 'root.levels' took aprox 102.184772 ms
16:15:53
STDOUT:
Something's taking too long! 'root' took aprox 104.285155 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 100.915688 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 102.300011 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels' took aprox 102.635756 ms
16:15:55
STDOUT:
Something's taking too long! 'root' took aprox 113.015682 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 108.979713 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 110.373418 ms
16:15:55
STDOUT:
Something's taking too long! 'root.levels' took aprox 110.549647 ms
16:15:57
STDOUT:
Something's taking too long! 'root' took aprox 112.170311 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities' took aprox 101.473991 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 118.531275 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 120.336084 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels' took aprox 120.543395 ms
16:15:57
STDOUT:
Something's taking too long! 'root' took aprox 122.251147 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities.regular' took aprox 109.197287 ms
16:15:57
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities' took aprox 111.649247 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 128.183122 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 130.040418 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 130.337164 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 133.098772 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities.regular' took aprox 107.335004 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities' took aprox 109.592556 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 130.762342 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 131.3183 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 131.513296 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 134.781306 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 104.256126 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 105.23257 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 105.4607 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 108.236676 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities.regular' took aprox 144.324071 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick.entities' took aprox 146.630006 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 161.376957 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 162.288011 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 162.484473 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 164.915029 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 100.698113 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 101.433233 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 101.58483 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 104.196601 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 101.537328 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 103.533615 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 100.197282 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 100.460014 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 102.30353 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 106.353868 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world' took aprox 107.338523 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels' took aprox 107.494227 ms
16:15:59
STDOUT:
Something's taking too long! 'root' took aprox 110.091627 ms
16:15:59
STDOUT:
Something's taking too long! 'root.levels.world.tick' took aprox 101.885095 ms

 

[Captainnana]

I think you need to use a better profiler, try VisualVM on a JMX connection it should help you more

 

[Danjo]

From talking to roxservers this morning it seems they mislead us slightly by saying we were on a dedicated server. Its actually shared hosting so I believe other profilers are out of the question.

 

[damnedsky]

Just as a small suggestion please see this link: Mod code fixes and tweaks.
It's not much but it might help you a little bit for now.

 

[Danjo]

I'll make some of the changes suggested. Quite considering changing hosts too after the whole dedicated issue.

 

[damnedsky]

Don't forget these are brand new mods, some of which are not even out to the public yet, so bugs such as these are not necessarily server related.

 

[Danjo]

We're moving hosts tonight to see what happens, I'll report back on how it affects the tickrate.
Thanks captain and damned

 

[Lathanael]

Do you have installed Millinaire by any chance?

 

[Greedseed]

Don't forget these are brand new mods, some of which are not even out to the public yet, so bugs such as these are not necessarily server related.

Like damnedsky stated here, most of these are brand spanking new versions of mods. There are bound to be problems with them. These will get fixt over time, but keep in mind. A lot of mods and add a couple of players and a "lower" end system can have trouble very soon. Even "medium" systems can run out of power very soon under such server loads.

 

[Danjo]

Do you have installed Millinaire by any chance?

Nope, nothing extra installed.

 

[Greedseed]

Nope, nothing extra installed.

You are runninga only 4 gig of ram. And how many players where exploring the map ?

We ran a 25gig server with top of the line CPU's and if we rolled a new map, 15 players exploring would lower the tick rate dramaticly. Again Mod servers can kill most low to mediam power servers very easy.

 

[GateKeeper258]

I do am having the same problem, on a dual core dedicated system I own, running Linux Mint 14 in command line mode and Sun Java 1.6 64bit, tested on clean 1.5.1 with forge minecraftforge-universal-1.5.1-7.7.2.678.zip and minecraftforge-universal-1.5.1-7.7.2.682.zip as well as 1.5.2 with forge minecraftforge-universal-1.5.2-7.8.0.696.zip. Below is a paste of the log regarding the errors. Also, I tried with Sun Java 1.7 as well with the same results. I will try again without forge for both 1.5.1 and 1.5.2 to see if the problem corrects itself. Just a note, I was running FTB Direwolf20 5.2.1 1.4.7 with no problems at all, but wanted to get to 1.5.x and now getting problems.

2013-05-16 17:06:54 [INFO] [ForgeModLoader] Forge Mod Loader version 5.2.6.696 for Minecraft 1.5.2 loading
2013-05-16 17:06:54 [INFO] [ForgeModLoader] Java is Java HotSpot(TM) 64-Bit Server VM, version 1.6.0_43, running on Linux:amd64:3.5.0-25-generic, installed at /home/shawn/jre1.6.0_43
2013-05-16 17:06:54 [FINE] [ForgeModLoader] Java classpath at launch is minecraftforge-universal-1.5.2-7.8.0.696.zip
2013-05-16 17:06:54 [FINE] [ForgeModLoader] Java library path at launch is /home/shawn/jre1.6.0_43/lib/amd64/server:/home/shawn/jre1.6.0_43/lib/amd64:/home/shawn/jre1.6.0_43/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
 
...
 
2013-05-16 17:07:34 [INFO] [Minecraft-Server] Started debug profiling
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root.levels.world.tick.entities.regular' took aprox 136.063 ms
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root.levels.world.tick.entities' took aprox 151.19684 ms
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root.levels.world.tick' took aprox 164.75068 ms
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root.levels.world' took aprox 166.59336 ms
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root.levels' took aprox 167.78116 ms
2013-05-16 17:07:35 [INFO] [STDOUT] Something's taking too long! 'root' took aprox 168.40784 ms
 
...
 
2013-05-16 17:07:38 [WARNING] [Minecraft-Server] Can't keep up! Did the system time change, or is the server overloaded?
 
...
 
2013-05-16 17:07:42 [INFO] [Minecraft-Server] Stopped debug profiling after 7.24 seconds (125 ticks)
2013-05-16 17:08:18 [INFO] [Minecraft-Server] Stopping the server

 

[rawrEmmy]

Do you have a readme to this profiler tool? Because I can't read a file that doesn't make sense.

For instance :
[03] entities - 83,84%/81,36%
[04] regular - 97,65%/79,44%

Both these lines have the same number of spaces of indentation. This implies they are on the same level. Then how can they add to more than 100%?

This is the default server debug profiler I think. I just found it today but from what I can figure the bracketed numbers denote the "level" of the processes and subprocesses - so [03] would be on the same level as the parent processes of level [04] processes, and child processes of a [04] would be found at level [05]. At least, I'm assuming these are the names of processes and that they work the same as the processes we learned about in class...