Fix and improve max_lag

OgelGames commented 3 years ago

Lag is now calculated inside the mod, instead of being extracted from server status.

Fixes #166 and #191

S-S-X commented 3 years ago

If going for average then is it possible to use https://github.com/mt-mods/technic/blob/fd4bece11a633e665cf73c782bb1d2032169ee88/technic/machines/network.lua#L382-L394 which already exists and almost sure outperforms anything else when it comes to overhead of calculating averages? It might be possible to drop max_lag.lua/lag.lua completely while reducing total lines of code and increasing performance.

However if it seems that doing it will require changes to sma function then probably should not be done as it can actually benefit from performance somewhat while lag.lua functions executed only once / globalstep wont benefit that much.

OgelGames commented 3 years ago

I don't think that should be used in this case, the method I used aims to sample every globalstep, while avoiding calculations being done every globalstep; instead they are only done when the functions are called (which is no more than once a second).

S-S-X commented 3 years ago

I don't think that should be used in this case, the method I used aims to sample every globalstep, while avoiding calculations being done every globalstep; instead they are only done when the functions are called (which is no more than once a second).

Yes, I think that fact makes it better to have separate function that calculates average for whole table instead of rolling average calculated for single added value is probably better even while table does contain 100 entries and average globalstep is only about 100ms favoring per value calculation more vs per call calculation cost but I think not enough to warrant changing it.

Also if someone wants to make average for get_avg_lag based only 10 values (or probably even for 20 values) then globalstep continuous would be worse and only benefit would be from spreading (very small) workload over longer time.

BuckarooBanzay commented 3 years ago

ok, this is nicer than my ugly hack :+1: Just a heads-up: the dtime value may never exceed 2 seconds: https://github.com/minetest/minetest/blob/e9bc59e376f88f1d4d1c6d3fedf62d9049e3e60d/src/server.cpp#L524-L526

OgelGames commented 3 years ago

the dtime value may never exceed 2 seconds

That's strange... Explains this though: https://github.com/minetest-monitoring/monitoring/blob/master/builtin/lag.lua#L28-L30

S-S-X commented 3 years ago

Tested a bit, generated 5 seconds artificial globalstep lag (busy loop in globalstep) and checked how this responds. Engine 4.9 seconds lag reported. Technic.get_avg_lag 0.158 seconds lag reported.

Multiple 15 seconds lag spikes, bit over 0.2 seconds reported by technic.get_avg_lag and engine reporting just bit less than 15 seconds lag.

This will change completely how technic globalstep lag check mechanism will actually respond to different lag spikes, it might be fine or it might need some adjustments. Maybe still make it respond bit faster by reducing size of table where values are collected, some 20 - 50 possibly?

Still remember that what I tested was probably not anywhere near any real situation but it still shows that response is maybe bit too slow especially compared to previous instant response. Reducing table size will also affect similar way when reducing high averages back to normal when actual globalstep lag gets down, response is faster and technic globalstep frequency gets higher bit sooner when lag is over.

As averages are collected over very long time it does not really detect high lag spikes (and respond fast) which can be useful when attempting to fix situation in game (you know, that happened many times).

S-S-X commented 3 years ago

For actual server testing maybe it could be useful to add current average lag values to output of command, possibly just add another value for technic.get_avg_lag here: https://github.com/mt-mods/technic/blob/64237957e472c35c81e257ed59026500098808ee/technic/machines/init.lua#L96-L99

So that running /technic_get_active_networks would say something like:

Cached network data: 2 active networks, 4 total networks, 16 network nodes, 0.256s avg lag

... network data report rows ...

OgelGames commented 3 years ago

Tested a bit, generated 5 seconds artificial globalstep lag (busy loop in globalstep) and checked how this responds. Engine 4.9 seconds lag reported. Technic.get_avg_lag 0.158 seconds lag reported.

Hmm... maybe the method MT uses is better, but then that is a bit too slow to return back to normal after a short lag spike... 🤔

S-S-X commented 3 years ago

Hmm... maybe the method MT uses is better, but then that is a bit too slow to return back to normal after a short lag spike..

Yes, I think this new system is a lot better as max_lag returned by engine will take extremely long time to go down if it gets high enough. But some tuning is needed as it should really also get higher a lot faster, simplest way to make it do that (and also even return back to normal faster when lag is over) is to reduce table size making single value to affect average a lot more.

Other way to add faster response would be to scale added values by multiplying input (and counter this accordingly when reading averages), that makes higher values more significant.

Or calculate averages by using only say 10 highest values which would account more for short lag spikes, might or might not be useful... this could also be tuned for example to drop 40 highest and 40 lowest values and use 20 remaining to calculate average.

OgelGames commented 3 years ago

Maybe this would work? It's basically the same as the way the engine calculates max_lag, but it decreases faster. (* 0.9 instead of * 0.9998)

local last_step = minetest.get_us_time()

local max_lag = 0

minetest.register_globalstep(function()
    -- Calculate own dtime as a workaround to 2 second limit
    local now = minetest.get_us_time()
    local dtime = now - last_step
    last_step = now

    max_lag = max_lag * 0.9  -- Decrease slowly

    if dtime > max_lag then
        max_lag = dtime
    end
end)

function technic.get_max_lag()
    return max_lag / 1000000
end

Could also tie that multiplier to a setting too... 🤔

S-S-X commented 3 years ago

Maybe this would work? It's basically the same as the way the engine calculates max_lag, but it decreases faster. (* 0.9 instead of * 0.9998)

I think this would work fine, better than what engine does anyway. I however liked average values bit more however as it would smooth out occasional single server step lag spikes while still providing very useful averages.

For useful averages you don't really need many values to do that, network lag detection did it very well with just 3 values but still used 5 values (no specific reason for 5 values... it was just largest where I was not able to measure performance with get_us_time at all).

Could also tie that multiplier to a setting too... 🤔

Yes, would be good idea to allow easier adjustment.

OgelGames commented 3 years ago

So I decided the only way to figure out this properly was to test the different methods, and plot them on a graph:

Orange = max_lag from the engine (pulled from server status),
Green = technic.get_max_lag() in this PR
Blue = technic.get_avg_lag() in this PR
Red = max_lag calculated with a multiplier of 0.99.

lag-graph https://app.rawgraphs.io/

You were definitely right about technic.get_avg_lag() not responding to lag spikes... 👀

S-S-X commented 3 years ago

So I decided the only way to figure out this properly was to test the different methods, and plot them on a graph:

Did not test in game again but I think this can be merged. While it does not provide any smoothing for very short lag spikes looking at graphs you provided this is clearly way better for technic lag control purposes than engine status parsing and it responds to lag spikes immediately just like engine status parsing did.

Maybe I'll add lag value to network stats command, not exactly required but can still be useful to confirm in game what is happening.

github-actions[bot] commented 3 years ago

Click for detailed source code test coverage report

### Test coverage report for Technic CNC 79.43% in 8/8 files: ``` File Hits Missed Coverage ----------------------------------------------------- api.lua 157 83 65.42% cnc.lua 50 3 94.34% digilines.lua 39 8 82.98% formspec.lua 103 8 92.79% init.lua 19 6 76.00% materials.lua 174 94 64.93% pipeworks.lua 25 13 65.79% programs.lua 263 0 100.00% ``` ### Test coverage report for technic 9.56% in 10/102 files: ``` File Hits Missed Coverage -------------------------------------------------------------- config.lua 46 4 92.00% crafts.lua 0 86 0.00% effects.lua 0 3 0.00% helpers.lua 0 116 0.00% init.lua 0 30 0.00% integration_test.lua 0 24 0.00% items.lua 0 51 0.00% legacy.lua 0 7 0.00% machines/HV/battery_box.lua 0 6 0.00% machines/HV/cables.lua 9 26 25.71% machines/HV/compressor.lua 0 6 0.00% machines/HV/electric_furnace.lua 0 6 0.00% machines/HV/forcefield.lua 0 213 0.00% machines/HV/generator.lua 9 0 100.00% machines/HV/grinder.lua 0 6 0.00% machines/HV/init.lua 0 12 0.00% machines/HV/nuclear_reactor.lua 0 266 0.00% machines/HV/quarry.lua 0 304 0.00% machines/HV/solar_array.lua 0 6 0.00% machines/LV/alloy_furnace.lua 0 6 0.00% machines/LV/battery_box.lua 0 6 0.00% machines/LV/cables.lua 10 26 27.78% machines/LV/compressor.lua 0 10 0.00% machines/LV/electric_furnace.lua 0 6 0.00% machines/LV/extractor.lua 0 13 0.00% machines/LV/generator.lua 0 7 0.00% machines/LV/geothermal.lua 0 56 0.00% machines/LV/grinder.lua 0 7 0.00% machines/LV/init.lua 0 16 0.00% machines/LV/lamp.lua 0 107 0.00% machines/LV/music_player.lua 0 81 0.00% machines/LV/solar_array.lua 0 6 0.00% machines/LV/solar_panel.lua 0 27 0.00% machines/LV/water_mill.lua 0 47 0.00% machines/MV/alloy_furnace.lua 0 6 0.00% machines/MV/battery_box.lua 0 6 0.00% machines/MV/cables.lua 10 26 27.78% machines/MV/centrifuge.lua 0 6 0.00% machines/MV/compressor.lua 0 6 0.00% machines/MV/electric_furnace.lua 0 6 0.00% machines/MV/extractor.lua 0 6 0.00% machines/MV/freezer.lua 0 6 0.00% machines/MV/generator.lua 0 7 0.00% machines/MV/grinder.lua 0 6 0.00% machines/MV/hydro_turbine.lua 0 44 0.00% machines/MV/init.lua 0 17 0.00% machines/MV/lighting.lua 0 170 0.00% machines/MV/power_radiator.lua 0 96 0.00% machines/MV/solar_array.lua 0 7 0.00% machines/MV/tool_workshop.lua 0 73 0.00% machines/MV/wind_mill.lua 0 45 0.00% machines/compat/digtron.lua 0 13 0.00% machines/init.lua 0 85 0.00% machines/network.lua 193 163 54.21% machines/other/anchor.lua 0 79 0.00% machines/other/coal_alloy_furnace.lua 0 94 0.00% machines/other/coal_furnace.lua 0 3 0.00% machines/other/constructor.lua 0 103 0.00% machines/other/frames.lua 0 551 0.00% machines/other/init.lua 0 8 0.00% machines/other/injector.lua 0 85 0.00% machines/power_monitor.lua 0 57 0.00% machines/register/alloy_furnace.lua 0 30 0.00% machines/register/alloy_recipes.lua 0 27 0.00% machines/register/battery_box.lua 0 238 0.00% machines/register/cables.lua 168 49 77.42% machines/register/centrifuge.lua 0 6 0.00% machines/register/centrifuge_recipes.lua 0 25 0.00% machines/register/common.lua 0 114 0.00% machines/register/compressor.lua 0 6 0.00% machines/register/compressor_recipes.lua 0 33 0.00% machines/register/electric_furnace.lua 0 6 0.00% machines/register/extractor.lua 0 6 0.00% machines/register/extractor_recipes.lua 0 71 0.00% machines/register/freezer.lua 0 6 0.00% machines/register/freezer_recipes.lua 0 12 0.00% machines/register/generator.lua 91 114 44.39% machines/register/grinder.lua 0 6 0.00% machines/register/grinder_recipes.lua 0 100 0.00% machines/register/grindings.lua 0 39 0.00% machines/register/init.lua 0 22 0.00% machines/register/machine_base.lua 0 166 0.00% machines/register/recipes.lua 0 78 0.00% machines/register/solar_array.lua 0 30 0.00% machines/supply_converter.lua 75 66 53.19% machines/switching_station.lua 0 79 0.00% machines/switching_station_globalstep.lua 0 58 0.00% max_lag.lua 0 12 0.00% radiation.lua 0 138 0.00% register.lua 20 20 50.00% tools/cans.lua 0 71 0.00% tools/chainsaw.lua 0 115 0.00% tools/flashlight.lua 0 68 0.00% tools/init.lua 0 14 0.00% tools/mining_drill.lua 0 268 0.00% tools/mining_lasers.lua 0 65 0.00% tools/multimeter.lua 0 208 0.00% tools/prospector.lua 0 101 0.00% tools/sonic_screwdriver.lua 0 51 0.00% tools/tree_tap.lua 0 38 0.00% tools/vacuum.lua 0 32 0.00% util/throttle.lua 0 11 0.00% ``` ### Raw test runner output for geeks: CNC: ``` ●●●●●●W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results ●W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results ●●●●●●●W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results ●W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results ●W: InvRef:get_list returning list src as reference, this can lead to unxpected results ●●●●W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list src as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results W: InvRef:get_list returning list dst as reference, this can lead to unxpected results ●● 22 successes / 0 failures / 0 errors / 0 pending : 0.200565 seconds ``` Technic: ``` E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: E: INVALID MINETEST CONFIGURATION FILE PATH FOUND: E: spec/fixtures/minetest.cfg E: E: PLEASE CHANGE NAME OF FILE TO BE minetest.conf: E: spec/fixtures/minetest.conf E: E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! ●●●●●●●●●●●●●●●●●●●●●●●●●●●●●●E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: E: INVALID MINETEST CONFIGURATION FILE PATH FOUND: E: spec/fixtures/minetest.cfg E: E: PLEASE CHANGE NAME OF FILE TO BE minetest.conf: E: spec/fixtures/minetest.conf E: E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! ●●●●●●●●●●●●●●●●●E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: E: INVALID MINETEST CONFIGURATION FILE PATH FOUND: E: spec/fixtures/minetest.cfg E: E: PLEASE CHANGE NAME OF FILE TO BE minetest.conf: E: spec/fixtures/minetest.conf E: E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! E: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! ●●●●●◌●●●●● 57 successes / 0 failures / 0 errors / 1 pending : 0.174429 seconds Pending → spec/supply_converter_spec.lua @ 99 Supply converter building overloads network spec/supply_converter_spec.lua:99: overload does not work with supply converter ```

mt-mods / technic

Fix and improve max_lag #193