SleepyTrousers / EnderIO-1.5-1.12

http://enderio.com/
The Unlicense
729 stars 362 forks source link

Conduit Bundle low TPS #4457

Closed WolfeyWolfey closed 6 years ago

WolfeyWolfey commented 6 years ago

Issue Description:

It occurs in modpack, but when the mod is isolated the issue still occurs. I'm pasting the timings from the other mods enabled as well. Currently disabling conduit bundles to see if that alleviates the issue.

What happens:

Incredibly high TPS usage with only ~800 conduit bundles in the world.

Timings: https://timings.aikar.co/?id=bbe37e8316f14ef384a0e0cfe149aab8

What you expected to happen:

Normal tick rate for a block like this.

Steps to reproduce:

  1. Place a large/moderate amount of conduit bundles in the world, connected to machines.
  2. Leave server running for ~1 hour
  3. Low TPS and other performance issues. ...

Affected Versions (Do not use "latest"):

Your most recent log file where the issue was present:

No logs would be generated from this issue, though, I can provide debug information from the world snapshot.

[pastebin/gist/etc link here]

WolfeyWolfey commented 6 years ago

Just an update, disabling MEConduits and OCConduits seems to help alleviate some of the TPS issues, but blockConduitBundleTileEntity is still topping the charts, with very few of them actually in the world.

WolfeyWolfey commented 6 years ago

Including the timing report of the server with OC Conduits and ME conduits disabled. That seemed to be the culprit.

https://timings.aikar.co/?id=c0c3cbbf36894078b9148a14747604b7

HenryLoenwind commented 6 years ago

Don't use aikar timings, use the vanilla profiler.

https://www.reddit.com/r/feedthebeast/comments/5mxn51/vanilla_has_an_built_in_profiler_that_not_a_lot/

WolfeyWolfey commented 6 years ago

Didn't know vanilla even had that... I'm still getting very high tick time from bundles, but I'll take a vanilla reading of timings as well, will paste after I let it run for a bit.

Any reason not to use aikar? I've been using them for quite a while now.

WolfeyWolfey commented 6 years ago

`---- Minecraft Profiler Results ---- // Hello world

Time span: 483397 ms Tick span: 9334 ticks // This is approximately 19.31 ticks per second. It should be 20 ticks per second

--- BEGIN PROFILE DUMP ---

--- END PROFILE DUMP --- `

Going to assume this is not the desired results. Will be pulling the world tonight to test it without spongeforge entirely, but, that is the debug result from /debug on, /debug off.

HenryLoenwind commented 6 years ago

aikar attributes everything to one thing unless it uses an event to trigger other things. That doesn't work very well with Forge mods that use capabilities and interfaces to talk to each other. So no matter which code causes the lag, if it's connected to a conduit aikar will blame the conduit bundle for it.

You see the same with the Farming station---not a single plant or block update under it. Just as if the Farming Station was just sitting there and burning CPU cycles to mine Bitcoin. Nope. 90% of the farm time is talking to plants, asking them if they are fully grown, asking them for their drops or resetting them to their "freshly planted" state.

Conduits are hit especially hard by this, as most they do is talking to other blocks.

PS: And yes, something definitely is suppressing the vanilla profiler. It should look like this: https://gist.github.com/HenryLoenwind/5f0caf24365c14bcc17bae8cd3ec5817

dreeadnought commented 6 years ago

I am having quite a bit of lag as well on my server Enclosed is the minecraft profiler and its results

---- Minecraft Profiler Results ----
// Maybe if you treated it better then it'll have more motivation to work faster! Poor server.

Time span: 73584 ms
Tick span: 1468 ticks
// This is approximately 19.95 ticks per second. It should be 20 ticks per second

--- BEGIN PROFILE DUMP ---

[00] levels - 96.74%/96.74%
[01] |   Biome Bundle - 99.81%/96.56%
[02] |   |   tick - 99.64%/96.22%
[03] |   |   |   entities - 88.28%/84.94%
[04] |   |   |   |   blockEntities - 91.85%/78.02%
[05] |   |   |   |   |   .conduitBundle - 60.67%/47.34%
[06] |   |   |   |   |   |   tick - 89.11%/42.18%
[07] |   |   |   |   |   |   |   unspecified - 99.47%/41.96%
[07] |   |   |   |   |   |   |   neigborUpdate - 0.53%/0.22%
[06] |   |   |   |   |   |   unspecified - 10.89%/5.15%
[05] |   |   |   |   |   unspecified - 34.62%/27.01%
[05] |   |   |   |   |   .blockInventoryChest - 2.07%/1.61%
[06] |   |   |   |   |   |   serverTick - 88.50%/1.43%
[07] |   |   |   |   |   |   |   tasks - 81.07%/1.16%
[07] |   |   |   |   |   |   |   unspecified - 18.35%/0.26%
[07] |   |   |   |   |   |   |   sideIO - 0.59%/0.01%
[06] |   |   |   |   |   |   unspecified - 11.50%/0.19%
[05] |   |   |   |   |   .blockAlloySmelter - 0.72%/0.57%
[06] |   |   |   |   |   |   serverTick - 95.94%/0.54%
[07] |   |   |   |   |   |   |   sideIO - 87.99%/0.48%
[07] |   |   |   |   |   |   |   unspecified - 7.81%/0.04%
[07] |   |   |   |   |   |   |   tasks - 3.19%/0.02%
[07] |   |   |   |   |   |   |   clientNotification - 1.01%/0.01%
[06] |   |   |   |   |   |   unspecified - 4.06%/0.02%
[05] |   |   |   |   |   .blockFarmStation - 0.44%/0.34%
[06] |   |   |   |   |   |   serverTick - 95.76%/0.33%
[07] |   |   |   |   |   |   |   tasks - 83.43%/0.27%
[07] |   |   |   |   |   |   |   unspecified - 8.94%/0.03%
[07] |   |   |   |   |   |   |   clientNotification - 6.93%/0.02%
[07] |   |   |   |   |   |   |   sideIO - 0.70%/0.00%
[06] |   |   |   |   |   |   unspecified - 4.24%/0.01%
[05] |   |   |   |   |   .blockVat - 0.43%/0.34%
[06] |   |   |   |   |   |   serverTick - 96.02%/0.32%
[07] |   |   |   |   |   |   |   tasks - 87.09%/0.28%
[07] |   |   |   |   |   |   |   unspecified - 8.46%/0.03%
[07] |   |   |   |   |   |   |   clientNotification - 3.01%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 1.45%/0.00%
[06] |   |   |   |   |   |   unspecified - 3.98%/0.01%
[05] |   |   |   |   |   .blockTransceiver - 0.43%/0.33%
[06] |   |   |   |   |   |   serverTick - 91.63%/0.31%
[07] |   |   |   |   |   |   |   tasks - 63.57%/0.19%
[07] |   |   |   |   |   |   |   unspecified - 23.00%/0.07%
[07] |   |   |   |   |   |   |   clientNotification - 9.12%/0.03%
[07] |   |   |   |   |   |   |   sideIO - 4.30%/0.01%
[06] |   |   |   |   |   |   unspecified - 8.37%/0.03%
[05] |   |   |   |   |   .blockPoweredSpawner - 0.18%/0.14%
[06] |   |   |   |   |   |   serverTick - 81.36%/0.11%
[07] |   |   |   |   |   |   |   unspecified - 57.08%/0.07%
[07] |   |   |   |   |   |   |   clientNotification - 35.66%/0.04%
[07] |   |   |   |   |   |   |   tasks - 4.64%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 2.62%/0.00%
[06] |   |   |   |   |   |   unspecified - 18.64%/0.03%
[05] |   |   |   |   |   .blockSpawnGuard - 0.13%/0.10%
[06] |   |   |   |   |   |   serverTick - 84.59%/0.09%
[07] |   |   |   |   |   |   |   unspecified - 46.92%/0.04%
[07] |   |   |   |   |   |   |   clientNotification - 33.31%/0.03%
[07] |   |   |   |   |   |   |   tasks - 18.47%/0.02%
[07] |   |   |   |   |   |   |   sideIO - 1.30%/0.00%
[06] |   |   |   |   |   |   unspecified - 15.41%/0.02%
[05] |   |   |   |   |   .blockInhibitorObelisk - 0.06%/0.05%
[06] |   |   |   |   |   |   serverTick - 88.84%/0.04%
[07] |   |   |   |   |   |   |   clientNotification - 54.17%/0.02%
[07] |   |   |   |   |   |   |   unspecified - 38.67%/0.02%
[07] |   |   |   |   |   |   |   tasks - 6.19%/0.00%
[07] |   |   |   |   |   |   |   sideIO - 0.97%/0.00%
[06] |   |   |   |   |   |   unspecified - 11.16%/0.01%
[05] |   |   |   |   |   .blockSoulBinder - 0.06%/0.04%
[06] |   |   |   |   |   |   serverTick - 81.42%/0.04%
[07] |   |   |   |   |   |   |   unspecified - 59.26%/0.02%
[07] |   |   |   |   |   |   |   tasks - 21.05%/0.01%
[07] |   |   |   |   |   |   |   clientNotification - 18.04%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 1.66%/0.00%
[06] |   |   |   |   |   |   unspecified - 18.58%/0.01%
[05] |   |   |   |   |   .blockExperienceObelisk - 0.05%/0.04%
[06] |   |   |   |   |   |   serverTick - 67.15%/0.03%
[07] |   |   |   |   |   |   |   unspecified - 80.36%/0.02%
[07] |   |   |   |   |   |   |   tasks - 13.49%/0.00%
[07] |   |   |   |   |   |   |   sideIO - 6.15%/0.00%
[06] |   |   |   |   |   |   unspecified - 32.85%/0.01%
[05] |   |   |   |   |   .blockSagMill - 0.04%/0.03%
[06] |   |   |   |   |   |   serverTick - 64.57%/0.02%
[07] |   |   |   |   |   |   |   unspecified - 62.11%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 22.68%/0.01%
[07] |   |   |   |   |   |   |   tasks - 15.21%/0.00%
[06] |   |   |   |   |   |   unspecified - 35.43%/0.01%
[05] |   |   |   |   |   .blockSliceAndSplice - 0.04%/0.03%
[06] |   |   |   |   |   |   serverTick - 86.42%/0.03%
[07] |   |   |   |   |   |   |   tasks - 67.24%/0.02%
[07] |   |   |   |   |   |   |   unspecified - 31.85%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 0.91%/0.00%
[06] |   |   |   |   |   |   unspecified - 13.58%/0.00%
[05] |   |   |   |   |   .blockPainter - 0.04%/0.03%
[06] |   |   |   |   |   |   serverTick - 84.57%/0.02%
[07] |   |   |   |   |   |   |   tasks - 48.34%/0.01%
[07] |   |   |   |   |   |   |   unspecified - 30.76%/0.01%
[07] |   |   |   |   |   |   |   sideIO - 20.91%/0.00%
[06] |   |   |   |   |   |   unspecified - 15.43%/0.00%
[05] |   |   |   |   |   .getBrightness - 0.00%/0.00%
[05] |   |   |   |   |   .checkedPosition < toCheckCount - 0.00%/0.00%
[04] |   |   |   |   regular - 7.25%/6.16%
[05] |   |   |   |   |   tick - 91.53%/5.63%
[06] |   |   |   |   |   |   unspecified - 39.96%/2.25%
[06] |   |   |   |   |   |   travel - 22.81%/1.29%
[07] |   |   |   |   |   |   |   move - 52.80%/0.68%
[07] |   |   |   |   |   |   |   rest - 26.11%/0.34%
[07] |   |   |   |   |   |   |   unspecified - 21.09%/0.27%
[06] |   |   |   |   |   |   ai - 14.80%/0.83%
[07] |   |   |   |   |   |   |   newAi - 94.57%/0.79%
[08] |   |   |   |   |   |   |   |   unspecified - 28.02%/0.22%
[08] |   |   |   |   |   |   |   |   goalSelector - 27.36%/0.22%
[09] |   |   |   |   |   |   |   |   |   goalSetup - 64.08%/0.14%
[09] |   |   |   |   |   |   |   |   |   unspecified - 29.58%/0.06%
[09] |   |   |   |   |   |   |   |   |   goalTick - 6.35%/0.01%
[08] |   |   |   |   |   |   |   |   controls - 19.56%/0.15%
[09] |   |   |   |   |   |   |   |   |   unspecified - 57.29%/0.09%
[09] |   |   |   |   |   |   |   |   |   look - 25.27%/0.04%
[09] |   |   |   |   |   |   |   |   |   jump - 8.89%/0.01%
[09] |   |   |   |   |   |   |   |   |   move - 8.55%/0.01%
[08] |   |   |   |   |   |   |   |   targetSelector - 14.42%/0.11%
[09] |   |   |   |   |   |   |   |   |   goalSetup - 56.75%/0.06%
[09] |   |   |   |   |   |   |   |   |   unspecified - 43.25%/0.05%
[08] |   |   |   |   |   |   |   |   checkDespawn - 3.57%/0.03%
[08] |   |   |   |   |   |   |   |   mob tick - 2.97%/0.02%
[08] |   |   |   |   |   |   |   |   navigation - 2.42%/0.02%
[08] |   |   |   |   |   |   |   |   sensing - 1.68%/0.01%
[07] |   |   |   |   |   |   |   unspecified - 5.43%/0.05%
[06] |   |   |   |   |   |   entityBaseTick - 6.72%/0.38%
[07] |   |   |   |   |   |   |   unspecified - 94.53%/0.36%
[07] |   |   |   |   |   |   |   portal - 5.47%/0.02%
[06] |   |   |   |   |   |   move - 5.64%/0.32%
[06] |   |   |   |   |   |   livingEntityBaseTick - 5.01%/0.28%
[06] |   |   |   |   |   |   rest - 1.78%/0.10%
[06] |   |   |   |   |   |   push - 1.06%/0.06%
[06] |   |   |   |   |   |   mobBaseTick - 0.51%/0.03%
[06] |   |   |   |   |   |   chunkCheck - 0.50%/0.03%
[06] |   |   |   |   |   |   headTurn - 0.48%/0.03%
[06] |   |   |   |   |   |   portal - 0.21%/0.01%
[06] |   |   |   |   |   |   rangeChecks - 0.20%/0.01%
[06] |   |   |   |   |   |   looting - 0.16%/0.01%
[06] |   |   |   |   |   |   jump - 0.16%/0.01%
[05] |   |   |   |   |   unspecified - 8.09%/0.50%
[05] |   |   |   |   |   remove - 0.37%/0.02%
[04] |   |   |   |   pendingBlockEntities - 0.73%/0.62%
[04] |   |   |   |   unspecified - 0.15%/0.13%
[04] |   |   |   |   remove - 0.01%/0.01%
[04] |   |   |   |   global - 0.00%/0.00%
[04] |   |   |   |   players - 0.00%/0.00%
[03] |   |   |   tickBlocks - 7.25%/6.97%
[04] |   |   |   |   pollingChunks - 99.07%/6.91%
[05] |   |   |   |   |   tickBlocks - 86.60%/5.98%
[06] |   |   |   |   |   |   randomTick - 59.41%/3.55%
[06] |   |   |   |   |   |   unspecified - 40.59%/2.43%
[05] |   |   |   |   |   unspecified - 9.28%/0.64%
[05] |   |   |   |   |   forcedChunkLoading - 2.05%/0.14%
[05] |   |   |   |   |   iceandsnow - 0.95%/0.07%
[05] |   |   |   |   |   tickChunk - 0.44%/0.03%
[06] |   |   |   |   |   |   unspecified - 88.48%/0.03%
[06] |   |   |   |   |   |   recheckGaps - 11.52%/0.00%
[05] |   |   |   |   |   thunder - 0.20%/0.01%
[05] |   |   |   |   |   getChunk - 0.19%/0.01%
[05] |   |   |   |   |   checkNextLight - 0.17%/0.01%
[05] |   |   |   |   |   regularChunkLoading - 0.12%/0.01%
[04] |   |   |   |   unspecified - 0.86%/0.06%
[04] |   |   |   |   playerCheckLight - 0.07%/0.00%
[03] |   |   |   tickPending - 1.46%/1.41%
[04] |   |   |   |   ticking - 90.84%/1.28%
[04] |   |   |   |   unspecified - 4.77%/0.07%
[04] |   |   |   |   cleaning - 4.39%/0.06%
[03] |   |   |   unspecified - 1.44%/1.38%
[03] |   |   |   chunkSource - 1.15%/1.11%
[03] |   |   |   mobSpawner - 0.35%/0.33%
[03] |   |   |   chunkMap - 0.04%/0.03%
[03] |   |   |   portalForcer - 0.02%/0.02%
[03] |   |   |   village - 0.02%/0.02%
[02] |   |   tracker - 0.28%/0.27%
[02] |   |   unspecified - 0.07%/0.07%
[02] |   |   timeSync - 0.01%/0.01%
[01] |   unspecified - 0.19%/0.18%
[00] save - 3.11%/3.11%
[00] unspecified - 0.09%/0.09%
[00] tickables - 0.03%/0.03%
[00] connection - 0.01%/0.01%
[00] jobs - 0.01%/0.01%
[00] players - 0.01%/0.01%
[00] dim_unloading - 0.00%/0.00%
[00] snooper - 0.00%/0.00%
[00] tallying - 0.00%/0.00%
--- END PROFILE DUMP ---