High server lag/ticktime during chunk generation

[anthonytam]

Game Version

v1.18.1

Platform

Linux

Modded

Modded

SP/MP

Multiplayer

Description

During points of high chunk generation, such as a player venturing out into the map, server tick time increases significantly from a normal 45-60ms to 5s peeking at 12s. During periods of high tick time, players experience significant server lag (of course) with their ping increasing to ~600ms.

The server typically sees 4 to 12 players online when the lag occurs, I have not been able to replicate the issue on a server with only 1 player.

Server Specs: CPU: Intel Xeon Silver 4110 (16) @ 3.0GHz Memory: 32GB 2400MHz OS: Ubuntu 22.04.2, Kernel 5.15.0-71 Server has plenty of memory to spare (~8GB utilized) and the mono process running the server typically sits at 170% usage, peeking to 210%.

How to reproduce

No response

Screenshots

Example 1:

Example 2:

Logs

The server has been logging logticks to InfluxDB via Th3Essentials mod should be able to dump samples during high chunk generation if needed (I also don't mind sharing access to the Grafana instance for easy searching). I've also provided some screenshots of server performance during chunk generation.

Happy to provide anything else I can!

[Prinzip]

Sup. we also have a dedicated server with nearly the same hardware. All time the Server is idling...

In 1.17.x there was no lag with 20+ players on the same server. Currently its hard lagging, reaching 10+ players. With 20 players its not playable, to high laggs - because of this i had to limit the max players... We reduced the maxchunkradius, removed all entitys, set autosave higher, removed all mods - nothing helps. the map was created in 1.18 rc5, i also tested it with the same seed in 1.18.0 stable - same result.

With Th3Essentials statistics i got the result, its not only the chunk generation. If people stay in night at home and no new chunks will be generated, this lagg spikes are seen often too.

here are some tick logs

ticks1.txt ticks_16_players(1).txt

And some statistic pictures:

[radfast]

OK that's extreme!

Thanks for the tick logs, I am going through them, and we'll see what we can improve in 1.18.x release. It is very useful to see tick logs with 5-18 players online. We certainly want servers with these numbers to be rock solid stable.

Looking forward a few months (I estimate 1-3 months but no promise) there will be a .NET7 version of the game which should run much faster on servers, with shorter tick times therefore. The only "obstacle" to us releasing that already is that it will break around 15% of mods which depend on a patching library called Harmony, because Harmony is not yet released for .NET7.

[Prinzip]

here is a new tick log, current 15 people online and collecting items taking long time.

1.txt 2.txt

[teknik1]

i constat on our server if there more than 10 players all mobs lag a lot and they can't attack players because they look stuck. If we dig a lot and there are many items on the grounds this create a hudge lag in all aeras in the servers.... that was not the case in 1.17 the lag was only near the players who was digging. 15 players on the servers and the game come unplayable ....

[Prinzip]

little update - it seems there is also a clay forming bug - this brings also the hugh laggs :

clayform.txt

[radfast]

@Prinzip I'll bet the clay forming lag (which is very extreme!) is mod-related

If you are able to reproduce the issue / investigate it further, three things to check:

1. what toolmode is the player using (add / copy layer / etc.?)
2. what clayform is the player creating
3. check that sound sounds/player/clayform.ogg is available and working OK, the final step before the problematic mark is to play that sound

[Prinzip]

@radfast i dont know how to reproduce this u wrote with alot of players at the same time

The only mod is xskills by Xandu - This can changes things with the clay forms

[Prinzip]

@radfast i got an answer from the players who were online - it seems its a vanilla feature:

the only guy, who formed clay in this time, had 5 storage vessels at the same time to form. The exciting at this is - he created the form 2 days before and did not finished them in this time, only ca 2 layers of them. Durring this time we had about 4 server restarts

we checked his xskills profil - he did not used it, so the mod did not manipulate something.

[tyronx]

those those affected, how do you start the server? Is it inside a vm/container or natively?

[Prinzip]

Ubuntu 22 - dedicated root server

VS will be started as a service like written at https://wiki.vintagestory.at/index.php/Setting_up_a_Multiplayer_Server#Advanced_Dedicated_Server

[radfast]

@radfast i got an answer from the players who were online - it seems its a vanilla feature:

the only guy, who formed clay in this time, had 5 storage vessels at the same time to form. The exciting at this is - he created the form 2 days before and did not finished them in this time, only ca 2 layers of them. Durring this time we had about 4 server restarts

we checked his xskills profil - he did not used it, so the mod did not manipulate something.

Thanks for checking. We can try testing saving a reloading part-formed clay forms. But I can't be sure this isn't xskills causing the issue: even if xskills is not used it changes our code even for vanilla tasks. If it happens again, ideally immediately make a copy of the save game for sending to the devs (hopefully not too many GB!), to trouble-shoot an issue like this we really have to be able to reproduce it first

[radfast]

In the graphs in Example 2, the peak in server ticktime is at 11:37:48 which is before the number of generating chunks starts to rise. Possibly it initiates the climb in generating chunks

I would assume what happened is that one or several players came online at 11:37:48

Server ticktime is closely correlated with the number of players online. It would be very helpful always to see a player count graph alongside (above or below) a ticktime graph.

[radfast]

With tyron, we are currently making several significant multiplayer server performance improvements which - combined - might even be able to half the tick time, or approximately half, when a server is under heavy load. (YMMV and we are excited to know the real-life results.)

No promise about the exact release schedule for this, but one possible plan is to make a 1.18.2 release this week for all players, and a simultaneous 1.18.3-rc1 release for server-owners. In that case, 1.18.2 will contain some bugfixes for all players, and 1.18.3-rc1 will contain, additionally, performance improvements for multiplayer servers. We would ask any server owners who are willing to help, to download and run 1.18.3-rc1 server-side only, and monitor the server ticks. (Players with game version 1.18.2 will be able to connect to 1.18.3-rc1 servers.)

The reason for making an rc1 release of the performance improvements, before general release, is that we do not know whether our improvements will break any mods. Most mods should be fine, but mods which have unusual entities (not simply variations on the game's existing mammals, poultry and fish) or which have unusual new damage sources (similar to cactus or fire) or mods which use Harmony to deeply integrate with our code might have some kind of issue.

[Prinzip]

here is an example i gave tyron too:

currently i stoped monitoring this stuff, but i can enable it again at next update

[anthonytam]

those those affected, how do you start the server? Is it inside a vm/container or natively?

@tyronx We're running our server in docker on bare metal with an Alpine base image. Running in Docker is the most preferable for us but I've also tried running it directly on bare metal in a tmux session with no change

Happy to test run the 1.18.3-rc1 version once released, we'll report back any findings we have (Good or bad :) )

[radfast]

here is an example i gave tyron too:

currently i stoped monitoring this stuff, but i can enable it again at next update

@Prinzip yes please do do this monitoring again in next update (which will be called 1.18.2-rc1 now, and will combine the 1.18.2 and 1.18.3-rc1 concepts which I described above). The update should drop this morning :)

If you have the issue where the server becomes slow responding (many seconds of block lag etc) after many hour / days, it would be useful to see graphs like those over a long time interval, ideally for the whole period from server start to the time when the block lag is happening. (If the graphing package cannot change the resolution on the time axis then maybe take snapshots every 4 hours? If that's not too much trouble for you? Even something approximately approaching this will be helpful. Of course, we are looking to see if something has changed radically when the server becomes slow to respond)

[radfast]

@anthonytam @Prinzip @teknik1 The release 1.18.2-rc1 is now out, please see Discord #news channel.

Your players do not need to update, they can remain on 1.18.1 (and they will not currently be prompted to download 1.18.2 because it is not a stable release).

So: the server can update to 1.18.2-rc1 and the players can remain on 1.18.1 and the players can still connect to the server, totally OK. The game will not inform the players the server is running this higher version.

If maybe some of the players choose themselves to update their own game to 1.18.2-rc1 that is also OK, of course.

The players who remain on 1.18.1 will still have the 1.18.1 bugs (for example, placed beams deleting chests and other blocks) but the server will not have the bugs, so re-logging may fix issues of this kind for this player. There may be other similar small discrepancies where a bug has been fixed in 1.18.2 - again, generally re-logging will fix issues.

[Prinzip]

i updated the server to the version. first thing i noticed: if i stop the vs service - it take a long time until finished. maybee because of the failure

May 4 11:28:36 115754E VintageStoryTest[179770]: 4.5.2023 11:28:36 [Server Error] Exception thrown during handling event OnGameWorldBeingSaved: System.NullReferenceException: Object reference not set to an instance of an object May 4 11:28:36 115754E VintageStoryTest[179770]: at Vintagestory.Server.ServerSystemLoadAndSaveGame.SaveGameWorld (System.Boolean saveLater) [0x0000f] in :0 May 4 11:28:36 115754E VintageStoryTest[179770]: at Vintagestory.Server.ServerSystemLoadAndSaveGame.OnWorldBeingSaved () [0x0012b] in :0 May 4 11:28:36 115754E VintageStoryTest[179770]: at Vintagestory.Server.ServerEventManager.TriggerGameWorldBeingSaved () [0x00022] in :0

[radfast]

Yes, there is an exception on a hard stop of the server, sorry we noticed this only after we already started the build process today. Using the /stop command from console should be OK to shutdown the server without this issue, should not throw the exception. Other hard exits from the server (for example Alt F4) may produce the issue.

If this is a serious problem we will release a 1.18.2-rc2

[Prinzip]

it can be helpful for the daily backup, if service will be stoped bevor. but please wait, maybee we will find more failures today.

[Prinzip]

if using /debug logticks 100 - nothing will shown in the log like in the version before.

(8players atm)

[radfast]

Nice, looks like our changes have made a big difference :) What is your MaxPhysicsThreads setting?

It would be interesting to see the logticks output, especially looking at the 5 ticks which exceeded 500ms.

[Prinzip]

let's see if more people are online today. using 6 threads atm, i ll increase it later.

"It would be interesting to see the logticks output, especially looking at the 5 ticks which exceeded 500ms." The debug logticks command is not working - in the log is often shown like [Server Warning] Server overloaded. A tick took 523ms to complete, also i can see in the statistic values above 250 often. but the command did not generate informations in the log like in the last server version.

[radfast]

the command did not generate informations in the log like in the last server version.

That's an issue ... it should generate information in the log in the same way as in the last server version. Please post the server-main.txt log when you have a chance. How are you generating the tick time graph: is it a mod, or is it parallel software which reads the log file?

[radfast]

using 6 threads atm, i ll increase it later.

6 threads should be plenty. An increase from 6 to 8 will not make a huge difference (maybe 25% reduction in controlledphysics tick time, but there is some overhead per thread so more likely 15-20% in practice). You also need to think about how many physical CPU threads you have available on the system, the server has at least 6 other threads running for stable networking, worldgen etc.

[Prinzip]

server-main.txt

theessentials mod is generating the statistics

[radfast]

As a goal, I think ideally server tick time should be under 100ms with 8 players online. Your graph suggests around 250ms average so we still have work to do ... frustrating that there is not the detailed logticks output in the log. It looks like that is being diverted to theessentials mod

[Th3Dilli]

@Prinzip do you have "InlfuxDBOverwriteLogTicks": true? if so turn that to false since that will prevent logticks from going to the log file

note: the logtick in th3Esentials mod is not that useful anymore since the game prints them in a recursive way and i havnt found a good way to display that in grafana so they are kind misleading atm since you cant tell wich logtick is part of another one, i will remove the logick logging to grafana/influx in the next release

[Prinzip]

@Th3Dilli thanks, i ll disable it.

@radfast i got alot of this failure, when i shutdown the server with @Th3Dilli Discord Command /shutdown:

May 4 14:31:36 115754E VintageStory[181109]: 4.5.2023 14:31:36 [Server Fatal] System.Exception: Thread synchronization problem, blame radfast May 4 14:31:36 115754E VintageStory[181109]: at Vintagestory.Common.LoadBalancer.SynchroniseWorkOnMainThread () [0x0000f] in :0 May 4 14:31:36 115754E VintageStory[181109]: at Vintagestory.Server.ServerSystemEntityPhysics.OnServerTick (System.Single dt) [0x0002e] in :0 May 4 14:31:36 115754E VintageStory[181109]: at Vintagestory.Server.ServerMain.Process () [0x001ba] in :0

[Th3Dilli]

the Discord Command /shutdown will use api.Server.ShutDown() fyi radfast

[teknik1]

on G-portal we can only update with stable release because we don't have access to root folder.

[anthonytam]

@anthonytam @Prinzip @teknik1 The release 1.18.2-rc1 is now out, please see Discord #news channel.

I've updated to the rc release, no issues on initial startup with the mods we have enabled/loading the map. A few errors when the first player joined, however might not be fully related and aren't showing up anymore.

4.5.2023 14:03:03 [Server Error] BETransient @515033, 113, 514235 for Block tallgrass-eaten-free, but there is cobblestone-granite at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515034, 113, 514236 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515035, 113, 514236 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515035, 113, 514237 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515036, 113, 514238 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515035, 113, 514238 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515026, 113, 514235 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515025, 113, 514238 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:03 [Server Error] BETransient @515021, 112, 514229 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE
4.5.2023 14:03:04 [Server Error] BETransient @515015, 110, 514203 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE

Initially loading / with 1 player in the server, I can already notice a ticktime decrease of ~7 to 10ms which is great! As more players join (Likely in a few hours) I'll see how it handles a higher load

Thanks for getting the new unstable release out so quickly!

[radfast]

the Discord Command /shutdown will use api.Server.ShutDown() fyi radfast

Thank you. All routes to shutdown are fixed in the next build which we will release (potentially today/tomorrow). If you need to shut down the server before that build - and I guess you must, when updating to that build! - please be aware that the final save before shutdown may not occur if the exception is seen. In my testing, the console /stop command saves the game correctly, if you have the option to use that instead today that would be your safest approach.

[Prinzip]

currently there are 8 peoples online and here is the logtick debug. Its far away from <100ms :(

1.txt

if more people come online, i will send u the next update with more players at this time.

[radfast]

4.5.2023 14:03:04 [Server Error] BETransient @515015, 110, 514203 for Block tallgrass-eaten-free, but there is tallgrass-eaten-snow3 at this position? Will delete BE

Initially loading / with 1 player in the server, I can already notice a ticktime decrease of ~7 to 10ms which is great! As more players join (Likely in a few hours) I'll see how it handles a higher load

Thanks for getting the new unstable release out so quickly!

The BETransient / tallgrass-eaten error is a known long-standing issue, don't worry about it. It is a minor issue logged to the log, only when snow falls or snow melts. A possible consequence, if that error is seen, is that that grass at the specified position will then not grow taller as the months pass. We should fix this but it is not related to 1.18.2-rc1

The optimisations are designed to help, the most, servers with a load of around 5-20 players. The improvements will help all servers including single-player games, but 5-20 players is the target we are designing for here. Below 5 players, a server probably had decent tick times already. Above 20 players, most servers are going to struggle, at least until we can get the stable .NET7 update out - that is coming soon (TM), actually it depends on Harmony not us.

For slow-ticking servers there is, unfortunately, a vicious circle where more and more game elements need updates in the same tick because longer time has passed. In contrast, if we can fix most of the causes of slow ticks, there is a virtuous circle where less and less tasks need to be done each tick because less time has passed, meaning the next tick can also take a shorter time. Therefore, I looked at improving several of the main causes of slow ticks on multiplayer servers.

This has been and will be an ongoing project ever since game version 1.14, and more improvements are planned in the future.

Real world information from server owners is amazingly valuable in this project. I love the Grafana graphs which Th3Essentials can produce - thank you @Th3Dilli - to give an overall picture of performance scaling, and how things change depending on the number of players online. When tick time becomes slow, the /debug logticks output from logs gives me and other developers the specific information we need to identify performance hotspots in code, so please do remember to switch on logticks any time you notice degraded performance.

[anthonytam]

We're currently bouncing between 7 and 9 players online and the improvements are very significant, average ticktime is down to ~70ms with the highest spike being 500ms and is definitely an outlier. We asked a few players to explore to test chunk generation again and the server handles the load much better then before.

Agreed that .NET7 will likely being significant performance improvements for free, we'll be keeping and eye out for when its ready 😄

And yes, the Grafana visualizations have been super helpful in following specific server stats, once I noticed it was already developed it was one of the first things I added in. @Th3Dilli: while the visualizations for logticks may not be possible anymore, having the ability to ingest them directly into InfluxDB instead of writing to the log file is still pretty nice. I notice some performance loss when saving logticks (Saving them to a SATA SSD, not an NVMe) that InfluxDB is able to handle better. If ever needed, we can just query the DB directly instead of grabbing the log file (Unless there's something else I'm missing here)

[Prinzip]

currently there are ca 13 people online and the laggs are back again. here is the new logticks file: 12players.txt

what changes i made since yesterday:

• i changed the maxchunkradius from 7 back to 10
• new servermagicnumbers.json generated, and made this changes : "DefaultEntityTrackingRange": 3 + "MaxPhysicsThreads": 6
• /serverconfig spawncapplayerscaling from 0 back to 0.75

...i changed this back to this values, because its the default by the game

At this lagg time there are ca 2400 entities and ca 1900 active.

[teknik1]

i think there are probleme with entities ! animals don't die when they get stuck inside blocks, so with the time we can have a lot of invisible aniamls under sand, gravels ... if there are 15 players with a lot of bunnys sheeps and pigs they make huge lags ...

i think animals shoulb be able to eat grass or they die.... Thix ways we cannot make a tons of animals inside a 3x3 area ! This was the way in BetterThanWolves.

[teknik1]

server 1.8.1 9 players with chunck radius 12 -> 6 auto save each 10 minutes entity trackingrange 3 tracked entity by client 3000 ->1000 a command kill all fish, rabbit, fox, butterflyes, each 3 minutes...

But all mobs can't fight they look stuck and staying at place.

logticks 100

4.5.2023 22:18:27 [Server Notification] A tick took 171.02 ms 171.02ms, call : all 156.49ms, 1 call : tickentities 142.27ms, 1262 calls, avg 112.73 us/call: behaviors 75.00ms, 1052 calls, avg 71.29 us/call: done-behavior-harvestable 39.39ms, 532 calls, avg 74.05 us/call: controlledphysics 26.23ms, 2128 calls, avg 12.33 us/call: collision 7.47ms, 2128 calls, avg 3.51 us/call: trigger-insideblock 6.41ms, 2128 calls, avg 3.01 us/call: terraincollision 4.02ms, 2128 calls, avg 1.89 us/call: prep 3.44ms, 2128 calls, avg 1.62 us/call: apply-collisionandflags 2.93ms, 2128 calls, avg 1.38 us/call: stepping-checks 1.82ms, 2128 calls, avg 0.85 us/call: apply-motion 10.50ms, 2128 calls, avg 4.93 us/call: locomotors 1.21ms, 2128 calls, avg 0.57 us/call: init 1.17ms, 2128 calls, avg 0.55 us/call: knockback-and-mountedcheck 10.90ms, 486 calls, avg 22.43 us/call: ai-tasks 3.42ms, 629 calls, avg 5.43 us/call: task-startexecute-fleeentity 1.71ms, 664 calls, avg 2.57 us/call: task-startexecute-wander 1.26ms, 1615 calls, avg 0.78 us/call: task-startexecute-idle 0.95ms, 332 calls, avg 2.85 us/call: task-startexecute-meleeattack 0.46ms, 248 calls, avg 1.84 us/call: task-startexecute-seekfoodandeat 0.45ms, 177 calls, avg 2.57 us/call: task-continueexec-idle 0.45ms, 323 calls, avg 1.40 us/call: task-startexecute-seekentity 0.36ms, 199 calls, avg 1.80 us/call: task-continueexec-wander 3.76ms, 1206 calls, avg 3.11 us/call: done-behavior-repulseagents 2.06ms, 56 calls, avg 36.81 us/call: done-behavior-passiveentityphysics 1.55ms, 1288 calls, avg 1.20 us/call: done-behavior-timeddespawn 1.55ms, 738 calls, avg 2.09 us/call: done-behavior-breathe 0.86ms, 1206 calls, avg 0.71 us/call: done-behavior-controlledentityphysics 0.76ms, 1153 calls, avg 0.66 us/call: done-behavior-floatupwhenstuck 11.72ms, 1262 calls, avg 9.29 us/call: entity-animation-ticking 1.96ms, 1206 calls, avg 1.62 us/call: entityAgent-ticking 0.36ms, 1262 calls, avg 0.29 us/call: entity-tick-specificclasses 5.43ms, 2 calls, avg 2713.60 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 1.86ms, 1 call : gmleVintagestory.Server.ServerSystemBlockSimulation 1.75ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.44ms, 1 call : ss-UpdateEntitiesTickingFlag 0.78ms, 78 calls, avg 10.05 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.48ms, 87 calls, avg 5.56 us/call: gmleVintagestory.GameContent.BlockEntityItemFlow 0.38ms, 1 call : ss-tick-Vintagestory.Server.ServerSystemBlockSimulation 0.36ms, 1 call : gmleVintagestory.GameContent.WeatherSystemServer

4.5.2023 22:18:27 [Server Notification] A tick took 130.08 ms 130.08ms, call : all 124.61ms, 1 call : tickentities 110.79ms, 1262 calls, avg 87.79 us/call: behaviors 42.37ms, 1052 calls, avg 40.27 us/call: done-behavior-harvestable 39.29ms, 532 calls, avg 73.86 us/call: controlledphysics 26.14ms, 2128 calls, avg 12.28 us/call: collision 8.02ms, 2128 calls, avg 3.77 us/call: trigger-insideblock 6.16ms, 2128 calls, avg 2.89 us/call: terraincollision 3.97ms, 2128 calls, avg 1.87 us/call: prep 3.47ms, 2128 calls, avg 1.63 us/call: apply-collisionandflags 2.65ms, 2128 calls, avg 1.24 us/call: stepping-checks 1.74ms, 2128 calls, avg 0.82 us/call: apply-motion 10.59ms, 2128 calls, avg 4.98 us/call: locomotors 1.17ms, 2128 calls, avg 0.55 us/call: init 1.13ms, 2128 calls, avg 0.53 us/call: knockback-and-mountedcheck 11.03ms, 484 calls, avg 22.80 us/call: ai-tasks 2.98ms, 625 calls, avg 4.76 us/call: task-startexecute-fleeentity 2.82ms, 660 calls, avg 4.27 us/call: task-startexecute-wander 1.33ms, 1611 calls, avg 0.82 us/call: task-startexecute-idle 0.75ms, 321 calls, avg 2.35 us/call: task-startexecute-seekentity 0.48ms, 330 calls, avg 1.46 us/call: task-startexecute-meleeattack 0.39ms, 201 calls, avg 1.92 us/call: task-continueexec-wander 0.38ms, 248 calls, avg 1.52 us/call: task-startexecute-seekfoodandeat 0.36ms, 172 calls, avg 2.09 us/call: task-continueexec-idle 3.71ms, 1206 calls, avg 3.08 us/call: done-behavior-repulseagents 2.36ms, 56 calls, avg 42.21 us/call: done-behavior-passiveentityphysics 1.96ms, 1288 calls, avg 1.52 us/call: done-behavior-timeddespawn 1.70ms, 738 calls, avg 2.30 us/call: done-behavior-breathe 0.92ms, 1206 calls, avg 0.76 us/call: done-behavior-controlledentityphysics 0.74ms, 1153 calls, avg 0.64 us/call: done-behavior-floatupwhenstuck 7.91ms, 1262 calls, avg 6.27 us/call: entity-animation-ticking 1.63ms, 1206 calls, avg 1.35 us/call: entityAgent-ticking 0.38ms, 1262 calls, avg 0.30 us/call: entity-tick-specificclasses 1.44ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.16ms, 1 call : ss-UpdateEntitiesTickingFlag 0.94ms, 124 calls, avg 7.57 us/call: gmleVintagestory.GameContent.BlockEntityFarmland 0.65ms, 79 calls, avg 8.21 us/call: gmleVintagestory.GameContent.BlockEntityFirepit

4.5.2023 22:18:28 [Server Notification] A tick took 239 ms 239.00ms, call : all 156.82ms, 1 call : entityspawner 152.52ms, 3038 calls, avg 50.20 us/call: spawn-attempts 61.88ms, 3038 calls, avg 20.37 us/call: testspawn game:butterfly-monarch 31.37ms, 3038 calls, avg 10.33 us/call: testspawn game:butterfly-macrocosmamoth 26.69ms, 3038 calls, avg 8.79 us/call: testspawn game:butterfly-meadowbluemale 25.02ms, 3038 calls, avg 8.24 us/call: testspawn game:butterfly-purplishcoppermale 7.26ms, 3038 calls, avg 2.39 us/call: testspawn game:butterfly-ireniametalmark 62.60ms, 1 call : tickentities 53.07ms, 1260 calls, avg 42.12 us/call: behaviors 28.97ms, 530 calls, avg 54.66 us/call: controlledphysics 19.30ms, 1590 calls, avg 12.14 us/call: collision 5.33ms, 1590 calls, avg 3.35 us/call: trigger-insideblock 5.11ms, 1590 calls, avg 3.21 us/call: terraincollision 2.83ms, 1590 calls, avg 1.78 us/call: prep 2.54ms, 1590 calls, avg 1.60 us/call: apply-collisionandflags 2.20ms, 1590 calls, avg 1.38 us/call: stepping-checks 1.19ms, 1590 calls, avg 0.75 us/call: apply-motion 7.68ms, 1590 calls, avg 4.83 us/call: locomotors 0.95ms, 1590 calls, avg 0.60 us/call: init 0.81ms, 1590 calls, avg 0.51 us/call: knockback-and-mountedcheck 8.66ms, 484 calls, avg 17.89 us/call: ai-tasks 2.37ms, 625 calls, avg 3.79 us/call: task-startexecute-fleeentity 2.10ms, 660 calls, avg 3.18 us/call: task-startexecute-wander 1.22ms, 1611 calls, avg 0.76 us/call: task-startexecute-idle 0.43ms, 173 calls, avg 2.47 us/call: task-continueexec-idle 0.43ms, 330 calls, avg 1.29 us/call: task-startexecute-meleeattack 0.36ms, 321 calls, avg 1.13 us/call: task-startexecute-seekentity 3.37ms, 1204 calls, avg 2.80 us/call: done-behavior-repulseagents 1.43ms, 738 calls, avg 1.94 us/call: done-behavior-breathe 1.35ms, 1284 calls, avg 1.05 us/call: done-behavior-timeddespawn 1.35ms, 56 calls, avg 24.06 us/call: done-behavior-passiveentityphysics 0.97ms, 1151 calls, avg 0.84 us/call: done-behavior-floatupwhenstuck 0.80ms, 1204 calls, avg 0.66 us/call: done-behavior-controlledentityphysics 0.63ms, 1050 calls, avg 0.60 us/call: done-behavior-harvestable 7.47ms, 1260 calls, avg 5.93 us/call: entity-animation-ticking 1.57ms, 1204 calls, avg 1.30 us/call: entityAgent-ticking 8.77ms, 5 calls, avg 1753.16 us/call: gmleVintagestory.GameContent.BlockEntityCrate 5.56ms, 3 calls, avg 1852.00 us/call: gmleVintagestory.GameContent.BlockEntityGenericTypedContainer 2.10ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.05ms, 1 call : ss-UpdateEntitiesTickingFlag 0.58ms, 94 calls, avg 6.15 us/call: gmleVintagestory.GameContent.BlockEntityFarmland 0.54ms, 1 call : net-read-done

4.5.2023 22:18:28 [Server Notification] A tick took 139.74 ms 139.74ms, call : all 123.67ms, 1 call : tickentities 70.16ms, 1260 calls, avg 55.68 us/call: behaviors 36.98ms, 530 calls, avg 69.77 us/call: controlledphysics 24.77ms, 2120 calls, avg 11.68 us/call: collision 7.32ms, 2120 calls, avg 3.45 us/call: trigger-insideblock 6.00ms, 2120 calls, avg 2.83 us/call: terraincollision 3.69ms, 2120 calls, avg 1.74 us/call: prep 3.36ms, 2120 calls, avg 1.58 us/call: apply-collisionandflags 2.74ms, 2120 calls, avg 1.29 us/call: stepping-checks 1.53ms, 2120 calls, avg 0.72 us/call: apply-motion 9.74ms, 2120 calls, avg 4.59 us/call: locomotors 1.16ms, 2120 calls, avg 0.55 us/call: init 1.07ms, 2120 calls, avg 0.50 us/call: knockback-and-mountedcheck 9.22ms, 476 calls, avg 19.37 us/call: ai-tasks 2.56ms, 609 calls, avg 4.20 us/call: task-startexecute-fleeentity 1.74ms, 644 calls, avg 2.70 us/call: task-startexecute-wander 1.21ms, 1595 calls, avg 0.76 us/call: task-startexecute-idle 0.58ms, 322 calls, avg 1.80 us/call: task-startexecute-meleeattack 0.57ms, 174 calls, avg 3.27 us/call: task-continueexec-idle 0.46ms, 313 calls, avg 1.47 us/call: task-startexecute-seekentity 0.41ms, 124 calls, avg 3.29 us/call: task-startexecute-throwatentity 3.45ms, 1204 calls, avg 2.87 us/call: done-behavior-repulseagents 2.80ms, 56 calls, avg 49.97 us/call: done-behavior-passiveentityphysics 2.62ms, 1188 calls, avg 2.20 us/call: done-behavior-health 2.24ms, 738 calls, avg 3.03 us/call: done-behavior-breathe 2.16ms, 1284 calls, avg 1.68 us/call: done-behavior-timeddespawn 1.56ms, 1050 calls, avg 1.49 us/call: done-behavior-harvestable 1.10ms, 1053 calls, avg 1.04 us/call: done-behavior-emotionstates 10.88ms, 1260 calls, avg 8.64 us/call: entity-animation-ticking 1.65ms, 1204 calls, avg 1.37 us/call: entityAgent-ticking 5.89ms, 3 calls, avg 1962.50 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 1.78ms, 33 calls, avg 54.08 us/call: gmleVintagestory.GameContent.Mechanics.BEBehaviorWindmillRotor 1.49ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.34ms, 1 call : ss-UpdateEntitiesTickingFlag 0.85ms, 78 calls, avg 10.96 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.69ms, 9 calls, avg 76.14 us/call: gmleVintagestory.GameContent.BlockEntityStoneCoffin 0.63ms, 107 calls, avg 5.90 us/call: gmleVintagestory.GameContent.BlockEntityFarmland 0.49ms, 87 calls, avg 5.60 us/call: gmleVintagestory.GameContent.BlockEntityItemFlow

4.5.2023 22:18:28 [Server Notification] A tick took 113.94 ms 113.94ms, call : all 97.19ms, 1 call : tickentities 88.06ms, 1251 calls, avg 70.39 us/call: behaviors 53.11ms, 522 calls, avg 101.74 us/call: controlledphysics 26.82ms, 2088 calls, avg 12.84 us/call: locomotors 23.86ms, 2088 calls, avg 11.42 us/call: collision 6.67ms, 2088 calls, avg 3.20 us/call: trigger-insideblock 5.77ms, 2088 calls, avg 2.77 us/call: terraincollision 3.68ms, 2088 calls, avg 1.76 us/call: prep 3.02ms, 2088 calls, avg 1.45 us/call: apply-collisionandflags 2.98ms, 2088 calls, avg 1.42 us/call: stepping-checks 1.59ms, 2088 calls, avg 0.76 us/call: apply-motion 1.12ms, 2088 calls, avg 0.54 us/call: init 1.04ms, 2088 calls, avg 0.50 us/call: knockback-and-mountedcheck 9.83ms, 1041 calls, avg 9.44 us/call: done-behavior-harvestable 9.42ms, 476 calls, avg 19.80 us/call: ai-tasks 2.56ms, 609 calls, avg 4.20 us/call: task-startexecute-fleeentity 2.27ms, 644 calls, avg 3.53 us/call: task-startexecute-wander 1.24ms, 1595 calls, avg 0.78 us/call: task-startexecute-idle 0.65ms, 313 calls, avg 2.06 us/call: task-startexecute-seekentity 0.41ms, 322 calls, avg 1.28 us/call: task-startexecute-meleeattack 0.41ms, 173 calls, avg 2.37 us/call: task-continueexec-idle 0.37ms, 195 calls, avg 1.90 us/call: task-continueexec-wander 3.45ms, 1195 calls, avg 2.89 us/call: done-behavior-repulseagents 1.97ms, 1266 calls, avg 1.56 us/call: done-behavior-timeddespawn 1.62ms, 56 calls, avg 28.95 us/call: done-behavior-passiveentityphysics 1.29ms, 738 calls, avg 1.75 us/call: done-behavior-breathe 0.82ms, 1142 calls, avg 0.72 us/call: done-behavior-floatupwhenstuck 0.77ms, 1195 calls, avg 0.65 us/call: done-behavior-controlledentityphysics 7.10ms, 1251 calls, avg 5.68 us/call: entity-animation-ticking 1.56ms, 1195 calls, avg 1.31 us/call: entityAgent-ticking 11.24ms, 1 call : gmleVintagestory.GameContent.EntityBehaviorHunger 1.76ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.41ms, 1 call : ss-UpdateEntitiesTickingFlag 0.83ms, 79 calls, avg 10.45 us/call: gmleVintagestory.GameContent.BlockEntityFirepit

4.5.2023 22:18:28 [Server Notification] A tick took 103.88 ms 103.88ms, call : all 65.56ms, 1 call : tickentities 53.05ms, 1251 calls, avg 42.41 us/call: behaviors 28.59ms, 523 calls, avg 54.67 us/call: controlledphysics 18.88ms, 1570 calls, avg 12.02 us/call: collision 5.41ms, 1570 calls, avg 3.44 us/call: trigger-insideblock 5.11ms, 1570 calls, avg 3.25 us/call: terraincollision 2.54ms, 1570 calls, avg 1.62 us/call: prep 2.46ms, 1570 calls, avg 1.57 us/call: apply-collisionandflags 2.01ms, 1570 calls, avg 1.28 us/call: stepping-checks 1.24ms, 1570 calls, avg 0.79 us/call: apply-motion 7.66ms, 1570 calls, avg 4.88 us/call: locomotors 0.92ms, 1570 calls, avg 0.59 us/call: init 0.88ms, 1570 calls, avg 0.56 us/call: knockback-and-mountedcheck 8.74ms, 477 calls, avg 18.32 us/call: ai-tasks 3.09ms, 610 calls, avg 5.06 us/call: task-startexecute-fleeentity 1.18ms, 645 calls, avg 1.82 us/call: task-startexecute-wander 1.12ms, 1597 calls, avg 0.70 us/call: task-startexecute-idle 0.72ms, 322 calls, avg 2.22 us/call: task-startexecute-meleeattack 0.41ms, 313 calls, avg 1.30 us/call: task-startexecute-seekentity 3.44ms, 1195 calls, avg 2.88 us/call: done-behavior-repulseagents 1.60ms, 738 calls, avg 2.17 us/call: done-behavior-breathe 1.35ms, 1266 calls, avg 1.06 us/call: done-behavior-timeddespawn 1.31ms, 56 calls, avg 23.34 us/call: done-behavior-passiveentityphysics 0.78ms, 1195 calls, avg 0.65 us/call: done-behavior-controlledentityphysics 0.73ms, 1179 calls, avg 0.62 us/call: done-behavior-health 0.67ms, 1142 calls, avg 0.58 us/call: done-behavior-floatupwhenstuck 10.43ms, 1251 calls, avg 8.34 us/call: entity-animation-ticking 1.58ms, 1195 calls, avg 1.32 us/call: entityAgent-ticking 0.35ms, 1251 calls, avg 0.28 us/call: entity-tick-specificclasses 27.48ms, 2 calls, avg 13738.20 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 3.43ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 2.35ms, 2 calls, avg 1174.90 us/call: ss-UpdateEntitiesTickingFlag 1.42ms, 160 calls, avg 8.90 us/call: gmleVintagestory.GameContent.BlockEntityFarmland 1.15ms, 78 calls, avg 14.80 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.49ms, 87 calls, avg 5.66 us/call: gmleVintagestory.GameContent.BlockEntityItemFlow 0.41ms, 1 call : gmleVintagestory.GameContent.WeatherSystemServer

4.5.2023 22:18:28 [Server Notification] A tick took 189.34 ms 189.34ms, call : all 78.74ms, 1 call : entityspawner 74.69ms, 3038 calls, avg 24.59 us/call: spawn-attempts 43.68ms, 3038 calls, avg 14.38 us/call: testspawn game:butterfly-smallwhitefemale 30.76ms, 3038 calls, avg 10.12 us/call: testspawn game:butterfly-orangetiger 60.15ms, 1 call : tickentities 51.64ms, 1251 calls, avg 41.28 us/call: behaviors 25.41ms, 522 calls, avg 48.68 us/call: controlledphysics 16.82ms, 1566 calls, avg 10.74 us/call: collision 4.93ms, 1566 calls, avg 3.15 us/call: terraincollision 4.64ms, 1566 calls, avg 2.96 us/call: trigger-insideblock 2.40ms, 1566 calls, avg 1.53 us/call: prep 2.13ms, 1566 calls, avg 1.36 us/call: apply-collisionandflags 1.64ms, 1566 calls, avg 1.05 us/call: stepping-checks 1.00ms, 1566 calls, avg 0.64 us/call: apply-motion 6.73ms, 1566 calls, avg 4.30 us/call: locomotors 0.89ms, 1566 calls, avg 0.57 us/call: init 0.79ms, 1566 calls, avg 0.51 us/call: knockback-and-mountedcheck 11.20ms, 476 calls, avg 23.53 us/call: ai-tasks 3.78ms, 644 calls, avg 5.87 us/call: task-startexecute-wander 2.82ms, 609 calls, avg 4.64 us/call: task-startexecute-fleeentity 1.30ms, 1595 calls, avg 0.81 us/call: task-startexecute-idle 0.79ms, 313 calls, avg 2.53 us/call: task-startexecute-seekentity 0.37ms, 322 calls, avg 1.15 us/call: task-startexecute-meleeattack 3.32ms, 1195 calls, avg 2.78 us/call: done-behavior-repulseagents 1.31ms, 738 calls, avg 1.78 us/call: done-behavior-breathe 1.30ms, 1266 calls, avg 1.02 us/call: done-behavior-timeddespawn 1.20ms, 56 calls, avg 21.41 us/call: done-behavior-passiveentityphysics 1.07ms, 1044 calls, avg 1.02 us/call: done-behavior-emotionstates 0.75ms, 1195 calls, avg 0.63 us/call: done-behavior-controlledentityphysics 0.58ms, 476 calls, avg 1.23 us/call: ai-pathfinding 6.56ms, 1251 calls, avg 5.24 us/call: entity-animation-ticking 1.53ms, 1195 calls, avg 1.28 us/call: entityAgent-ticking 20.36ms, 651 calls, avg 31.27 us/call: gmleVintagestory.GameContent.BlockEntityGenericTypedContainer 14.26ms, 158 calls, avg 90.28 us/call: gmleVintagestory.GameContent.BlockEntityCrate 7.00ms, 51 calls, avg 137.22 us/call: gmleVintagestory.GameContent.BlockEntityGroundStorage 2.39ms, 2 calls, avg 1197.45 us/call: ss-UpdateEntitiesTickingFlag 1.72ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.07ms, 186 calls, avg 5.78 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.40ms, 1 call : net-read-done

4.5.2023 22:18:28 [Server Notification] A tick took 101.49 ms 101.49ms, call : all 87.33ms, 1 call : tickentities 75.56ms, 1251 calls, avg 60.40 us/call: behaviors 49.50ms, 524 calls, avg 94.46 us/call: controlledphysics 39.22ms, 2096 calls, avg 18.71 us/call: collision 23.46ms, 2096 calls, avg 11.19 us/call: terraincollision 6.25ms, 2096 calls, avg 2.98 us/call: trigger-insideblock 2.99ms, 2096 calls, avg 1.43 us/call: prep 2.82ms, 2096 calls, avg 1.35 us/call: apply-collisionandflags 2.21ms, 2096 calls, avg 1.06 us/call: stepping-checks 1.38ms, 2096 calls, avg 0.66 us/call: apply-motion 8.12ms, 2096 calls, avg 3.87 us/call: locomotors 0.97ms, 2096 calls, avg 0.46 us/call: knockback-and-mountedcheck 0.94ms, 2096 calls, avg 0.45 us/call: init 7.49ms, 478 calls, avg 15.67 us/call: ai-tasks 2.01ms, 611 calls, avg 3.29 us/call: task-startexecute-fleeentity 1.31ms, 646 calls, avg 2.03 us/call: task-startexecute-wander 1.07ms, 1599 calls, avg 0.67 us/call: task-startexecute-idle 0.55ms, 322 calls, avg 1.72 us/call: task-startexecute-meleeattack 0.46ms, 173 calls, avg 2.69 us/call: task-continueexec-idle 0.42ms, 313 calls, avg 1.34 us/call: task-startexecute-seekentity 3.39ms, 1195 calls, avg 2.84 us/call: done-behavior-repulseagents 3.06ms, 1041 calls, avg 2.94 us/call: done-behavior-harvestable 2.11ms, 56 calls, avg 37.71 us/call: done-behavior-passiveentityphysics 1.47ms, 1266 calls, avg 1.16 us/call: done-behavior-timeddespawn 1.34ms, 738 calls, avg 1.82 us/call: done-behavior-breathe 0.74ms, 54 calls, avg 13.79 us/call: collision 0.69ms, 1195 calls, avg 0.58 us/call: done-behavior-controlledentityphysics 9.86ms, 1251 calls, avg 7.88 us/call: entity-animation-ticking 1.46ms, 1195 calls, avg 1.23 us/call: entityAgent-ticking 4.43ms, 2 calls, avg 2217.10 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 2.39ms, 2 calls, avg 1192.80 us/call: ss-UpdateEntitiesTickingFlag 1.34ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.17ms, 155 calls, avg 7.56 us/call: gmleVintagestory.GameContent.BlockEntityFarmland 0.67ms, 78 calls, avg 8.58 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.58ms, 194 calls, avg 3.00 us/call: dceVintagestory.GameContent.EntityBehaviorMultiply 0.40ms, 87 calls, avg 4.61 us/call: gmleVintagestory.GameContent.BlockEntityItemFlow 0.35ms, 1 call : gmleVintagestory.Server.ServerSystemBlockSimulation

4.5.2023 22:18:29 [Server Notification] A tick took 150.12 ms 150.12ms, call : all 93.37ms, 1 call : tickentities 79.57ms, 1258 calls, avg 63.25 us/call: behaviors 55.29ms, 526 calls, avg 105.11 us/call: controlledphysics 44.94ms, 1577 calls, avg 28.50 us/call: collision 30.17ms, 1577 calls, avg 19.13 us/call: terraincollision 5.89ms, 1577 calls, avg 3.74 us/call: trigger-insideblock 2.79ms, 1577 calls, avg 1.77 us/call: prep 2.67ms, 1577 calls, avg 1.69 us/call: apply-collisionandflags 2.00ms, 1577 calls, avg 1.27 us/call: stepping-checks 1.31ms, 1577 calls, avg 0.83 us/call: apply-motion 8.24ms, 1577 calls, avg 5.23 us/call: locomotors 0.97ms, 1577 calls, avg 0.62 us/call: init 0.90ms, 1577 calls, avg 0.57 us/call: knockback-and-mountedcheck 8.44ms, 479 calls, avg 17.61 us/call: ai-tasks 1.71ms, 647 calls, avg 2.64 us/call: task-startexecute-wander 1.69ms, 612 calls, avg 2.76 us/call: task-startexecute-fleeentity 1.47ms, 1597 calls, avg 0.92 us/call: task-startexecute-idle 0.79ms, 313 calls, avg 2.53 us/call: task-startexecute-seekentity 0.47ms, 322 calls, avg 1.45 us/call: task-startexecute-meleeattack 0.35ms, 170 calls, avg 2.08 us/call: task-continueexec-idle 3.50ms, 1202 calls, avg 2.91 us/call: done-behavior-repulseagents 1.60ms, 740 calls, avg 2.17 us/call: done-behavior-breathe 1.30ms, 1273 calls, avg 1.02 us/call: done-behavior-timeddespawn 1.20ms, 56 calls, avg 21.49 us/call: done-behavior-passiveentityphysics 0.85ms, 1202 calls, avg 0.71 us/call: done-behavior-controlledentityphysics 0.77ms, 1149 calls, avg 0.67 us/call: done-behavior-floatupwhenstuck 0.64ms, 479 calls, avg 1.34 us/call: ai-pathfinding 11.06ms, 1258 calls, avg 8.79 us/call: entity-animation-ticking 1.65ms, 1202 calls, avg 1.38 us/call: entityAgent-ticking 20.25ms, 87 calls, avg 232.77 us/call: gmleVintagestory.GameContent.BlockEntityItemFlow 14.32ms, 1 call : mainthreadtasks 0.73ms, 60 calls, avg 12.24 us/call: MTT-ChunkLoaded-LoadBlockEntities 0.41ms, 66 calls, avg 6.22 us/call: MTT-ChunkLoaded-LoadedEvent 10.34ms, 1 call : ss-tick-Vintagestory.Server.ServerSystemSendChunks 5.73ms, 2 calls, avg 2867.35 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 1.54ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.30ms, 1 call : ss-UpdateEntitiesTickingFlag 0.70ms, 78 calls, avg 8.99 us/call: gmleVintagestory.GameContent.BlockEntityFirepit 0.37ms, 1 call : gmleVintagestory.GameContent.WeatherSystemServer

4.5.2023 22:18:29 [Server Notification] A tick took 335.31 ms 335.31ms, call : all 151.87ms, 1 call : entityspawner 147.21ms, 3038 calls, avg 48.46 us/call: spawn-attempts 41.84ms, 3038 calls, avg 13.77 us/call: testspawn game:butterfly-smallcoppermale 39.76ms, 3038 calls, avg 13.09 us/call: testspawn game:butterfly-peacock 34.19ms, 3038 calls, avg 11.25 us/call: testspawn game:butterfly-arcticwhitefemale 25.81ms, 3038 calls, avg 8.50 us/call: testspawn game:butterfly-grayhairstreak 5.33ms, 3038 calls, avg 1.75 us/call: testspawn game:butterfly-theanoalpinemale 143.59ms, 1 call : tickentities 134.10ms, 1268 calls, avg 105.76 us/call: behaviors 54.48ms, 1058 calls, avg 51.49 us/call: done-behavior-harvestable 53.55ms, 524 calls, avg 102.20 us/call: controlledphysics 27.83ms, 2096 calls, avg 13.28 us/call: locomotors 23.37ms, 2096 calls, avg 11.15 us/call: collision 7.10ms, 2096 calls, avg 3.39 us/call: trigger-insideblock 5.90ms, 2096 calls, avg 2.82 us/call: terraincollision 3.24ms, 2096 calls, avg 1.55 us/call: prep 3.20ms, 2096 calls, avg 1.53 us/call: apply-collisionandflags 2.31ms, 2096 calls, avg 1.10 us/call: stepping-checks 1.49ms, 2096 calls, avg 0.71 us/call: apply-motion 1.11ms, 2096 calls, avg 0.53 us/call: init 1.00ms, 2096 calls, avg 0.48 us/call: knockback-and-mountedcheck 9.23ms, 477 calls, avg 19.35 us/call: ai-tasks 2.27ms, 645 calls, avg 3.51 us/call: task-startexecute-wander 1.94ms, 610 calls, avg 3.18 us/call: task-startexecute-fleeentity 1.32ms, 1593 calls, avg 0.83 us/call: task-startexecute-idle 0.83ms, 313 calls, avg 2.64 us/call: task-startexecute-seekentity 0.60ms, 322 calls, avg 1.88 us/call: task-startexecute-meleeattack 3.72ms, 1212 calls, avg 3.07 us/call: done-behavior-repulseagents 2.15ms, 56 calls, avg 38.36 us/call: done-behavior-passiveentityphysics 1.60ms, 1283 calls, avg 1.25 us/call: done-behavior-timeddespawn 1.48ms, 745 calls, avg 1.99 us/call: done-behavior-breathe 0.78ms, 1212 calls, avg 0.65 us/call: done-behavior-controlledentityphysics 0.72ms, 45 calls, avg 16.10 us/call: collision 7.39ms, 1268 calls, avg 5.82 us/call: entity-animation-ticking 1.62ms, 1212 calls, avg 1.34 us/call: entityAgent-ticking 25.90ms, 1 call : ss-tick-Vintagestory.Server.ServerSystemSendChunks 2.55ms, 522 calls, avg 4.88 us/call: gmleVintagestory.GameContent.BlockEntityTransient 1.98ms, 1 call : mainthreadtasks 1.92ms, 1 call : gmleVintagestory.GameContent.EntityPartitioning 1.68ms, 352 calls, avg 4.78 us/call: gmleVintagestory.GameContent.BlockEntitySapling 1.35ms, 1 call : ss-UpdateEntitiesTickingFlag 1.10ms, 155 calls, avg 7.10 us/call: gmleVintagestory.GameContent.BlockEntityFirepit

4.5.2023 22:18:29 [Server Notification] A tick took 364.11 ms 364.11ms, call : all 129.79ms, 1 call : tickentities 115.80ms, 1271 calls, avg 91.11 us/call: behaviors 38.84ms, 524 calls, avg 74.12 us/call: controlledphysics 25.90ms, 2096 calls, avg 12.35 us/call: collision 7.70ms, 2096 calls, avg 3.67 us/call: trigger-insideblock 6.27ms, 2096 calls, avg 2.99 us/call: terraincollision 4.00ms, 2096 calls, avg 1.91 us/call: prep 3.58ms, 2096 calls, avg 1.71 us/call: apply-collisionandflags 2.52ms, 2096 calls, avg 1.20 us/call: stepping-checks 1.70ms, 2096 calls, avg 0.81 us/call: apply-motion 10.20ms, 2096 calls, avg 4.87 us/call: locomotors 1.22ms, 2096 calls, avg 0.58 us/call: knockback-and-mountedcheck 1.19ms, 2096 calls, avg 0.57 us/call: init 23.13ms, 1215 calls, avg 19.03 us/call: done-behavior-repulseagents 20.04ms, 1061 calls, avg 18.89 us/call: done-behavior-harvestable 11.92ms, 477 calls, avg 24.99 us/call: ai-tasks 3.22ms, 610 calls, avg 5.28 us/call: task-startexecute-fleeentity 2.49ms, 645 calls, avg 3.86 us/call: task-startexecute-wander 1.41ms, 1593 calls, avg 0.88 us/call: task-startexecute-idle 0.90ms, 322 calls, avg 2.81 us/call: task-startexecute-meleeattack 0.76ms, 313 calls, avg 2.42 us/call: task-startexecute-seekentity 0.65ms, 124 calls, avg 5.24 us/call: task-startexecute-throwatentity 0.55ms, 184 calls, avg 2.99 us/call: task-continueexec-idle 0.35ms, 247 calls, avg 1.43 us/call: task-startexecute-seekfoodandeat 4.25ms, 56 calls, avg 75.95 us/call: done-behavior-passiveentityphysics 2.73ms, 1199 calls, avg 2.27 us/call: done-behavior-health 2.44ms, 745 calls, avg 3.27 us/call: done-behavior-breathe 2.31ms, 1286 calls, avg 1.79 us/call: done-behavior-timeddespawn 1.57ms, 90 calls, avg 17.42 us/call: collision 0.68ms, 90 calls, avg 7.55 us/call: prep 0.49ms, 90 calls, avg 5.41 us/call: trigger-insideblock 11.49ms, 1271 calls, avg 9.04 us/call: entity-animation-ticking 1.85ms, 1215 calls, avg 1.52 us/call: entityAgent-ticking 0.46ms, 1271 calls, avg 0.37 us/call: entity-tick-specificclasses 56.11ms, 56 calls, avg 1001.96 us/call: gmleVintagestory.GameContent.BlockEntityGenericTypedContainer 53.99ms, 42 calls, avg 1285.57 us/call: gmleVintagestory.GameContent.BlockEntityCrate 38.47ms, 9 calls, avg 4273.98 us/call: gmleVintagestory.GameContent.BlockEntityBarrel 15.90ms, 3 calls, avg 5299.90 us/call: gmleVintagestory.GameContent.BlockEntityTrough 15.80ms, 15 calls, avg 1053.11 us/call: gmleVintagestory.GameContent.BlockEntityGroundStorage 8.40ms, 1 call : ss-tick-Vintagestory.Server.ServerSystemSendChunks 6.98ms, 3 calls, avg 2327.63 us/call: gmleVintagestory.Server.ServerSystemEntitySimulation 6.94ms, 1 call : gmleVintagestory.GameContent.BlockEntityCondenser

[radfast]

@teknik1 the logticks you have posted is from the 1.18.1 version of the game, not 1.18.2-rc1. Let's see your 1.18.2-rc1 equivalents? You speak of animals "getting stuck inside blocks". That is not possible (or please provide evidence?)

@here:

1. In general, animals become inactive if there is no player nearby, so it should not be necessary for your servers to force-despawn hares, raccoons, salmon etc - these creatures should make little or no load for the server if there is no player nearby. We can maybe do even more in a future game version to reduce their load, or we can make configurable what "nearby" means, like a CreaturesActiveRadius setting.

2. The "animals moving slow" or "pulled backwards" issue will start to happen whenever server tick time exceeds 135ms. The more that server average tick time exceeds 135ms, the more obvious it will be that creatures are not moving correctly. Therefore our goal should be to get average tick times to 135ms or less. Anything less than that can be considered fully playable and smooth, there would be no noticeable block lag nor movement lag.

3. The most helpful thing you guys can do to help us along in this project is (A) keep testing 1.18.2-rc1 with mods and player numbers above 5, this is something the dev team cannot do ourselves (B) send us the actual /debug logticks output from time to time, like @Prinzip did. This logticks output has been customised by tyron and me to show us, as coders, exactly what parts of our code we can most usefully next focus on for performance improvements

[radfast]

4. If you like you could manually edit some creatures' json files to reduce their spawn chances on your own server. Would it be helpful to have global settings to raise or lower spawn chances and numbers of different entity groups? This would allow you to have some of these creatures in the game but less, for performance reasons - seems preferable to killing them all periodically

For a fine-grained system, I am thinking about:

• three global modifiers for passive, hostile, and non-interactable creatures
• possibility to override that individually for named entity types

[Prinzip]

is there a chance to get today a hotfix version fixing the vs service shutdown stuff and api.Server.ShutDown() working? atm this is more work for me to handle, besides collecting logticks.

[radfast]

Yes, I should think so! Yesterday you asked us to hold off on a hotfix!

[Prinzip]

Next Logticks, 7 Players.

i see a new lines: 567.05ms, 676 calls, avg 838.83 us/call: gmleVintagestory.GameContent.BlockEntityGroundStorage 116.59ms, 643 calls, avg 181.31 us/call: gmleVintagestory.GameContent.BlockEntityGenericTypedContainer 3859.05ms, 1 call : gmleVintagestory.GameContent.FruitTreeRootBH

05-05-23-7players.txt

[radfast]

3859.05ms, 1 call : gmleVintagestory.GameContent.FruitTreeRootBH ouch. I've seen this in logs too.

The containers are also calling for examination

[teknik1]

@teknik1 the logticks you have posted is from the 1.18.1 version of the game, not 1.18.2-rc1. Let's see your 1.18.2-rc1 equivalents? You speak of animals "getting stuck inside blocks". That is not possible (or please provide evidence?)

Our server was running about 1 years, when i traveled in that world i had see a lot of little hole with many animals inside, i found some players with hudge farms with around 300 animals. And when a mountain collapses or a ruin or any sand or gravel ceiling falls it can get stuck some animals that will stay there all the time... I don't know if this had an impact on lag.

[Prinzip]

new record

34474.17ms, 1 call : tickentities

maybee its useful

atm we thinking about why we are using and paying an expensive dedicated server. the server is idling all the time. players are leaving the game and are frustrated (i understand it). bad vs multiplayer future.

[radfast]

new record

34474.17ms, 1 call : tickentities

maybee its useful

atm we thinking about why we are using and paying an expensive dedicated server. the server is idling all the time. players are leaving the game and are frustrated (i understand it). bad vs multiplayer future.

If you can post up the logticks for this one, I will look today at what more we can do - gonna look at more radical solutions

Why are there 9546 item entities, that seems insane?

[Prinzip]

34474.txt

"Why are there 9546 item entities, that seems insane?" if alot of people going at the same time mining, forestring, farming etc. thats not unnormal alot of items are on ground (i think)

on more hint: maybee the logticks should written in a own file?

[radfast]

Thank you, I will spend today on this. We certainly want to improve these tick times some more.

Meanwhile we have some suggestions for the number of passive entities. The game already gives you fine-grained control over the spawning of different entity types. For the entities which you want to control, for example salmon, hares, butterflies, you can control the numbers by some simple edits to the JSONs in the server assets folder.

For example, in file /assets/survival/entities/air/butterfly.json file, these values at lines 273-274:

            spawnCapPlayerScaling: 0.75,
            maxQuantityByGroup: { code: "butterfly-*", maxQuantity: 40 },

If you reduce those numbers for the butterflies and some other entities which you don't much care about, you will: (a) have fewer of those entities spawning so fewer overall entities on the server to tick; and (b) if the limits are reached, there will be no more testentityspawn calls, so the entityspawner tick time will also be reduced for these specific entities

You might also want to reduce your global spawnCapPlayerScaling config, you wrote you increased it from 0 to 0.75, maybe for now try a lower value like 0.5

(You can also increase the per-entity numbers for some entities which you do want to see a lot of. For example, you can affect game balance by changing the numbers for Drifters and other hostile mobs. If your global spawnCapPlayerScaling config is low like 0.5, you could compensate by setting spawnCapPlayerScaling: 2.0, in the Drifter file only. File /assets/survival/entities/land/drifter.json.)

Obviously this will not help with 9500 dropped items, I will spend some time on the dropped items code today.