lloesche / valheim-server-docker

Valheim dedicated gameserver with automatic update, World backup, BepInEx and ValheimPlus mod support
https://hub.docker.com/r/lloesche/valheim-server
Apache License 2.0
1.92k stars 269 forks source link

Disconnects while "Unloading 0 unused Assets to reduce memory usage" #513

Open widnig89 opened 1 year ago

widnig89 commented 1 year ago

Hello,

I am not sure whether to report this here or directly to Valheim, but me and my friends are experiencing regular server instabilities (top left hud overlay server error icon) and/or disconnects every ~10 minutes.

I used docker logs --follow to watch log events while playing and having these instabilities (lags), and I found out that every time these lines are logged:

supervisord: valheim-server Unloading 0 Unused Serialized files (Serialized files now loaded: 0)
supervisord: valheim-server Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 1264525.
supervisord: valheim-server Total: 21222.956000 ms (FindLiveObjects: 19179.241756 ms CreateObjectMapping: 737.670632 ms MarkObjects: 1303.962937 ms  DeleteObjects: 2.073330 ms)

There seems to be also a relation of either having a real disconnect or just some server lags for all players depending on the value of Total. The higher the number, the higher the chance of a disconnect.

So I | grep Total for a better overview:

Oct 29 19:50:16 supervisord: valheim-server Total: 8375.767528 ms (FindLiveObjects: 6372.916215 ms CreateObjectMapping: 789.979297 ms MarkObjects: 1210.547183 ms  DeleteObjects: 2.316606 ms)
Oct 29 20:00:30 supervisord: valheim-server Total: 10350.575829 ms (FindLiveObjects: 6368.775447 ms CreateObjectMapping: 882.636269 ms MarkObjects: 3096.957784 ms  DeleteObjects: 2.203113 ms)
Oct 29 20:10:39 supervisord: valheim-server Total: 9495.797744 ms (FindLiveObjects: 8252.658226 ms CreateObjectMapping: 93.242169 ms MarkObjects: 1147.825232 ms  DeleteObjects: 2.064553 ms)
Oct 29 20:20:58 supervisord: valheim-server Total: 16177.314076 ms (FindLiveObjects: 13685.763159 ms CreateObjectMapping: 347.195734 ms MarkObjects: 2143.228770 ms  DeleteObjects: 1.116825 ms)
Oct 29 20:31:17 supervisord: valheim-server Total: 17698.724650 ms (FindLiveObjects: 16402.482538 ms CreateObjectMapping: 233.555317 ms MarkObjects: 1061.128693 ms  DeleteObjects: 1.549708 ms)
Oct 29 20:41:32 supervisord: valheim-server Total: 15325.296640 ms (FindLiveObjects: 12042.575211 ms CreateObjectMapping: 228.682776 ms MarkObjects: 3051.499832 ms  DeleteObjects: 2.528854 ms)
Oct 29 20:51:47 supervisord: valheim-server Total: 6365.624126 ms (FindLiveObjects: 4276.113975 ms CreateObjectMapping: 822.253156 ms MarkObjects: 1264.202524 ms  DeleteObjects: 3.049151 ms)
Oct 29 21:02:25 supervisord: valheim-server Total: 38784.680218 ms (FindLiveObjects: 34998.346607 ms CreateObjectMapping: 258.150900 ms MarkObjects: 3526.862947 ms  DeleteObjects: 1.311110 ms)

As you can see, these lines come all 10 minutes in the logs. And whenever the number is greater than ~30 seconds I usually get disconnected, whereas when it is something between ~10 to 29 seconds I just have the server error icon for this time and lags. Smaller than 10 I usually do not recognize anything.

I did a little bit of a cross research in the internet, and these lines seems to come from Unity3D Game Engine. (I assume some cleanup task to improve performance).

Still I am posting here, as these high Total number seems somehow not okay for my world.

My Valheim / Server Setup:

I used docker-compose without any additional optional environment variables (so no valheim plus, no mods, nothing...just a vanilla one).

My VPS setup is on contabo.com with the VPS S plan (4 vCores, 8GB RAM and 400GB SSD). Some lines from lshw -short:

/0/400                         processor  AMD EPYC 7282 16-Core Processor
/0/1000                        memory     8GiB System Memory
/0/1000/0                      memory     8GiB DIMM RAM
...
/0/100/5/0/0.0.0    /dev/sda   disk       429GB QEMU HARDDISK

My Valheim world is kind of new, we are 3 players just on the first island and starting to collect copper/tin orbs and producing stuff with it, but as I said, really fresh / minimalistic for now.

Here is a ls -lh from my /config/worlds-local folder:

-rw-r--r-- 1 root root 15M Oct 30 08:42 'Parkside World.db'
-rw-r--r-- 1 root root 15M Oct 30 08:11 'Parkside World.db.old'
-rw-r--r-- 1 root root  50 Oct 30 08:42 'Parkside World.fwl'
-rw-r--r-- 1 root root  50 Oct 30 08:11 'Parkside World.fwl.old'
-rw-r--r-- 1 root root  50 Oct 29 08:36 'Parkside World_backup_auto-20221029063614.fwl'
-rw-r--r-- 1 root root 13M Oct 29 09:37 'Parkside World_backup_auto-20221029073753.db'
-rw-r--r-- 1 root root  50 Oct 29 19:47 'Parkside World_backup_auto-20221029174733.fwl'
-rw-r--r-- 1 root root 15M Oct 29 20:09 'Parkside World_backup_auto-20221029180946.db'
-rw-r--r-- 1 root root  50 Oct 30 05:34 'Parkside World_backup_auto-20221030043401.fwl'
-rw-r--r-- 1 root root 17M Oct 30 06:00 'Parkside World_backup_auto-20221030050044.db'
-rw-r--r-- 1 root root  50 Oct 30 07:39 'Parkside World_backup_auto-20221030063951.fwl'
-rw-r--r-- 1 root root 15M Oct 30 08:11 'Parkside World_backup_auto-20221030071133.db'

I am also watching with htop my server, but currently not while having disconnects, but the cpu/ram usages seems ok while playing. RAM is lower than 2G of 7.76G and the 4 CPU cores are also not heavily in use.

So if anyone experience the same or having an advice, pls let me know as it makes playing really frustrating.

if you need more info, just let me know.

thx.

Nitair commented 1 year ago

I do have the same behavior on my setup (I am using as well contabo.com - 8vCores, 30 GB RAM, 400 GB NVMe).

I am running this image in a docker swarm setup on a worker node (since its my only worker node, I am using local volumes). See my deployment file: https://gist.github.com/Nitair/335f7ad712658db4b5279ae75627e838.

I was running the default values for all cron-jobs / without valheim plus / mods but changed them now to different times in order to check if this issue was related to those cron-jobs. I just received at 22:29 the report of another lag (logs at this time https://gist.github.com/Nitair/08357add869577cc0a182facbd6f9cf6). But they also reported to me that disconnects are happening too.

If a disconnect happens, I'll provide more logs here.

Aiiion commented 1 year ago

I am having the same issues as you @widnig89, running the same setup on contabo. I'll let you know if I get anywhere in my debugging. Here are my logs from the point that I lost connection with the server last:

Dec 15 18:18:11 supervisord: valheim-server Unloading 9 Unused Serialized files (Serialized files now loaded: 0) valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server Unloading 11 unused Assets to reduce memory usage. Loaded Objects now: 2804959. valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server Total: 29592.655825 ms (FindLiveObjects: 17837.252078 ms CreateObjectMapping: 1739.796793 ms MarkObjects: 10007.116295 ms DeleteObjects: 8.482013 ms) valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Got status changed msg k_ESteamNetworkingConnectionState_ClosedByPeer valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Socket closed by peer Steamworks.SteamNetConnectionStatusChangedCallback_t valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Closing socket xxxxxxxxxxxxx50 valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Closing socket xxxxxxxxxxxxx50 valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Failed to send data k_EResultNoConnection valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: send queue size:29 valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Got status changed msg k_ESteamNetworkingConnectionState_None valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:496 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:1 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:2 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:4 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:776 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Destroying abandoned non persistent zdo 2348894531:685 owner im going to hide this valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Disposing socket valheim-server-valheim-1 | Dec 15 18:18:41 supervisord: valheim-server 12/15/2022 18:18:41: Disposing socket

widnig89 commented 1 year ago

I did some further investigation, and I also experienced strange bugs in my game. eg. a boat gets damaged every few seconds when sailing. And some forums said that it is a server issue (stability, ...), as somehow the way the game engine is working / calculating on client side in combination with lags / movement, the boat "crashes" into the water every few seconds.

I then decided really to backup the world, and give g-portal a chance with the minimalistic setup. Since I moved there (with the same world), no matter how many players, we do not have any issues at all.

So I assume that Contabo VPS are not suitable for games like Valheim. And therefore made usage of the refund policy. There might be a way around it, and if you have solution I would appreciate it, but I can't help here anymore as I do not have a Contabo Server or using this script anymore.

Concluding that it is a (Contabo) VPS issue, rather something to do with this script.