Terasology: Substantial performance issues in latest JS, possibly spawning at 0,0,0 in multiplayer

[Cervator]

What you were trying to do

Play test recent JoshariasSurvival with @ktksan's awesome new GSOC biome stuff, including enabling of WildAnimals and some temperature maps.

After initial play testing also lagged wildly at times even in single player https://github.com/Terasology/WildAnimals/pull/58 was submitted to cut excessive deer spawn. This appears to have helped _some_

Timeouts may also have been helped _some_ by #4113 - you really need to be patient in some cases trying to join!

What actually happened

We had a variety of problems just trying to get a server stable, extensive load times, timeout failures trying to spawn in the world, massive lag spikes on the server with players trying to join/leave, to the point where a hosting client might completely stall for a minute or two while a client tries to join.

A weird consequence appears to be when you _do_ finally spawn you might be embedded deep in the ground _on the client's view_ of the world - but the server thinks you're perfectly fine and happy at spawn, able to move around and everything (as observed by a host player) despite not moving at all on the client (because stuck in solid ground). Maybe this could be a desync between host and client, with the client having partially loaded without blocks to land on, falling for a while until chunks caught up and froze the player in place?

Edit: Got more info on that case, the 2nd player appeared stuck at exactly 0, 0, 0 - we've had bugs like that in the past. Something about a LocationComponent not initializing or attaching right to the 2nd player?

How to reproduce

• Unsure - but seen both from source playing JS lately, as well as while testing Omega dev build 1094.
• Host a multiplayer game of JS and survive loading it (may take a while)
• Try to join with a second client - may take longer, may freeze the host for a period of time
• After a long freeze for the host player everything may then work perfectly fine, no lag, can see the 2nd client fine, despite that player being embedded deep in the ground in their game window

Log details and game version

Omega dev build 1094

Some log snippets from near the end of the 2nd client's log (host log was unremarkable) - highlights:

• Weird "unavailable entity" logs
• Odd warnings from DAG node stuff
• ClimateMapDisplaySystem is part of ktksan's changes and may just not be wired up right for multiplayer yet

...
21:48:34.731 [main] INFO  o.t.e.prefab.internal.PrefabFormat - Attempting to deserialize prefab JoshariasSurvival:AssembleCrudeHammerFromRock with inputs [/JoshariasSurvival/assets/prefabs/AssembleCrudeHammerFromRock.prefab]
21:48:34.732 [main] INFO  o.t.e.prefab.internal.PrefabFormat - Attempting to deserialize prefab PlantPack:Oreo with inputs [/PlantPack/assets/prefabs/crop/Oreo.prefab]
21:48:34.732 [main] ERROR o.t.p.serializers.PrefabSerializer - Prefab contains unknown component 'ChangingBlocks'
21:48:34.732 [main] INFO  o.t.e.prefab.internal.PrefabFormat - Attempting to deserialize prefab AdditionalFruits:WorkstationRecipe with inputs [/AdditionalFruits/assets/prefabs/WorkstationRecipe.prefab]
21:48:34.732 [main] ERROR o.t.p.serializers.PrefabSerializer - Prefab contains unknown component 'ListRecipes'
21:48:34.748 [main] INFO  o.t.w.c.b.ExtraBlockDataManager - Extra data slots registered: BiomesAPI.biomeHash -> 0
21:48:35.890 [main] ERROR o.t.engine.ComponentSystemManager - Cannot load ModuleRendering, must be a subclass of ComponentSystem
21:48:36.583 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (1834), capping to 1000
21:48:36.745 [main] INFO  o.t.r.world.WorldRendererImpl - 
Initialising rendering class CoreRenderingModule from CoreRendering module.

21:48:36.762 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:backdropNode:BufferPair1(connected to CoreRendering:opaqueObjectsNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.765 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:backdropNode:BufferPair1(connected to CoreRendering:opaqueBlocksNode:BufferPair1, CoreRendering:opaqueObjectsNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.767 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:backdropNode:BufferPair1(connected to CoreRendering:alphaRejectBlocksNode:BufferPair1, CoreRendering:opaqueBlocksNode:BufferPair1, CoreRendering:opaqueObjectsNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.793 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:applyDeferredLightingNode:BufferPair1(connected to CoreRendering:outlineNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.796 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:applyDeferredLightingNode:BufferPair1(connected to CoreRendering:chunksRefractiveReflectiveNode:BufferPair1, CoreRendering:outlineNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.827 [main] WARN  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:toneMappingNode:FBO1(connected to CoreRendering:firstLateBlurNode:FBO1, ;)connection is already read somewhere else.
21:48:36.833 [main] INFO  o.t.r.world.WorldRendererImpl - 
Initialising rendering class AdvancedRenderingModule from CoreRendering module.

21:48:36.837 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:backdropNode:BufferPair1(connected to CoreRendering:alphaRejectBlocksNode:BufferPair1, CoreRendering:overlaysNode:BufferPair1, CoreRendering:opaqueBlocksNode:BufferPair1, CoreRendering:opaqueObjectsNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - Trying to disconnect two nodes that aren't connected, CoreRendering:backdropNode and CoreRendering:opaqueObjectsNode
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - WARNING: destination connection (Output:CoreRendering:finalHazeNode:BufferPair1(connected to CoreRendering:opaqueObjectsNode:BufferPair1, ;)) is already connected to ({CoreRendering:opaqueObjectsNode:BufferPair1=Input:CoreRendering:opaqueObjectsNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;)}
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - Trying to disconnect two nodes that aren't connected, CoreRendering:backdropNode and CoreRendering:opaqueBlocksNode
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - WARNING: destination connection (Output:CoreRendering:finalHazeNode:BufferPair1(connected to CoreRendering:opaqueBlocksNode:BufferPair1, CoreRendering:opaqueObjectsNode:BufferPair1, ;)) is already connected to ({CoreRendering:opaqueBlocksNode:BufferPair1=Input:CoreRendering:opaqueBlocksNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;), CoreRendering:opaqueObjectsNode:BufferPair1=Input:CoreRendering:opaqueObjectsNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;)}
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - Trying to disconnect two nodes that aren't connected, CoreRendering:backdropNode and CoreRendering:alphaRejectBlocksNode
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - WARNING: destination connection (Output:CoreRendering:finalHazeNode:BufferPair1(connected to CoreRendering:alphaRejectBlocksNode:BufferPair1, CoreRendering:opaqueBlocksNode:BufferPair1, CoreRendering:opaqueObjectsNode:BufferPair1, ;)) is already connected to ({CoreRendering:alphaRejectBlocksNode:BufferPair1=Input:CoreRendering:alphaRejectBlocksNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;), CoreRendering:opaqueBlocksNode:BufferPair1=Input:CoreRendering:opaqueBlocksNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;), CoreRendering:opaqueObjectsNode:BufferPair1=Input:CoreRendering:opaqueObjectsNode:BufferPair1(connected to CoreRendering:finalHazeNode:BufferPair1, ;)}
21:48:36.845 [main] WARN  o.t.rendering.dag.RenderGraph - Trying to disconnect two nodes that aren't connected, CoreRendering:backdropNode and CoreRendering:overlaysNode
21:48:36.855 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:applyDeferredLightingNode:BufferPair1(connected to CoreRendering:chunksRefractiveReflectiveNode:BufferPair1, CoreRendering:prePostCompositeNode:BufferPair1, CoreRendering:outlineNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.861 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:simpleBlendMaterialsNode:BufferPair1(connected to CoreRendering:initialPostProcessingNode:BufferPair1, ;)connection is already read somewhere else.
21:48:36.864 [main] INFO  o.t.rendering.dag.RenderGraph - Warning, Output:CoreRendering:simpleBlendMaterialsNode:BufferPair1(connected to CoreRendering:initialPostProcessingNode:BufferPair1, CoreRendering:lightShaftsNode:BufferPair1, ;)connection is already read somewhere else.
21:48:37.057 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.VelocityRangeGeneratorComponent
21:48:37.057 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.EnergyRangeGeneratorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.ColorRangeGeneratorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.PositionRangeGeneratorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.TextureOffsetGeneratorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering GeneratorFunction for Component class class org.terasology.particles.components.generators.ScaleRangeGeneratorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering AffectorFunction for Component class class org.terasology.particles.components.affectors.AccelerationAffectorComponent
21:48:37.058 [main] INFO  o.t.p.updating.ParticleUpdaterImpl - Registering AffectorFunction for Component class class org.terasology.particles.components.affectors.VelocityAffectorComponent
21:48:37.059 [main] INFO  o.t.i18n.TranslationSystemImpl - Discovered engine:menu_hi
...
21:48:37.068 [main] INFO  o.t.i18n.TranslationSystemImpl - Discovered engine:menu_ru
21:48:37.254 [main] INFO  o.terasology.minion.work.WorkFactory - Initialize WorkFactory
21:48:37.261 [main] INFO  org.terasology.minion.work.WorkBoard - Initialize WorkBoard
21:48:37.264 [main] ERROR o.t.engine.ComponentSystemManager - Failed to initialise system org.terasology.climateConditions.visualization.ClimateMapDisplaySystem@2c1eba2e
java.lang.NullPointerException: null
    at org.terasology.climateConditions.visualization.ClimateMapDisplaySystem.setClimateSeed(ClimateMapDisplaySystem.java:45)
    at org.terasology.climateConditions.visualization.ClimateMapDisplaySystem.initialise(ClimateMapDisplaySystem.java:34)
    at org.terasology.engine.ComponentSystemManager.initialiseSystem(ComponentSystemManager.java:164)
    at org.terasology.engine.ComponentSystemManager.initialise(ComponentSystemManager.java:148)
    at org.terasology.engine.modes.loadProcesses.InitialiseSystems.step(InitialiseSystems.java:51)
    at org.terasology.engine.modes.StateLoading.update(StateLoading.java:236)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:468)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:431)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:407)
    at org.terasology.engine.Terasology.main(Terasology.java:182)
21:48:37.345 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:MOUNTAINS with id 3084
21:48:37.345 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:SNOW with id -7875
21:48:37.345 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:DESERT with id -25265
21:48:37.345 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:FOREST with id -15017
21:48:37.345 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:OCEAN with id -16252
21:48:37.346 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:BEACH with id 26857
21:48:37.346 [main] INFO  o.terasology.biomesAPI.BiomeManager - Registered biome CoreWorlds:PLAINS with id 18723
21:48:56.397 [main] INFO  o.t.l.p.ThirdPersonRemoteClientSystem - Somehow ended up in the else during linkHeldItemLocationForRemotePlayer - current item was EntityRef{id=0} and new item EntityRef{id=0}
21:49:29.779 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (33421), capping to 1000
21:49:30.383 [main] INFO  o.t.l.p.ThirdPersonRemoteClientSystem - Somehow ended up in the else during linkHeldItemLocationForRemotePlayer - current item was EntityRef{id=0} and new item EntityRef{id=0}
21:49:30.383 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.383 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.396 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1159, netId = 818, prefab = 'CoreAssets:defaultBlockParticles'}
21:49:30.503 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.504 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.505 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.505 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.506 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1162, netId = 821, prefab = 'CoreAssets:defaultBlockParticles'}
21:49:30.506 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1165, netId = 825, prefab = 'ManualLabor:PlantMatter'}
21:49:30.507 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1164, netId = 823, prefab = 'CoreAssets:defaultBlockParticles'}
21:49:30.508 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.508 [main] INFO  o.t.network.internal.ServerImpl - Dropping event PlaySoundEvent for unavailable entity EntityRef{id=0}
21:49:30.508 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1168, netId = 828, prefab = 'ManualLabor:PlantMatter'}
21:49:30.510 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1167, netId = 826, prefab = 'CoreAssets:defaultBlockParticles'}
21:49:34.292 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 1175, netId = 829, prefab = 'CoreAssets:defaultBlockParticles'}

Screenie

Top left is the hosting player, and everything is fine. Looking at player 2 who on _that_ screen moves around perfectly normally despite being hopelessly stuck in the ground on their own screen on the bottom right.

[keturn]

I recommend merging #4122 before doing any performance analysis. It changes the CPU usage characteristics considerably.

[DarkWeird]

Player in multiplayer have some entities:
1 client (has Location)
2 clientInfo
3 character(player) (has Location)
4 gaze (has Location)

These LocationComponents have hierarhy structure (world to local transformation)
Seem one of location component recieve setting location in invalid method (early we have issue with problem after respawn)

Odd warnings from DAG node stuff

Seems it is double initialization and can be linked with ERROR o.t.engine.ComponentSystemManager - Cannot load ModuleRendering, must be a subclass of ComponentSystem

[Cervator]

Also happened today testing MetalRenegades, so it isn't JS / CC specific. Again it seemed weirdly random. I joined the headless server first, could move around fine. Niru joined but got stuck in the ground (and was missing from the player overlay, hmm). 4D joined and was fine. After some relogging it would reverse. Even after resetting and restarting the server it changed who got stuck, but when stuck once likely keep logging in stuck, even after resetting config.cfg to generate a new player id. Doesn't seem to only be on respawn, but certainly that can trigger it.

[DarkWeird]

Seems, you lost character entity for player:
Default location on 0,0,0
Cannot move
Invisible at player list overlay.

Then player persist in store and loaded without character entity

[Cervator]

@DarkWeird yep that sounds right - question is how do we _fix_ it 😁

[DarkWeird]

I notice some related problem..

If you not touch your client input, then you not affected by any location changes..
There related to client camera, rotation and default value (NaN) which filtered by ClientPredicationSystem.. and server not receive input and then affecting location.

I catch zero position two times. But it fixed after any moving... (But i remember blocker.. that cannot fixed by moving, iirc it is serverPredicationSystem)

It looks like client receive defaulted locationComponent.. maybe bug in spawn system, something with operation ordering)

About blocker:
Maybe component was sended on add, changing event was dropped, or changed sended before than added

[keturn]

Okay, I succeeded in reproducing. It's hard to tell if a headless server is hanging (need that telemetry!), but it was obvious when the host was a full client where I could watch its FPS and debug metrics. When the second client joined, the host client would entirely pause for several seconds.

I also observed it hang when the second client disconnected.

The hang on connection was during NetworkSubsystem.preUpdate, I think in NetClient.sendInitialEntities.

There was a lot of loadClass stuff taking up time below that.

Thing is, I threw away the flame chart, thinking I could easily re-create it. But at some point I seem to have crossed a tipping point, where — at least for this world and that client — it doesn't hang on connection or disconnection anymore!

having sendInitialEntities take a while sounds plausible, but it doesn't seem like that should be also holding things up on _disconnection?_ I have yet to get a trace of that to see if it's different.

[keturn]

Okay, connecting with a "new" client (i.e. after deleting config.cfg:security.clientIdentities) has it reproducing again. Attaching the profile here so I don't lose it, even if GitHub doesn't display it in a useful way.
hang-on-client-connection.jfr.gz

Lots of time in ReflectionUtil.loadClasses. Straying over in to TeraNUI territory here.

One thing I notice is that it's using Java's paralellStream for this. I was reading up about that just the other day, wondering if it appropriate for #4140, and found people issuing cautions about its use. The trick is that it uses some common thread pool [citation needed], and if you put tasks in there that take a long time, you can end up blocking other things that use that thread pool.

That's something to look at but I don't think it's the problem, exactly. This probably isn't expected to take this long in the first place.

[keturn]

I managed to get a look at the disconnection case.
hang-on-client-disconnect.jfr.gz

The problem is during entity serialization again. But instead of serializing entities to send to the remote client, it's serializing the player entity to save, in PlayerStoreBuilder.

[keturn]

If this profiler data is accurate, it's getting stuck in gestalt's ModuleClassLoader.loadClass, recursing between that and java.lang.ClassLoader.loadClass for a long time. It's not clear from this profile what finally snaps it out of it; does it hit max recursion depth?

I don't know what to make of the server logs. "prefab contains unknown component" and "cannot deserialize unknown field" errors are abundant.

Is this relevant?

ERROR o.t.module.sandbox.ModuleClassLoader - Denied access to class (not allowed with this module's permissions): org.terasology.module.sandbox.API

[DarkWeird]

LoadClass is loading class (unexpectly)
There really recurcive, because it loading class, then trying loading class of field/parameters.

Check please, is it multithreaded or not.(static initializer must contains add classloader to special map) then it is can be faster. (It is actual for network game on joining phase. Because there modules loading.

About org.terasology.sandbox.API:
It must be in engine module or in white list.

P.s. I am reintegrate gestalt v7 in TS now.

Seems it can be disappointed after it. Or not :)

[keturn]

Now that we've got a bit more idea of where the server-side lag spikes are, does anyone have ideas about what might have changed since the previous play test to make this happen?

I don't have a good sense of when the last known-good state was and what has happened since then.

Brainstorming some possible types of things:

• changes to how or when the reflections cache is created
• changes to which classes are permitted by the gestalt module loader. maybe things renamed or moved to other packages?
• has this been happening since the TeraNUI extraction, when we started using nui-reflect?

[keturn]

also I still don't understand what flips when the client somehow becomes immune to the issue and I have to generate a new one to reproduce the error.

[keturn]

More brain dumping:

I hypothesized that there was some particular thing it was trying to load that was taking a long time because it had to look through a list of class loaders before failing.

I tweaked the logback.xml so it would include warnings from Reflections (we have it set limited to error-level by default, since we get spam from it we ignore), but I found no log of it totally failing like that.

Is there one particular thing that it's slow to load? or is it just a lot of things?

what would make it be slow only sometimes?

[Cervator]

I have a vague sense of it starting with ClimateConditions + WildAnimals being added to JS. Think I tried to take them off as dependencies and it was fine. Haven't tested specifically around NUI extraction though.

[keturn]

through trial and error I've found I can reproduce this on Core Gameplay + Manual Labor. I haven't managed to narrow it down any more than that, e.g. WildAnimals seems okay on its own.

• engine:3.3.0
• BiomesAPI:4.0.1
• CoreAssets:2.2.0
• CoreWorlds:1.2.1
• Health:1.0.2
• Inventory:1.3.1
• Pathfinding:1.0.0
• Behaviors:1.1.0
• Drops:1.0.2
• Explosives:1.0.1
• Furnishings:1.1.1
• CoreAdvancedAssets:1.2.0
• CoreRendering:1.0.2
• CoreSampleGameplay:4.1.0
• Durability:1.1.0
• Fluid:2.0.0
• InGameHelpAPI:1.0.0
• InGameHelp:1.1.0
• ItemRendering:1.1.0
• PotentialEnergyDevices:1.1.0
• Workstation:1.1.0
• Machines:1.2.1
• SubstanceMatters:2.0.0
• MarkovChains:1.5.1
• NameGenerator:1.0.0
• WorldlyTooltipAPI:1.0.0
• WildAnimals:1.0.0
• ManualLabor:1.3.0

[keturn]

in fact, a game with all of those ManualLabor dependencies except for ManualLabor itself seems to not show the issue.

So I guess it's something about ManualLabor?

I still don't know what that would be. I reviewed the recent commits there and there are some new textures and a few very small changes for TeraNUI.

[keturn]

Some findings:

A big source of slowness in sendInitialEntities is when it was serializing InventoryAccessComponent. It uses this getAsString method:

https://github.com/MovingBlocks/Terasology/blob/012985ccb97b6872af9d5bfdb3c589845ab98605/engine/src/main/java/org/terasology/persistence/typeHandling/extensionTypes/ComponentClassTypeHandler.java#L31-L32

resulting in ModuleEnvironmentSandbox.getSubTypeIdentifier running loadClass on all Component classes.

To some extent, this gets worse with the number of Components loaded in the type registry, so it's slower with bigger module sets like JS.

I am not sure exactly what it is about Manual Labor in particular that sets this off. Its HumanMachineAuthoritySystem does add a Component to the Player entity, so maybe that leads to more Components being serialized when a new Player connects? but I can't connect the dots from there to InventoryAccessComponent.

and I still don't know why this is something that would have become so much worse over the past month or two.

[keturn]

Something else to check on this kind of issue: Is the performance different when you have only .jar files for the modules instead of having their sources checked out?

I ask because I see the Reflections lib showing up in the call stack sometimes, and wonder if the reflections cache comes in to play.

[DarkWeird]

Something else to check on this kind of issue: Is the performance different when you have only .jar files for the modules instead of having their sources checked out?

I ask because I see the Reflections lib showing up in the call stack sometimes, and wonder if the reflections cache comes in to play.

Reflections cache not exists at source.
It is created for jar task only. Then deleted from build dir.

Then for "sources" reflection fetch in runtime

[Cervator]

Secondary issue with the 0,0,0 problem submitted here: #4152 - just considering this one specific to the performance issue in ManualLabor now.

[Cervator]

Closing this as at least _partially_ resolved via #4148 by @keturn - many thanks!

Tested several additional rounds of multiplayer separately with CoreSampleGameplay, ManualLabor, and JoshariasSurvival and submitted two new issues to cover any leftovers: #4152 and #4154