Log spaming "Assertion Failed: SDR service thread gave up on lock after waiting"

[arnibanani]

Hello!

I experience some problems with my server on a diskstation:
When a player is connected, my docker gets spammed with errorlogs:

08:08:07	src/steamnetworkingsockets/clientlib/steamnetworkingsockets_lowlevel.cpp (1276) : Assertion Failed: SDR service thread gave up on lock after waiting 60ms. This directly adds to delay of processing of network packets!	stdout
08:08:07	src/steamnetworkingsockets/clientlib/steamnetworkingsockets_lowlevel.cpp (1276) : Assertion Failed: SDR service thread gave up on lock after waiting 60ms. This directly adds to delay of processing of network packets!	stdout
--	--	--

...etc

After some time, i cant open my protocoll, i assume its overloaded?

Anyway, i found out that this is a message seems to be complaining about a high latency? Is there a way to stop these messages appearing?

[InB4DevOps]

On my DS416play I'm also seeing these log messages from time to time but not always. Do these messages appear for every connected player or only when a player with poor internet connectivity is connected?

[InB4DevOps]

BTW: what is your ping like when you connect via local IP? (see in game by pressing F2)

[arnibanani]

My local ping is around 30-40ms - not the best imo.

[InB4DevOps]

Is that you being in your base or out in the woods?
In my one of our bases I have ping around 70-100ms - connected via local IP.
This is odd.

[arnibanani]

That was a short test inside the base/house ingame.

[GerardVerberk]

Same issue for me for a few minutes after a player connects to the server. Running on Synology DS218+.

[InB4DevOps]

2021-02-25 10:33:20,stdout,Warning: failed to set thread priority: set failed for priority 8

2021-02-25 10:33:20,stdout,Warning: failed to set thread priority: set failed for 8: -1: setpriority() failed

I found this thread but I am unsure as to how it might apply to this container.
https://www.reddit.com/r/valheim/comments/lstk71/valheim_dedicated_server_fix_for_failed_to_set/
@lloesche your thoughts? I think this can improve server performance.

[lloesche]

@arnibanani I do not know if these should be filtered, but if that is what you would like to do there is a way to do so.

There are some undocumented environment variables, namely these:

DEFAULT_LOG_FILTER='grep --line-buffered -v -e "^\s*$" -e "^(Filename:"'
SERVER_LOG_FILTER=${SERVER_LOG_FILTER:-$DEFAULT_LOG_FILTER}
SERVER_LOG_STDOUT_FILTER=${SERVER_LOG_STDOUT_FILTER:-$SERVER_LOG_FILTER}
SERVER_LOG_STDERR_FILTER=${SERVER_LOG_STDERR_FILTER:-$SERVER_LOG_FILTER}

If you extend that line and run your server with e.g. -e SERVER_LOG_FILTER='grep --line-buffered -v -e "^\s*$" -e "^(Filename:" -e "Assertion Failed"'
it should get rid of those messages. Beware though that any error in this line might produce unpredictable results as all the server output is piped directly into this command. Hence its undocumented nature.

[lloesche]

Oh also this requires a fairly recent build of the container to work. Like within the past 24h or so.

[arnibanani]

Thanks for the reply. I have to say that iam just a "user", hoped theres a "one button"-solution. I'll let it be as it is as long as the server runs okay on my syno in general.

[SpiderKraken]

Arnibanani

Thanks for the reply. I have to say that iam just a "user", hoped theres a "one button"-solution. I'll let it be as it is as long as the server runs okay on my syno in general.

On my end of it the server doesnt run fine due to this, there are sudden kicks, huge slowdowns and rubber banding. Lost a boat as it kicked me and the boat kept going.....then boat reappeared where id docked it later on. That timer of 50+ms in the error constantly increases into the hundreds until it kicks people then it restarts the error on log in. Lloesche should i post my log see if theres anything there that you can see?

[lloesche]

@SpiderKraken definitely can't hurt to take a look. Maybe putting more eyes on it helps in finding a pattern or some underlying root cause. I'm pretty sure it was introduced with the latest Valheim update but I wonder why only some players are affected.

[lloesche]

Couldn't really find anything substantial but looking at the sources at

https://github.com/ValveSoftware/GameNetworkingSockets/blob/3b4787aff7de2aa0ad7dd4ce26d334df0370e2b2/src/steamnetworkingsockets/clientlib/steamnetworkingsockets_lowlevel.cpp#L1459-L1465

this error seems to be thrown if during internal dispatching of UDP packets the acquisition of some lock runs into a timeout taking more than 50ms or a couple of other conditions that are OR'ed into the assert. Because all the logs I've seen so far had a value larger than 50ms I'd assume it's the timeout that's triggering the log entry. From the source comments it sounds like this should never or rarely happen.

And since the linked "fix" is based on allowing the server process to set a negative nice level (making the kernel give more CPU time to the Valheim server) which tbh is not a great idea, I would assume that your system is too heavily loaded for the server to process packets in a timely manner. But then I've found threads where people say that their CPU is not an issue. So I don't know with certainty.

Also this seems to be a new problem introduced with the latest Valheim version and I'm assuming the Steam UDP library has been there from the start.

[SpiderKraken]

My cpu is rarely above 35% with 3 players connected, its ran for days perfectly fine no lag no spam messages or anything. Seems its something that was changed between updates as the patch notes specifically mention affecting sockets bandwidth if i remember correctly

[lloesche]

I was able to reproduce the error by starving my container of CPU resources. Here is what I did. I started a container on a 2 CPU 16 GB Ram VM on my local system. I then ran for i in {1..2}; do while : ; do : ; done & done inside the container to load both CPU cores at 100% and to top it off I did a renice -n 19 on the valheim_server.x86_64 process so it would get a lot less CPU cycles.

I was initially able to connect and the whole thing looked like this:

However after I started shooting some deer and chopping some trees I got this just flooding my log:

which is ironic because the log flooding just made things worse and starved the server of even more CPU.
My client was eventually disconnected from the server.

So I'm not saying this is the root cause for everyone who's seeing this issue, but not having enough CPU resources is a 100% confirmed way of causing the issue.

As mentioned above anyone who would like to filter those messages can start the container with

SERVER_LOG_FILTER='grep --line-buffered -v -e "^\s*$" -e "^(Filename:" -e "Assertion Failed"'

though this won't fix the underlying issue.

[arnibanani]

Thanks for the support, the filter works fine.

[InB4DevOps]

After I got myself an Intel NUC with i5 and 16GB RAM (which I am now using for Plex server and Valheim server) I am no longer seeing these log messages and the gaming experience is much smoother overall.

[lloesche]

@arnibanani just FYI the filter variable is no longer required. Those messages are now filtered by default. The variable doesn't hurt anything but also it doesn't do anything anymore as I've added a much more extensive log filtering system. Details here https://github.com/lloesche/valheim-server-docker#log-filters

[SpiderKraken]

@lloesche

even when cpu is completely normal low usage this issue is still present for me. ive tried adding server_public false to the environment variables to avoid steam sockets but it doesnt appear to work. so even at 35% cpu i get lag just by being in world not doing anything thanks to steam netwroking being rubbish as always. any advice? am i misusing the environment variable?

[InB4DevOps]

AFAIK the unity server uses only a single core. If the single core performance of your CPU is bad then there's nothing much you can do..

[lloesche]

@InB4DevOps well it uses multiple cores, the server starts around 50 threads but only two of them use any CPU cycles to speak of and one of them is doing about 70% of the work when 4 players are connected with the load climbing by around 5-10% on that one core the thread is assigned to (on my 2,4 GHz 6 core system) with each additional player. A dual core 5 GHz system is like the ideal environment for this server.

[SpiderKraken]

I would believe that if the server hadn't ran completely fine for ages prior to this. Im on the ds220+ with 10gb ram added. Server ran fine for like 12 days or so with 5 concurrent players no issues no lag no kicks, soon as the update messed with networking this issue presented and thats with only 3 of the 5 players active . Even with one player its busted

[SpiderKraken]

@InB4DevOps well it uses multiple cores, the server starts around 50 threads but only two of them use any CPU cycles to speak of and one of them is doing about 70% of the work when 4 players are connected with the load climbing by around 5-10% on that one core the thread is assigned to (on my 2,4 GHz 6 core system) with each additional player. A dual core 5 GHz system is like the ideal environment for this server.

didnt really get an answer to my question regarding the usage of the SERVER_ONLINE true/false. its set to false in the environment but still uses steamnetworksockets. iss this not working at all or did i miss a setting ? devs stated that using -online 0 forces direct connection and i asssumed that was what the environment variable did.

[lloesche]

I just merged #176
If you are running docker directly add --cap-add=sys_nice. This will allow the Steam networking library to give itself some more CPU priority which might help give it that bit more CPU cycles to process packages in time.
I also updated the docker-compose file with this capability. Note however if you're still using an older compose file that directory paths in the new one have changed and might need to be adjusted to your system.

When I tested this in my test environment described above it helped a lot with Steam being able to process packages. It's not a magic bullet though. Steam will renice one thread to -10. Once I reniced the two endless loop load tests and gave them more priority -19 the issues were the same.

[SpiderKraken]

Ryzen 5 4.4ghz

[InB4DevOps]

Were you using Docker on Windows in Hyper-V or WSL2 mode? Did you limit system resources for docker?

[SpiderKraken]

Just straight in docker on windows no limit to the cpu. Didnt use WSL2 due to the hassle of installing everything tbh as i hadnt used docker on windows prior to this

[InB4DevOps]

I just repeated @lloesche 's test #104 (comment)

Debian VM with 2 cores and 16GB RAM and I'm also having the same problem once I put high load on the cores.

I don't know why your Ryzen CPU does not perform as good as expected but I think that the bottleneck in your problem is still the CPU in the NAS.

[SpiderKraken]

Why would a cpu bottleneck only appear now though. Its the spam of the message in the log and its constant attempts to use sdr that hogs cpu. The game ran perfectly for weeks prior to this. So its not actually the cpu as under normal operation the cpu is more than enough, its only with this error happening that theres an issue. The server shouldnt be trying to do anything with sdr whatsoever as its only supposed to be direct connect. Swapping to a more powerful cpu isnt actually fixing anything its just not triggering the issue. If it worked fine before then suddenly doesnt that indicates the bug is in the networking code not the system surely

[TheUntouchable]

I have the same problem unfortunately... I run the Docker container on a Synology 218+ with Intel Dual Core @ 2Ghz.

Container is configured with sys_nice and I gave it high CPU priority over the Synology Docker GUI. It sits there at 10-20% CPU load while I'm connected, but it spams my logs and I sometimes have to wait more than 10 seconds to open a chest. Running the same map locally and no problems.... :(

[lloesche]

FYI the latest image will now by default filter the Assertion Failed messages from the log. This will of course not resolve the underlying issue but I figured there's also no value in having the messages flood the log and increase CPU load even more.
If for some reason one WOULD like to have those error messages in the log one can set VALHEIM_LOG_FILTER_STARTSWITH_AssertionFailed to an empty value.