Different globalstep compared to <5.9?

Zughy commented 2 months ago

Minetest version

5.9.1 (both server and client)

Irrlicht device

No response

Operating system and version

Pop!_OS 22.04 LTS

CPU model

i7

GPU model

No response

Active renderer

OpenGL

Summary

Things relying on small afters go slower than they used to, at least online. I had a report from an AES user and I can reproduce that as well. ~~There is no declared dedicated_server_step in our minetest.conf~~ silly me, it's 0.1

Steps to reproduce

download Block League from CDB
put it in a local world of yours
take from creative the submachine gun and shoot by holding down left click: everything works flawlessly
now join the AES server
play a Block League game or play the tutorial
try shooting with the submachine gun: see that it goes slower than in local. Stamina bar also stutters when reloading, something that didn't happen earlier

Submachine gun should shoot every 0.1 (see here). This is also noticeable with the peacifier, which shoots slightly slower than in local (it should shoot every 0.2, see here)

lhofhansl commented 2 months ago

Related? #13370

Zughy commented 2 months ago

@lhofhansl I don't think so, server worked flawlessly on 5.8, and that commit was in 5.8

lhofhansl commented 2 months ago

Or this: #14378? I remember we did some changes around this... Can't seem to find it, though.

Desour commented 2 months ago

Servers started from main menu, including singleplayer, don't use dedicated_server_step.

Zughy commented 2 months ago

Nice to know, but the issue remains: the game acts in two different ways according to local and multiplayer, something that didn't do before we upgraded the server (5.8.0 -> 5.9.1, no 5.9.0 in between)

Zughy commented 2 months ago

@sfan5 verbose log (not my server, but it belongs to a user having the same identical issue). They tried shooting for about 5 seconds, then stopped for 5 more

2024-09-26 00:04:26: INFO[Main]: Handing IAction::Move to manager
2024-09-26 00:04:27: INFO[Main]: Client: Detached inventory update: "creative_test", mode=update
2024-09-26 00:04:27: INFO[Main]: Client::ReceiveAll(): Packet processing budget exceeded.
2024-09-26 00:04:27: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:27: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): 3 playing sounds, 271 unopen sounds, 3 open sounds and 220 sound groups loaded.
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:28: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:29: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:29: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:29: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:29: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:29: INFO[Main]: Client: avg_rtt=0.078
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): 14 playing sounds, 271 unopen sounds, 3 open sounds and 220 sound groups loaded.
2024-09-26 00:04:30: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): Deleted 12 dead playing sounds.
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:30: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:31: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:31: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:31: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:31: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:31: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): 13 playing sounds, 271 unopen sounds, 3 open sounds and 220 sound groups loaded.
2024-09-26 00:04:32: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): Deleted 11 dead playing sounds.
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_reload.ogg"
2024-09-26 00:04:32: INFO[OpenALSoundManager]: OpenALSoundManager: Creating playing sound "bl_smg_shoot.ogg"
2024-09-26 00:04:34: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): 8 playing sounds, 270 unopen sounds, 4 open sounds and 220 sound groups loaded.
2024-09-26 00:04:34: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): Deleted 7 dead playing sounds.
2024-09-26 00:04:35: INFO[Main]: Game lost focus
2024-09-26 00:04:36: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): 1 playing sounds, 270 unopen sounds, 4 open sounds and 220 sound groups loaded.
2024-09-26 00:04:36: VERBOSE[OpenALSoundManager]: OpenALSoundManager::step(): Deleted 1 dead playing sounds.
2024-09-26 00:04:39: INFO[Main]: Irrlicht: Ignoring resize operation to (0 0)
2024-09-26 00:04:39: INFO[Main]: Client: avg_rtt=0.078
2024-09-26 00:04:49: INFO[Main]: Client packetcounter (30s): sum=383 avg=12.7667/s
2024-09-26 00:04:49: INFO[Main]: cmd 2 (TOCLIENT_HELLO) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 3 (TOCLIENT_AUTH_ACCEPT) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 103
2024-09-26 00:04:49: INFO[Main]: cmd 33 (TOCLIENT_ADDNODE) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 39 (TOCLIENT_INVENTORY) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 24
2024-09-26 00:04:49: INFO[Main]: cmd 42 (TOCLIENT_CSM_RESTRICTION_FLAGS) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 47 (TOCLIENT_CHAT_MESSAGE) count 2
2024-09-26 00:04:49: INFO[Main]: cmd 49 (TOCLIENT_ACTIVE_OBJECT_REMOVE_ADD) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 12
2024-09-26 00:04:49: INFO[Main]: cmd 51 (TOCLIENT_HP) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 52 (TOCLIENT_MOVE_PLAYER) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 58 (TOCLIENT_NODEDEF) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 60 (TOCLIENT_ANNOUNCE_MEDIA) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 61 (TOCLIENT_ITEMDEF) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 32
2024-09-26 00:04:49: INFO[Main]: cmd 65 (TOCLIENT_PRIVILEGES) count 2
2024-09-26 00:04:49: INFO[Main]: cmd 66 (TOCLIENT_INVENTORY_FORMSPEC) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 67 (TOCLIENT_DETACHED_INVENTORY) count 10
2024-09-26 00:04:49: INFO[Main]: cmd 69 (TOCLIENT_MOVEMENT) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 71 (TOCLIENT_ADD_PARTICLESPAWNER) count 30
2024-09-26 00:04:49: INFO[Main]: cmd 73 (TOCLIENT_HUDADD) count 87
2024-09-26 00:04:49: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 38
2024-09-26 00:04:49: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 77 (TOCLIENT_HUD_SET_PARAM) count 3
2024-09-26 00:04:49: INFO[Main]: cmd 78 (TOCLIENT_BREATH) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 81 (TOCLIENT_LOCAL_PLAYER_ANIMATIONS) count 2
2024-09-26 00:04:49: INFO[Main]: cmd 84 (TOCLIENT_CLOUD_PARAMS) count 4
2024-09-26 00:04:49: INFO[Main]: cmd 86 (TOCLIENT_UPDATE_PLAYER_LIST) count 2
2024-09-26 00:04:49: INFO[Main]: cmd 96 (TOCLIENT_SRP_BYTES_S_B) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 97 (TOCLIENT_FORMSPEC_PREPEND) count 1
2024-09-26 00:04:49: INFO[Main]: cmd 99 (TOCLIENT_SET_LIGHTING) count 5
2024-09-26 00:04:49: INFO[Main]: Client: avg_rtt=0.078

appgurueu commented 1 month ago

Something that came to my mind: It is possible that this jank is caused by Minetest being more efficient.

If you do minetest.after(0.1, f), f will only be called once $\geq 0.1$ seconds have passed. Which in the worst case is almost one server step (ca. 0.1 seconds) "too late".

If on 5.8, a server step usually took slightly more than $0.1$ seconds, and now it usually takes slightly less than $0.1$ seconds, you'd be observing pretty much exactly what you're seeing: The effect would be delayed by a server step. Note that the default for dedicated_server_step is $0.09$, so this seems realistic to me.

If this is indeed the case, there would be no bug with globalsteps / minetest.after here. As an immediate workaround, you could either increase your server step to ensure it's slightly above $0.1$, or decrease your timers to ensure they are always below the server step. However this will only work really well if the server step matches your expectation / is default.

The best solution would probably be to have an explicit globalstep which tries to approximate this better. A feature for minetest.after to run something slightly too early to not delay it by an entire server step (basically ceil -> round) could also be considered.

Zughy commented 1 month ago

If this is indeed the case, there would be no bug with globalsteps / minetest.after here. As an immediate workaround, you could either increase your server step to ensure it's slightly above 0.1 , or decrease your timers to ensure they are always below the server step. However this will only work really well if the server step matches your expectation / is default.

I highly disagree. This breaks any mod out there relying on small globalsteps, so if your hypothesis is correct it should be up to Minetest to fix this error. We go crazy for small breakages, and this is in my opinion the opposite of small

sfan5 commented 1 month ago

verbose log

May be I wasn't clear, but this needs a server log to diagnose. And a complete one ideally.

appgurueu commented 1 month ago

I highly disagree. This breaks any mod out there relying on small globalsteps, so if your hypothesis is correct it should be up to Minetest to fix this error.

To be precise, if my hypothesis is correct, mods relying on slightly longer globalsteps are broken by globalsteps now being slightly shorter due to performance improvements, which wouldn't be a bug, nor a breakage of backwards compatibility. In that case, both globalsteps and minetest.after would be working as expected.

The crucial measurement for testing my hypothesis would be globalstep dtimes, as reported to globalsteps (since that's what minetest.after uses), both for 5.8.0 and 5.9.1 with the observed behavior.

We go crazy for small breakages, and this is in my opinion the opposite of small

I can't judge the extent of this yet. But what would you want to happen? The two main options I see are both in my opinion worse than properly addressing this in mods:

Change the default from 0.09 to 0.1. This is probably the least bad option, but I'm definitely not happy with it: First, it adds 10% jank, just as default config. Second, there probably was a reason for the 0.09 (a little bit of budget to hit the 0.1 even if a few steps take a bit too long?). Third, it sort of is a breaking change as well, and could have the reverse effect on systems that were fast before (e.g. "something took two server steps before, now it only takes one"). We also don't want modders to rely on this default to begin with; mods should work with different server steps as well.
Change the behavior of minetest.after to run server steps prematurely if they are projected to otherwise run more than half a server step too late. Now this would be a breaking change.

Ultimately, mods which do minetest.after(slightly above server step, function() ... end) will always be brittle (e.g. may be off by a server step, which is the difference betwen 1x and 2x here, depending on how long globalsteps take, which depends both on user settings and Minetest performance) due to the discretization imposed by globalsteps.

Modders have to decide how to deal with this; if we figure out a good API, we can also put it in the engine. Prematurely running something is an option, but then you will probably want to keep track of some sort of "overtime".

zJudGenie commented 1 month ago

verbose log

May be I wasn't clear, but this needs a server log to diagnose. And a complete one ideally.

Here it is the debug.txt of the server in verbose mode debug.txt

sfan5 commented 1 month ago

Second, there probably was a reason for the 0.09

bad news: the reason was just "let's make it a little faster", see #6252

I thought about increasing it to 1/12 recently but after collecting some info from public servers I realized that most don't even reliably make 1/11 (current value) so it's probably not a good idea.

nerzhul commented 1 month ago

it's me who did this PR 7 years ago, then it's not very recent. If i remember it was done like this to increase by 10% the batching things which doesn't rely on timers without consuming much CPU. I think the more we are optimized the more we should reduce it to permit tinier batches of updates instead of big ones.

sfan5 commented 1 month ago

Here it is the debug.txt of the server in verbose mode debug.txt

Thanks. As far as I can see the problem is not network related.

I think to get to the bottom of this issue we'll need a measurement of the actual time elapsed between minetest.after and the callback. Either via dtime or get_us_time() in case those differ.

We should also add a warning to the documentation that minetest.after works only in units of the server step so the potential variance is high for times close to the server step.

Zughy commented 1 month ago

Apaprently setting the dedicated server step to 0.101 fixes that

MisterE123 commented 1 month ago

IDK if its related but with a server step set to .001 (so as fast as possible) the balloon entities in balloon_bop started not falling and being removed when I upgraded to 5.9.1.

setting the step to .101 "fixed" that too

HybridDog commented 1 month ago

I think the documentation should mention that the time passed to minetest.after is a lower bound and can be exceeded due to lag or the server step granularity.

Mods which rely on time-dependent behaviour should measure time differences with minetest.get_us_time and not rely on times passed to minetest.after. Minetest usually is not run on a real-time operating system, so (in my opinion) the programmer should expect that Minetest does not wait the exact time passed to minetest.after, similarly to the sleep function in C and other programming languages.

To reduce batching, I think the default value for the server step should be a number which cannot accurately be approximated by a rational number with small denominator and nominator. For example, it can be set to the golden ratio times a simple rational number which brings it close to 0.9: $\frac{1+\sqrt{5}}{2} \cdot \frac{11}{20} \approx 0.88991869381244$

sfan5 commented 1 month ago

I don't think this issue warrants the "Bug" label (implying it is confirmed). So far we just have two "my game doesn't work correctly anymore, changing server step fixes it" with no light shone on the space in between.

Here's code to measure what I mentioned:

local TARGET = 0.1
local gtimer = 0
local last1, last2
local c1, c2 = {}, {}
local function output(arr, s)
    s = s or "" 
    if #arr == 0 then
        print(s .. "no data")
        return
    end
    local mean = 0
    local min, max = arr[1], arr[1]
    for _, v in ipairs(arr) do
        mean = mean + v
        min = math.min(min, v)
        max = math.max(max, v)
    end
    mean = mean / #arr
    local stddev = 0
    for _, v in ipairs(arr) do
        stddev = stddev + math.pow(mean - v, 2)
    end
    stddev = math.sqrt(stddev / #arr)
    print(s .. string.format("N=%d μ=%f σ=%f MIN=%f MAX=%f", #arr, mean, stddev, min, max))
end
local function step()
    local now1 = core.get_us_time()
    local now2 = gtimer
    if last1 ~= nil then
        table.insert(c1, (now1 - last1) / 1000)
        table.insert(c2, (now2 - last2) * 1000)
    end
    last1 = now1
    last2 = now2
    if #c1 >= 5 / TARGET then
        output(c1, "realtime   : ")
        c1 = {}
        output(c2, "ingame time: ")
        c2 = {}
    end
    core.after(TARGET, step)
end
-- ensure we get to count before minetest.after runs
table.insert(core.registered_globalsteps, 1, function(dtime)
    gtimer = gtimer + dtime
end)
core.after(0, step)

To reduce batching, I think the default value for the server step should be a number which [...]

And that would have which advantage? Mathematically less likely to "collide" with fractions? I doubt the practical advantage.

Mods which rely on time-dependent behaviour should measure time differences with minetest.get_us_time

Not really, because pausing the game then no longer works. Writing code that relies on wall clock time but deals with ingame actions is a problem in itself.

sfan5 commented 1 month ago

My measurement results: 5.10.0-dev singleplayer:

realtime   : N=50 μ=113.599040 σ=3.341782 MIN=106.622000 MAX=134.029000
ingame time: N=50 μ=113.604680 σ=3.109449 MIN=106.606001 MAX=134.014003

5.10.0-dev server:

realtime   : N=50 μ=178.408980 σ=0.126228 MIN=178.259000 MAX=178.829000
ingame time: N=50 μ=178.401440 σ=0.132277 MIN=178.253002 MAX=178.824000

the SP result is off by 13ms which is reasonably close to 60fps (= 16ms) the server result is pretty much expected due to what @appgurueu explained (2*90ms = 180ms)

feel free to test older versions with that we could tell if it's gotten worse. but still that doesn't necessarily make this a bug.

MisterE123 commented 1 month ago

Edit: Just tested: Server step: 0.01: balloon entities don't fall as fast and spin much faster than normal Server step: 0.1: Balloon entities fall and spin normally Server step: 0.101: Same as 0.1

MisterE123 commented 1 month ago

Edit: this is the mod code's fault. Please minimize all my comments

HybridDog commented 1 month ago

And that would have which advantage? Mathematically less likely to "collide" with fractions?

Yes; I think many timers elapse at simple fractions, e.g. 1/60 s for display refresh, 1/125 s for mouse polling rate, etc.. I also doubt the advantage of this and of using 0.09 instead of 0.1 without tests confirming it.

zJudGenie commented 1 month ago

feel free to test older versions with that we could tell if it's gotten worse. but still that doesn't necessarily make this a bug.

I did some measurements in our docker container with the server.

I got this using 5.9.1(with the problem)

5.9.1 measurements

``` realtime : N=50 μ=183.998820 σ=36.420352 MIN=98.454000 MAX=218.531000 ingame time: N=50 μ=183.782399 σ=36.540041 MIN=100.006998 MAX=211.410999 realtime : N=50 μ=185.135240 σ=34.488907 MIN=97.457000 MAX=202.006000 ingame time: N=50 μ=185.313379 σ=34.384307 MIN=100.018002 MAX=200.487994 realtime : N=50 μ=189.305980 σ=29.721759 MIN=98.770000 MAX=201.044000 ingame time: N=50 μ=189.273699 σ=29.721638 MIN=100.024000 MAX=199.921004 realtime : N=50 μ=187.424440 σ=32.234137 MIN=99.689000 MAX=201.442000 ingame time: N=50 μ=187.415279 σ=32.171921 MIN=100.034997 MAX=200.150996 realtime : N=50 μ=183.480940 σ=36.312941 MIN=99.044000 MAX=201.537000 ingame time: N=50 μ=183.459159 σ=36.355079 MIN=100.001000 MAX=201.094992 realtime : N=50 μ=175.450920 σ=42.312766 MIN=98.196000 MAX=201.410000 ingame time: N=50 μ=175.419259 σ=42.329386 MIN=100.010000 MAX=199.960999 realtime : N=50 μ=183.368360 σ=36.329885 MIN=98.918000 MAX=202.897000 ingame time: N=50 μ=183.332539 σ=36.328203 MIN=100.038998 MAX=201.967999 realtime : N=50 μ=185.355540 σ=34.266126 MIN=99.234000 MAX=201.045000 ingame time: N=50 μ=185.360700 σ=34.255694 MIN=100.050002 MAX=200.038999 realtime : N=50 μ=191.320060 σ=27.391042 MIN=93.991000 MAX=204.514000 ingame time: N=50 μ=191.287060 σ=26.889955 MIN=100.074001 MAX=200.072996 realtime : N=50 μ=179.660440 σ=39.382771 MIN=99.546000 MAX=200.808000 ingame time: N=50 μ=179.655139 σ=39.394451 MIN=100.016996 MAX=200.634994 realtime : N=50 μ=173.498040 σ=43.258293 MIN=99.117000 MAX=201.090000 ingame time: N=50 μ=173.477919 σ=43.485755 MIN=100.000001 MAX=200.091004 realtime : N=50 μ=179.633840 σ=39.659509 MIN=97.368000 MAX=201.356000 ```

And this using 5.8.0(without problems)

5.8.0 measurements

``` realtime : N=50 μ=101.036900 σ=13.958308 MIN=90.727000 MAX=122.077000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.408740 σ=14.331324 MIN=90.811000 MAX=122.134000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=100.868580 σ=14.163343 MIN=90.891000 MAX=122.952000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.451620 σ=14.443328 MIN=90.857000 MAX=124.159000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=100.894400 σ=14.119361 MIN=90.872000 MAX=122.736000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.409680 σ=14.374191 MIN=90.766000 MAX=122.350000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.093520 σ=14.081378 MIN=90.828000 MAX=122.302000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.010720 σ=14.170426 MIN=90.839000 MAX=124.723000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.354140 σ=14.421130 MIN=90.843000 MAX=124.007000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=100.961580 σ=14.113927 MIN=90.847000 MAX=122.473000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 realtime : N=50 μ=101.462380 σ=14.459851 MIN=90.774000 MAX=124.737000 ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004 ```

Sorry but I don't know how to interpret them.

appgurueu commented 1 month ago

Sorry but I don't know how to interpret them.

N is the number of trials; MIN and MAX should also be pretty self explanatory. µ is the average value. σ is the standard deviation (the larger this is, the more values deviate from the average). Since the results seem to be consistent across runs, we can basically compare ingame time and real time results for 5.8 and 5.9.1.

I'll start with 5.8. We have:

realtime   : N=50 μ=101.036900 σ=13.958308 MIN=90.727000 MAX=122.077000
ingame time: N=50 μ=101.000004 σ=0.000000 MIN=101.000004 MAX=101.000004

(First, a question, just to be sure: Dedicated server step was left at the default setting of 0.09 here, right? Because it's a bit surprising to see 0.101, which would be the value to work around this artifact, so exactly)

If we assume this is correct, in terms of ingame time and also approximately real time, we're essentially always exactly on time.

Given that there appear to be real time steps of 90 ms, it is also very surprising to not see ingame time steps of 90 ms when that is the target dedicated server step.

Now 5.9.1. We have:

realtime   : N=50 μ=183.998820 σ=36.420352 MIN=98.454000  MAX=218.531000
ingame time: N=50 μ=183.782399 σ=36.540041 MIN=100.006998 MAX=211.410999

Clearly the problem is visible: On average we're taking ca. 2x 90 ms server steps to execute the minetest.after. Sometimes a serverstep is slower and then we get on time execution (so we get MIN=100.006998), but this happens less often.

So far everything seems consistent with my theory. But I think the simplest way to confirm it would be just some globalstep times: minetest.register_globalstep(print), maybe also realtime differences on top. On the new version I'd expect to see values < 0.1 much more often than on the older version.

Probably the simplest way to resolve this will be to set a dedicated server step of 0.101 as the new default. Given that that's what older MT versions apparently practically delivered anyways, nobody should be upset by this, and probably common minetest.after(0.x, ...) invocations should work reasonably well. People who want faster server steps can still set something like 0.051. Frankly if we can eventually deliver it we should probably consider that as the default.

sfan5 commented 1 month ago

I think we should figure out what caused this before trying to fix it by tweaking the step size. 322c4a5b2b8343c3942555c6a337e765ef84c3c4 comes to mind as it was between 5.8 and 5.9

Also because as far as I can tell changing the step size will just move the "area of problematic dtimes with minetest.after" to a different spot.

sfan5 commented 1 month ago

...however here are my test results with 5.8.0 (dedicated server, default config):

ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007
realtime   : N=50 μ=179.950080 σ=5.865038 MIN=150.807000 MAX=182.629000
ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007
realtime   : N=50 μ=180.293480 σ=4.180058 MIN=151.098000 MAX=181.889000
ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007
realtime   : N=50 μ=180.190640 σ=4.219275 MIN=150.704000 MAX=181.845000
ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007
realtime   : N=50 μ=180.193080 σ=4.234210 MIN=150.577000 MAX=181.622000
ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007

This suggests 5.8.0 even performs worse than 5.9.0 (by 3ms) and we still don't know what the bug is about.

sfan5 commented 1 month ago

Nor do I notice any difference with the reproduction steps:

https://github.com/user-attachments/assets/808ca59b-4e9b-4368-ad85-1c1acaeb5ce5

https://github.com/user-attachments/assets/c55b9ac9-37b3-4078-a4cb-0e62a3736d62

(standalone server in both cases, config is literally empty)

Zughy commented 1 month ago

What can we do as a next step @sfan5 ?

sfan5 commented 1 month ago

You can try to isolate the problem so it can be reproduced outside of your server.

In general it'd also be interesting to know if dedicated_server_step = 0.101 fixes the issue for you (it should).

nerzhul commented 1 month ago

you can tweak the server step if you want, it's intended to be carefully modified if needed. The more steps we do, the less tiny our updates batches are, but are done more often. I remember that before optimization engine was unable to step under 0.1 step before because it was too slow, it was reduced afterwards when engine can do its batches in time because it was sufficiently optimized. Increasing it meaning you will be less reactive for the networking part, and do bigger engine updates at the same time. The lag issue may be to mods doing too much on the step and making the step lag from the 0.9 target. Can you check how much mods are relying on the on_step on your side, it may explain your issue.

Zughy commented 1 month ago

@sfan5 yes, 0.101 does fix the issue, we've been using it for days (we didn't use it for the tests @zJudGenie published though)

zJudGenie commented 1 month ago

(First, a question, just to be sure: Dedicated server step was left at the default setting of 0.09 here, right? Because it's a bit surprising to see 0.101, which would be the value to work around this artifact, so exactly)

I forgot to mention that our dedicated_server_step was set to 0.1 and not to the default 0.09 @appgurueu

HybridDog commented 1 month ago

In case the problem is not caused by the server step but something else, for example network packet handling, metrics calculated on the server-side step time do not suffice. Maybe for an end-to-end test, we can modify OpenALSoundManager::createPlayingSound such that it saves the current time in microseconds if sound_name is "bl_smg_shoot.ogg", and then analyse these times, e.g. with a histogram plot of time differences.

Zughy commented 1 month ago

We'll be able to run multiple tests on Wednesday. What should we do exactly? What HybridDog suggests?

Zughy commented 1 month ago

Update We've tried disabling the audio calls completely (removing the sound from the weapon declaration): no changes. We've then updated to latest 5.10-dev: no changes (both with and without sounds)

We honestly don't know what else we can try. We'll start bisecting

Zughy commented 1 month ago

Bisect result, commit at fault: https://github.com/minetest/minetest/commit/322c4a5b2b8343c3942555c6a337e765ef84c3c4. @sfan5 @Desour . Both on 5.8 and 5.9.1 clients, default step

@lhofhansl was actually right and I don't seem to be able to check dates properly :))) 5.8 was prior to that commit of about 20 days (5.8.1 wasn't, but our server was just 5.8)

Maybe https://github.com/minetest/minetest/commit/322c4a5b2b8343c3942555c6a337e765ef84c3c4#diff-affef3b48d01251c90ee530ca02913c0f3a65157db648286256cc787f5e4ba53L2768-R2772 ?

Good commit

Bad commit

Desour commented 1 month ago

Bad commit

Looks like you're using dedicated_server_step=0.1. If you want to compare with singleplayer, you have to set it to 0.01666666666667. If I do this, I see no noticeable difference between singleplayer and dedicated server. If you're using a larger target dtime, core.after is supposed to trigger later.

https://github.com/minetest/minetest/commit/322c4a5b2b8343c3942555c6a337e765ef84c3c4 is supposed to change globalstep. Globalstep dtimes are more consistent and correct now. So, not a bug?

Explanation what is happening in master: If you core.after(0.1, ...), and if serverstep always reaches its target, assuming 0.09s target (dedicated server default), the after will trigger always two steps later (because 0.09 < 0.1, 0.18 >= 0.1). If you want to have a weapon that shoots at a 1/0.1 Hz rate on average, core.after is not suited for this, because it takes the 0.1 as upper limit at each shot. If you want 1/0.1 Hz on average, and the last one took longer than 0.1 s, you'll have to wait shorter for the next one. Related: #15047

You may also want to print statistics about the dtime, btw.: https://codeberg.org/Desour/test_tmp/commit/eb977bbd8165f81308404751b6acf25424fcbf1c

Zughy commented 1 month ago

Server and client worked the same way until that commit, or at least it wasn't possible to perceive any difference. I've been bikeshed to death in the past for really silly things, sorry but hearing "no bug" for this thing sounds absurd: we had to change the globalstep of the server to maintain the old behaviour, meaning that according to the MT version people should set a different globalstep to run some mods as intended (it's not our case since Block League won't be compatible with 5.8 servers, but it's quite unlikely that it's the only mod out there affected by this behaviour). I'll let @zJudGenie take care of the rest, as he's the sysadmin and I know nothing of it. I just wanted to clarify a couple of things

SmallJoker commented 1 month ago

I can see that tight step timings can be essential for mods that implement competitive mechanics (such as FPS), but that's no reason to waste CPU cycles (also on mobile phones) if not necessary.

I can think of the following solutions:

Mod API to request a lower step time if needed.
Change the core.after logic to a catch-up mechanism like implemented in node timers. Process events (e.g. arrow shooting) based on the cumulative dtime since the time this batch processing was executed.
Other ideas?

From what I can see, the singleplayer step period is simply not documented.

sfan5 commented 1 month ago

This issue is becoming spaghetti of test results.

@Zughy can you confirm if you tested this in singleplayer with a standalone server instance? If the latter, what was dedicated_server_step set to?

Singleplayer and multiplayer step times were never the same, not before and not after that commit. SP times are variable but much smaller (bound to frame rate) so probably won't reproduce the problem. So without confirming this we can't reason about it in valid ways.

Desour commented 1 month ago

SP times are variable but much smaller (bound to frame rate)

(To be exact: Now in master it's bound to target frame rate, not reached frame rate.)

And dedicated server dtime used to just take exactly the dedicated server step stepsize as dtime, or a multiple of it. This is also why core.after with 0.1 waited so shortly with 0.1 s stepsize setting. In master it's the actual dtime.

Zughy commented 1 month ago

@sfan5 it's a server hosted by @zJudGenie on a VPS, not a server launched via singleplayer. If I test it on a singleplayer server (connecting another client) the issue doesn't occur on the client hosting the server, but it happens on the one that connected (maybe a little faster than on AES but still slower than the one hosting)

sfan5 commented 1 month ago

Okay, so dedicated server.

That means

https://github.com/minetest/minetest/commit/322c4a5b2b8343c3942555c6a337e765ef84c3c4#diff-affef3b48d01251c90ee530ca02913c0f3a65157db648286256cc787f5e4ba53L2768-R2772 ?

isn't relevant. It applies only to SP. The explanation given by @Desour (or @appgurueu much earlier) would apply there.

I went and tested again with docker containers this time. ghcr.io/minetest/minetest:5.9.1:

realtime   : N=50 μ=179.004800 σ=0.151475 MIN=178.683000 MAX=179.322000
ingame time: N=50 μ=178.997379 σ=0.158551 MIN=178.653002 MAX=179.315001

registry.gitlab.com/minetest/minetest/server:5.7.0:

realtime   : N=50 μ=180.567340 σ=8.293745 MIN=152.244000 MAX=183.723000
ingame time: N=50 μ=180.000007 σ=0.000000 MIN=180.000007 MAX=180.000007

This doesn't mirror your results at all. So there is yet something missing to actually reproduce this.

If I test it on a singleplayer server (connecting another client) the issue doesn't occur on the client hosting the server, but it happens on the one that connected (maybe a little faster than on AES but still slower than the one hosting)

So far we've been assuming that this is a timing issue with the server step. But this doesn't add up. It can't possibly work fine for one client but not the other on the same server.

Zughy commented 1 month ago

So far we've been assuming that this is a timing issue with the server step. But this doesn't add up. It can't possibly work fine for one client but not the other on the same server.

Proof: on the left, server host, on the right, connected client.
5.9.1
It takes about 3s to empty the magazine on the left, about 4.5 on the right.
There are no other mods enabled aside MTG's and the ones needed for Block League. Disabling the shooting sound doesn't change anything.
Step length is not declared

https://github.com/user-attachments/assets/63000686-701d-49f9-97e3-2a946e049791

Desour commented 1 month ago

Is this issue now about clients connected to mainmenu hosted servers (those are different to dedicated servers, because they use the same fps step time as in SP, and if you unfocus the hoster client, the server step gets slower)? (dedicated_server_step still decides in what intervals packets are sent.) That video doesn't show which client recorded the audio, btw..

There's still no proper minimal reproducer. And I won't instead dig through that gun mod's code. The only thing here that comes near is sfan5's core.after measurement snippet, but it does nothing unexpected (it's just different if a mod relies on server steps being multiples of 0.1, which is unspecified and didn't use happen in many cases (different dediservstep setting, SP) anyways).

This is just too vague.

Zughy commented 1 month ago

Is this issue now about clients connected to mainmenu hosted servers

The issue happens both with those and with dedicated servers

That video doesn't show which client recorded the audio, btw..

Both, as the sound doesn't halve when I switch client

And I won't instead dig through that gun mod's code.

This is the shooting loop
https://gitlab.com/zughy-friends-minetest/weapons_lib/-/blob/main/src/api/weapons.lua?ref_type=heads#L604
where the following gets called since the weapon has continuous fire (meaning I can hold down the action key to keep shooting)
https://gitlab.com/zughy-friends-minetest/weapons_lib/-/blob/main/src/api/weapons.lua?ref_type=heads#L635

This is the weapon definition. Left click is action1 table
https://gitlab.com/zughy-friends-minetest/block_league/-/blob/master/block_league/src/weapons/smg.lua

This is the dev version, it won't work on <5.9, but the one on CDB will. If you need more info about the functioning of the mod, just ask

sfan5 commented 1 month ago

Proof: on the left, server host, on the right, connected client. 5.9.1 It takes about 3s to empty the magazine on the left, about 4.5 on the right.

Singleplayer does funny things like reduce the FPS (and therefore the server step) once the window of the "host" client is not in focus. In my tests this changes the time delta from 113 to 148ms, which more or less matches the durations you gave (assuming a magazine of 30).

But we're still guessing at things again, so let me be very clear: Before we have reproduction steps that rely on hard data there is no point for me to even open this issue again.

that means:

hard numbers: make the gun code log timestamps or delays. even better if the test case does not rely on block league at all (like mine). not "you can hear/see the gun is too slow".
dedicated server, not singleplayer
must show the regression between 5.8.0 and 5.10.0-dev
does not rely on more than 1 person on the server
by definition anyone should be able to follow these steps and see the difference

Zughy commented 1 month ago

Stand-alone mod replicating the gun behaviour, try it with

minetest.register_node(minetest.get_current_modname() .. ":node", {
    description = "Test node",
    tiles = {"server_favorite.png"},
    inventory_image = "server_favorite.png",
    groups = {cracky = 3},

    on_use = function(itemstack, user, pointed_thing)
        loop(user, 0)
    end
})

local function loop(player, prev)
    local curr_time = minetest.get_us_time()
    minetest.chat_send_player(player:get_player_name(), curr_time - prev)
    if not player:get_player_control()["LMB"] then return end
    minetest.after(0.1, function() loop(player, curr_time) end)
end

find the test item in creative
hold it in your hand
keep pressed the left click to start logging. Ignore the first message

Before the commit at fault:

Commit at fault:

It's basically doubled.

Beware:

there are other mods in the server, we can try again tomorrow with no mods at all
we haven't tested with 5.10-dev as the issue is the same from that commit. If really needed, we'll test with 5.10-dev tomorrow

@sfan5

Desour commented 1 month ago

Thanks.

What is dedicated_server_step set to? (I get the same results with 0.1, so I'm assuming this.)

Nothing unexpected is happening here, as already explained above: dtime used to be in multiples of dedicated_server_step on dedicated servers. (This was unspecified behaviour. If a mod depends on this, it's not our issue.) So if you after with 0.1, and set dedicated_server_step=0.1, it happened to wait shorter than in master. You can also set dedicated_server_step=0.11 to get a faster after(0.1, ...), btw..

(FYI: core.after isn't really designed to work well with short delays that aren't 0. It's always off up to one dtime.)

Zughy commented 1 month ago

What is dedicated_server_step set to?

0.1

This was unspecified behaviour. If a mod depends on this, it's not our issue

How was I supposed to know that something that worked for years was expected to actually work differently? Like, it's been years I've been reporting every bug I encounter, so if I did think something was off I would actually have opened an issue.

This fix broke half of our server and there is no mention in the documentation about how core.after calls are supposed to work (or at least, I can't find it). I mean, I'm learning about core.after not being suited for delays shorter than one second only now, when I've been actively modding since 2020 and after a month of testing. If that parenthesis you've written had been put in the documentation, we probably wouldn't have been here discussing that much. Actually, that would have allowed me to open an issue. So I don't think it's fair blaming us for using an "unspecified behaviour". Unless, again, I'm missing a clear state in the docs.

Furthermore, I think that the current behaviour is counterintuitive: why something that takes 0.1s to run, in a server that runs ever 0.1s, is supposed to run after 0.2? Like, what am I supposed to write in the weapons_lib documentation? "If you're thinking the weapon delay is supposed to be 0.1, write 0.09 instead due to \<stuff>, but only if you're running a dedicated server"? It sounds like a bug to me.

I'm also pretty sure that this change broke other things out there (basically any 0.1 after that is now taking twice the time in dedicated servers)

minetest / minetest