Skip to content
This repository has been archived by the owner on Feb 27, 2024. It is now read-only.

Hermitpack lag issues #968

Closed
NyleGarcia opened this issue Oct 18, 2016 · 62 comments
Closed

Hermitpack lag issues #968

NyleGarcia opened this issue Oct 18, 2016 · 62 comments

Comments

@NyleGarcia
Copy link

NyleGarcia commented Oct 18, 2016

@bloodmc @LemADEC refrencing the hermit pack issue that wasnt resolved in ticket #948

hermit pack warmroast
WarmRoasthermitpack.zip
timings
https://timings.aikar.co/v2/?id=f11ff43a4cd447288ecfab1e069e7991

@bloodmc
Copy link
Contributor

bloodmc commented Oct 18, 2016

@Bebabo10 Thanks, I'll investigate this further when I get some more time to spare =)

@bloodmc
Copy link
Contributor

bloodmc commented Oct 18, 2016

@Bebabo10 @LemADEC @hunter688 Please test
https://www.dropbox.com/s/9ll2aa9bi58ptwu/spongeforge-1.10.2-2098-6.0.0-BETA-0.jar?dl=0

Let me know if you notice a difference. I'm troubleshooting an odd issue with this pack.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 18, 2016

Also here is a highly experimental async build

https://www.dropbox.com/s/oy4hu3h4j3cre9w/spongeforge-1.10.2-2098-6.0.0-BETA-async-test1.jar?dl=0

Make sure you backup your entire world before testing this build. DO NOT run in production, i'm not responsible if anything breaks =)

Let me know performance results from this build.

@LemADEC
Copy link

LemADEC commented Oct 18, 2016

Using
forge-1.10.2-12.18.2.2107-universal.jar
spongeforge-1.10.2-2098-6.0.0-BETA-async-test1.jar
Nucleus-0.11.0-S5-1.10.2-plugin.jar
HermitPack 1.1.0 (newest beta)

The /home and /rtp commands fail to teleport unless chunks are already loaded.
The /minecraft:tp command works.
Once I teleport to the lag base (-88 91 742), I can /home to my home base (987 78 2078), but I'm still unable to teleport to other home points.
I did /spawn, waited 2mn then tried again: home and lag base can be reached with /home but not other ones.
So I guess chunks are loading "too slow" and they are never getting unloaded.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 18, 2016

@LemADEC Test the other build I posted as well as latest SF. The async build is highly experimental.

@LemADEC
Copy link

LemADEC commented Oct 18, 2016

image
TPS is still 20 after 90mn uptide, warmroast isn't happy.

@LemADEC
Copy link

LemADEC commented Oct 18, 2016

Trying now with spongeforge-1.10.2-2098-6.0.0-BETA-1819.jar

Teleportation works as expected.
Lag is present. Looks like Forestry bee hives are reloading chunks:
image

@Vauxite
Copy link

Vauxite commented Oct 19, 2016

There seems to be a chunkunloading issue.
https://timings.aikar.co/v2/?id=9e2213b1e5704b90ac0c4f7a7af1ab89

Version:
Minecraft: 1.10.2
SpongeAPI: 6.0.0-SNAPSHOT-73050f3
SpongeForge: 1.10.2-2098-6.0.0-BETA-1818
Minecraft Forge: 12.18.2.2098

@LemADEC
Copy link

LemADEC commented Oct 19, 2016

After fixing Forestry beehive bugs, lag remains:
image

To reproduce, I'm just doing a 10+ random teleportations to load parts of the map, including the lag base and mine.

@LemADEC
Copy link

LemADEC commented Oct 19, 2016

Highlights on the Sponge part on a 10mn acquisition:
image
image

@bloodmc
Copy link
Contributor

bloodmc commented Oct 19, 2016

Test the following builds and report back

https://www.dropbox.com/s/59gzwvso8gko58w/spongeforge-1.10.2-2098-6.0.0-BETA-test1.jar?dl=0
https://www.dropbox.com/s/5stru9a51zmzf5u/spongeforge-1.10.2-2098-6.0.0-BETA-test2.jar?dl=0

Let me know which build is best and if both perform better than build 1819

@NyleGarcia
Copy link
Author

http://pastebin.com/ubAxthrM
when using test2 will share the warm roast next time we restart the build you gave us for all the mods has been running on just at certain times the server starts to drop in tps.

@NyleGarcia
Copy link
Author

WarmRoast.zip

@Vauxite
Copy link

Vauxite commented Oct 19, 2016

@bloodmc
Tested the 2nd one first,
https://timings.aikar.co/v2/?id=54b41389d49a4f04be4072fabe6ea2ba
Will test the other one on next restart.

@LemADEC
Copy link

LemADEC commented Oct 19, 2016

With beta-test1, lag is initially severely reduced during the first 10mn profiling:
image
then I've restarted the profiler (still no moving from my base), and we can see it's actually lagging (11mn profiling):
image
image

With beta-test2, lag is initially reduced but worse than beta-test1, during first 10mn profiling:
image
after restarting the profiler, waiting 10mn, lag is gone:
https://gyazo.com/a0104645b53a64f8fa351d0c6877f7c1
image

I did a few more tests and overall, beta-test2 was the only one able to unload the laggy base (1/3 success vs 0/3), but overall beta-test1 is less laggy.

@Vauxite
Copy link

Vauxite commented Oct 20, 2016

@LemADEC
Copy link

LemADEC commented Oct 21, 2016

According to our players, spongeforge-1.10.2-2098-bleeding-BETA-TEST1 is better than spongeforge-1.10.2-2098-6.0.0-BETA-1823.
In both cases, chunk-gc was disabled, if that makes any sense.

Looks like the lag increase was in fact due to a buggy tile entity from Mekanism or QuantumTanks.

@NyleGarcia
Copy link
Author

its looking like refined storage and sponge may be causing the issue with hermit pack https://i.gyazo.com/49f7796102cb651250fcfc0871df10b9.png

@NyleGarcia
Copy link
Author

WarmRoast.zip

@bloodmc
Copy link
Contributor

bloodmc commented Oct 21, 2016

@Bebabo10 Does that lag occur everytime you go to a specific area? If so, upload your world so I can test it. I also have your old world, if you tell me the location I can see if it occurs.

Also, please test the same area with Forge only and let me know if lag persists.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 21, 2016

@Vauxite Looks like forestry's swarm is causing most of your lag. Is there a way you can setup a world with JUST forestry and try to reproduce the lag? I can then test it on my end.

@NyleGarcia
Copy link
Author

@NyleGarcia
Copy link
Author

Found the issue now its at 20 tps again

@bloodmc
Copy link
Contributor

bloodmc commented Oct 22, 2016

@Bebabo10 Please try the same issue without Sponge and let me know if it occurs. I'm curious if Sponge is causing the lag issue.

@NyleGarcia
Copy link
Author

https://www.dropbox.com/s/r4s2e79mjdwicak/world-hermitpack.zip?dl=1 hope you got good Internet its a 3.8gb world and will test without Forge tomorrow when player count is low

@bloodmc
Copy link
Contributor

bloodmc commented Oct 22, 2016

@Bebabo10 What is the lag location?

@bloodmc
Copy link
Contributor

bloodmc commented Oct 22, 2016

@Bebabo10 @LemADEC @Vauxite @hunter688 Please test SF 1826. It should solve the chunk unloading issue where performance slowly declines. I also optimized a few areas for chunk lookups.

@NyleGarcia
Copy link
Author

@bloodmc What do you mean chunk lookup? and it is very difficult to find the source of the lag when your live testing ,will try to get tick profiler to work again to more easily find the locations.

@ghost
Copy link

ghost commented Oct 23, 2016

potion fixed with 1830

@LemADEC
Copy link

LemADEC commented Oct 23, 2016

We've updated to spongeforge-1.10.2-2107-6.0.0-BETA-0.jar
and changed chunk-unload-delay to 0

Inventory issue persist with IC2 Jetpacks and weaponcase:weaponsword. No other inventory issue in sight so far.
Lag is still present.
Profiler shows some IC2 cable reloading chunks:
image

@LemADEC
Copy link

LemADEC commented Oct 23, 2016

We had a server hang with spongeforge-1.10.2-2107-6.0.0-BETA-0.jar

  • There was no response on console
  • Warmroast and Java debug tools were unable to connect
  • kill -3 had no effect either
  • forced server heap dump is available but only 28MB and fails to load in Eclipse MAT

A few minutes before that, one player was unable to move his ic2:bronze_leggings. I couldn't reproduce it with my inventory. Rebooting didn't help.

Since at least build 1830, we're seeing CME exceptions during world saving:

[21:43:13] [main/INFO] [mixin]: SpongePowered MIXIN Subsystem Version=0.5.17 Source=file:/home/hermitpack/mods/spongeforge-1.10.2-2107-6.0.0-BETA-1830.jar Env=SERVER
...
[01:43:27] [main/INFO] [mixin]: SpongePowered MIXIN Subsystem Version=0.5.17 Source=file:/home/hermitpack/mods/spongeforge-1.10.2-2107-6.0.0-BETA-1830.jar Env=SERVER
...
[02:06:03] [File IO Thread/ERROR]: Failed to save chunk
java.util.ConcurrentModificationException
>       at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_101]
>       at java.util.HashMap$KeyIterator.next(HashMap.java:1461) ~[?:1.8.0_101]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:23) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_150663_a(CompressedStreamTools.java:111) ~[ea.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_74800_a(CompressedStreamTools.java:101) ~[ea.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_183013_b(AnvilChunkLoader.java:242) ~[atj.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75814_c(AnvilChunkLoader.java:220) [atj.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.func_75736_b(SourceFile:37) [bbu.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.run(SourceFile:30) [bbu.class:?]
>       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
...
[05:43:42] [main/INFO] [mixin]: SpongePowered MIXIN Subsystem Version=0.5.17 Source=file:/home/hermitpack/mods/spongeforge-1.10.2-2107-6.0.0-BETA-0.jar Env=SERVER
...
[06:07:33] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 6034ms behind, skipping 120 tick(s)
[06:07:36] [File IO Thread/ERROR]: Failed to save chunk
java.util.ConcurrentModificationException
>       at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_101]
>       at java.util.HashMap$KeyIterator.next(HashMap.java:1461) ~[?:1.8.0_101]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:23) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_150663_a(CompressedStreamTools.java:111) ~[ea.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_74800_a(CompressedStreamTools.java:101) ~[ea.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_183013_b(AnvilChunkLoader.java:242) ~[atj.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75814_c(AnvilChunkLoader.java:220) [atj.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.func_75736_b(SourceFile:37) [bbu.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.run(SourceFile:30) [bbu.class:?]
>       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
[06:07:39] [Server thread/INFO]: Admin LemADEC: is anyone exploring the world right now?
...
[06:52:16] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 4658ms behind, skipping 93 tick(s)
[06:52:19] [File IO Thread/ERROR]: Failed to save chunk
java.util.ConcurrentModificationException
>       at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_101]
>       at java.util.HashMap$KeyIterator.next(HashMap.java:1461) ~[?:1.8.0_101]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:23) ~[dr.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_150663_a(CompressedStreamTools.java:111) ~[ea.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_74800_a(CompressedStreamTools.java:101) ~[ea.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_183013_b(AnvilChunkLoader.java:242) ~[atj.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75814_c(AnvilChunkLoader.java:220) [atj.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.func_75736_b(SourceFile:37) [bbu.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.run(SourceFile:30) [bbu.class:?]
>       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
[06:52:54] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 17279ms behind, skipping 345 tick(s)
...
[08:58:39] [main/INFO] [FML]: Loading tweaker org.spongepowered.asm.launch.MixinTweaker from spongeforge-1.10.2-2107-6.0.0-BETA-0.jar
...
[09:01:55] [Server thread/INFO]: Simpleriz lost connection: Disconnected
[09:01:55] [Server thread/INFO]: Simpleriz left the game
RemoteToolkit plugin for Bukkit was not detected. Disabling heartbeat until next restart.
[09:02:58] [File IO Thread/ERROR]: Failed to save chunk
java.util.ConcurrentModificationException
>       at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_101]
>       at java.util.HashMap$KeyIterator.next(HashMap.java:1461) ~[?:1.8.0_101]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:23) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_150663_a(CompressedStreamTools.java:111) ~[ea.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_74800_a(CompressedStreamTools.java:101) ~[ea.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_183013_b(AnvilChunkLoader.java:242) ~[atj.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75814_c(AnvilChunkLoader.java:220) [atj.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.func_75736_b(SourceFile:37) [bbu.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.run(SourceFile:30) [bbu.class:?]
>       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
[09:03:01] [Server thread/INFO] [nucleus]: 2muChPride ran the command: /home ha
[09:03:03] [Server thread/ERROR] [Sponge]: No entity type is registered for class crazypants.enderio.machine.killera.TileKillerJoe$Attackera
...
[09:03:18] [Server thread/INFO]: BLK_WARRIOR joined the game
[09:03:18] [Server thread/INFO] [STDOUT]: [mcjty.lib.preferences.PreferencesProperties:syncToClient:31]: syncToClient: style = STYLE_FLAT_GRADIENT
[09:03:19] [File IO Thread/ERROR]: Failed to save chunk
java.util.ConcurrentModificationException
>       at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_101]
>       at java.util.HashMap$KeyIterator.next(HashMap.java:1461) ~[?:1.8.0_101]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:23) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagList.func_74734_a(SourceFile:45) ~[dx.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_150298_a(NBTTagCompound.java:453) ~[dr.class:?]
>       at net.minecraft.nbt.NBTTagCompound.func_74734_a(NBTTagCompound.java:26) ~[dr.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_150663_a(CompressedStreamTools.java:111) ~[ea.class:?]
>       at net.minecraft.nbt.CompressedStreamTools.func_74800_a(CompressedStreamTools.java:101) ~[ea.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_183013_b(AnvilChunkLoader.java:242) ~[atj.class:?]
>       at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75814_c(AnvilChunkLoader.java:220) [atj.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.func_75736_b(SourceFile:37) [bbu.class:?]
>       at net.minecraft.world.storage.ThreadedFileIOBase.run(SourceFile:30) [bbu.class:?]
>       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
[09:03:22] [Server thread/WARN] [Sponge]: Unable to find InventoryPacketState handler for click window packet: CPacketClickWindow{windowId=5, slotId=-999, usedButton=4, actionNumber=1, clickedItem=null, mode=QUICK_CRAFT}
[09:03:24] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 5498ms behind, skipping 109 tick(s)
...

Those exceptions won't show up in log files saved by Forge, for unknown reason, so I'm unable to confirm when it started.

We've rolled back to the API 5 bleeding version for now.

@gabizou
Copy link
Member

gabizou commented Oct 24, 2016

Just going to mention that the API 5 bleeding version is not the same as API 5 stable version.

Another note: I do have a distaste for Torcherino, mostly because it masks performance by calling additional tile updates:

torcherino

As an example, this is calling neighboring blocks updates, including blocks that generally are unperformant, even if harmless (such as grass or snow).

@bloodmc
Copy link
Contributor

bloodmc commented Oct 24, 2016

@Bebabo10 @LemADEC @Vauxite @hunter688 Please test SF 1835 and report back. Also make sure to test with chunk-gc-tick-interval enabled as I've fixed the major issue causing slowdowns with it. Feel free to experiment as well with chunk-unload-delay between 0-30.

@NyleGarcia
Copy link
Author

@bloodmc fixed in build 1835

@LemADEC
Copy link

LemADEC commented Oct 24, 2016

For the record, Torcherino was disabled in all my testings.

Lag base still remains chunkloaded, lag is getting better but it's still present on this 2 mn profiling:
image
image
This is with chunk-gc interval 1 and delay 0.

Inventory issue with Jetpack is still present => is there a separate issue to track it?

@NyleGarcia
Copy link
Author

@bloodmc
Copy link
Contributor

bloodmc commented Oct 24, 2016

@LemADEC TrackingUtil simply wraps around each TE tick so we can capture relevant information and the real slowdown is with whatever TE it is showing so I would report to the mod dev as that is not a sponge issue.

Report any performance issues with refined storage here

https://github.com/raoulvdberge/refinedstorage/issues

@LemADEC
Copy link

LemADEC commented Oct 24, 2016

@bloodmc My concern is about java.utils.ArrayList.removeAll taking 14% CPU. To me this indicates chunks are in constant reloading.
On server we had to disable chunk-gc again because lag was way worse with it (more than 150ms per tick).
I wish we had a mod/plugin monitoring 'fast chunk reloads' to help identify such bogus behavior.

Have we considered reimplementing the Cauldron (?) trick that disables TE update ticks when no players are in vicinity?

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC Set the following in your config

mob-spawn-range 4
chunk-gc-tick-interval 1
chunk-unload-delay 0
max-chunk-unloads-per-tick=100
auto-save-interval 6000

If the issue still occurs, turn on debug logging by setting the following to true
chunk-load=true
chunk-unload=true
log-stacktraces=true

Once this is done, simply execute
/sponge reload -g
This will refresh the global config.
Note: This will cause major spam as chunks load/unload but it will show exactly whats causing it. When done with debug, simply set them back to false and run the same command again.

Also upload your world and let me know the location where this lag is occuring and provide a timings report (not warmroast).

@LemADEC
Copy link

LemADEC commented Oct 25, 2016

@bloodmc timings isn't a valid sub command when I type "/sponge timings" or "/sponge timings -g"

To reproduce quickly, I go the lag base (same world and coordinates I've posted last week: -99 91 753), then do 20 times /rtp (using Nucleus plugin, with 30 attempts at 3000 radius), then go back to my base.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC For sponge timings the command would be

/sponge timings on
wait a few minutes
/sponge timings paste

When done with timings,
/sponge timings off

I still need the output from the chunk load/unload debug. Follow what i said above and report back with the logs.

@LemADEC
Copy link

LemADEC commented Oct 25, 2016

@bloodmc Server console logger crashed due to the spam so I couldn't get the timings. Here's the logs:
It probably crashed too soon after enabling logs to see much, I'll try again later this week with a larger buffer.

@LemADEC
Copy link

LemADEC commented Oct 25, 2016

Please remove the link once you've got it.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC Thanks, I was able to reproduce the issue. Working on a fix.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC Turns out some logic was wrong in my chunkgc handler. I'll be pushing a fix shortly =) Looks like everything is working perfectly now, just need to test a bit more.

bloodmc added a commit to SpongePowered/Sponge that referenced this issue Oct 25, 2016
Many mods, including vanilla, tend to leak chunks which end up causing
extra processing for our Chunk GC as it has to constantly queue the same
chunks for unload everytime. The biggest offending methods are
getBlockState and getChunkFromBlockCoords. Both of these methods will load
or generate a chunk that does not exist.

To avoid this, we now validate the phase and/or state to determine whether
or not a chunk request should be allowed to load.
Note: This feature can be disabled by setting denyChunkRequests to false
in config.

* Fix ChunkGC adding duplicate chunks to unload queue.
* If chunk unload delay is configured, schedule unloads for chunk leaks.
  This prevents chunk leaks from immediately unloading at end of tick.

Fixes SpongePowered/SpongeForge#968
Fixes SpongePowered/SpongeForge#980
@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC Please test latest build and confirm that the lag is fixed. I would recommend keeping the chunk delay at around 15. There were problems with this in earlier builds due to the ChunkGC logic not being correct. I also introduced some optimizations to fight against mods that leak chunks.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

I'm pushing a better build, so just wait for next one.

@bloodmc
Copy link
Contributor

bloodmc commented Oct 25, 2016

@LemADEC @Bebabo10 @Vauxite @hunter688 Please test SF 1841. It should solve this issue once and for all =). Before you run the build, make sure you change the following defaults in config

chunk-gc-tick-interval - 600
chunk-unload-delay - 15

The chunk gc will now run once every 30 seconds to cleanup any chunks that leaked. The chunk unload delay is only for player chunks (doesn't affect leaks). So if a chunk that was used by a player is not used within 15 seconds, it unloads. If it gets active before unload, the timer resets.

@LemADEC
Copy link

LemADEC commented Oct 27, 2016

The lag appears to be gone for the most part. Here's a timings report about
10mn after my lag stress test:
https://timings.aikar.co/v2/?id=8dff316c281143f988b370fb5217590e

Sadly, we're observing a lot of IC2 crashes since we've deployed the latest
fix. The pattern was there before when players where dismounting IC2
consumers. It's a bit too soon to conclude if the last sponge changes are
causing it with the chunk gc. We've disabled the latest for now and will
see how it goes. Here's the typical pattern observed:
'''
java.lang.NullPointerException: Exception in server tick loop
at
ic2.core.energy.leg.EnergyNetLocalLeg.emitEnergyFrom(EnergyNetLocalLeg.java:341)
at
ic2.core.energy.leg.EnergyNetLocalLeg.tickEnd(EnergyNetLocalLeg.java:144)
at ic2.core.energy.leg.EventHandler.preTick(EventHandler.java:46)
at
net.minecraftforge.fml.common.eventhandler.ASMEventHandler_189_EventHandler_preTick_WorldTickEvent.invoke(.dynamic)
at
net.minecraftforge.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:90)
at
net.minecraftforge.fml.common.eventhandler.EventBus.post(EventBus.java:130)
at
net.minecraftforge.fml.common.eventhandler.EventBus.post(EventBus.java:99)
at
net.minecraftforge.fml.common.FMLCommonHandler.onPostWorldTick(FMLCommonHandler.java:269)
at
net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:718)
at
net.minecraft.server.dedicated.DedicatedServer.func_71190_q(DedicatedServer.java:387)
at
net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:613)
at
net.minecraft.server.MinecraftServer.run(MinecraftServer.java:471)
at java.lang.Thread.run(Thread.java:745)
'''

2016-10-25 19:43 GMT+02:00 bloodmc notifications@github.com:

@LemADEC https://github.com/LemADEC @Bebabo10
https://github.com/Bebabo10 @Vauxite https://github.com/Vauxite
@hunter688 https://github.com/hunter688 Please test SF 1841. It should
solve this issue once and for all =). Before you run the build, make sure
you change the following defaults in config

chunk-gc-tick-interval - 600
chunk-unload-delay - 15

The chunk gc will now run once every 30 seconds to cleanup any chunks that
leaked. The chunk unload delay is only for player chunks (doesn't affect
leaks). So if a chunk that was used by a player is not used within 15
seconds, it unloads. If it gets active before unload, the timer resets.


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#968 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEjgYEUifYVtkvpMLbOjPXqj7y190iQKks5q3j-vgaJpZM4KZThN
.

@Aroma1997
Copy link

That crash is caused by an IC2 addon not using the API correctly. My guess: calculator.
In a newer build of IC2, we changed that to log the error instead of crashing the game. Try updating your IC2 version.

@LemADEC
Copy link

LemADEC commented Oct 28, 2016

This is from the FTB HermitPack 1.1.0 version, Calculator isn't part of that pack. However TechReborn and Mekanism are in.
Will the log give a block name or at least a mod name so we know where to look for?

@Aroma1997
Copy link

If you update your IC2 version, it will.

gabizou pushed a commit to SpongePowered/Sponge that referenced this issue Nov 17, 2016
Many mods, including vanilla, tend to leak chunks which end up causing
extra processing for our Chunk GC as it has to constantly queue the same
chunks for unload everytime. The biggest offending methods are
getBlockState and getChunkFromBlockCoords. Both of these methods will load
or generate a chunk that does not exist.

To avoid this, we now validate the phase and/or state to determine whether
or not a chunk request should be allowed to load.
Note: This feature can be disabled by setting denyChunkRequests to false
in config.

* Fix ChunkGC adding duplicate chunks to unload queue.
* If chunk unload delay is configured, schedule unloads for chunk leaks.
  This prevents chunk leaks from immediately unloading at end of tick.

Fixes SpongePowered/SpongeForge#968
Fixes SpongePowered/SpongeForge#980

Conflicts:
	src/main/java/org/spongepowered/common/interfaces/world/gen/IMixinChunkProviderServer.java
	src/main/java/org/spongepowered/common/mixin/core/world/gen/MixinChunkProviderServer.java
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

8 participants