Skip to content

Fix and improve max_lag#193

Merged
OgelGames merged 14 commits intomasterfrom
lag-calc-fix
Jul 11, 2021
Merged

Fix and improve max_lag#193
OgelGames merged 14 commits intomasterfrom
lag-calc-fix

Conversation

@OgelGames
Copy link
Copy Markdown
Contributor

@OgelGames OgelGames commented Jul 8, 2021

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

Fixes #166 and #191

Comment thread technic/lag.lua Outdated
@S-S-X
Copy link
Copy Markdown
Member

S-S-X commented Jul 8, 2021

If going for average then is it possible to use

-- Moving average function generator
local function sma(period)
local values = {}
local index = 1
local sum = 0
return function(n)
-- Add new value and return average
sum = sum - (values[index] or 0) + n
values[index] = n
index = index ~= period and index + 1 or 1
return sum / #values
end
end
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 OgelGames added Bug fix Enhancement New feature or request labels Jul 8, 2021
@OgelGames
Copy link
Copy Markdown
Contributor Author

OgelGames commented Jul 8, 2021

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).

Comment thread technic/lag.lua Outdated
Comment thread technic/lag.lua Outdated
@S-S-X
Copy link
Copy Markdown
Member

S-S-X commented Jul 8, 2021

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
Copy link
Copy Markdown
Member

ok, this is nicer than my ugly hack 👍
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
Copy link
Copy Markdown
Contributor Author

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
Copy link
Copy Markdown
Member

S-S-X commented Jul 8, 2021

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
Copy link
Copy Markdown
Member

S-S-X commented Jul 8, 2021

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:

minetest.chat_send_player(name,
("Cached network data: %d active networks, %d total networks, %d network nodes.\n%s"):format(
activecount, netcount, nodecount, table.concat(network_info, "\n")
))

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
Copy link
Copy Markdown
Contributor Author

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
Copy link
Copy Markdown
Member

S-S-X commented Jul 9, 2021

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
Copy link
Copy Markdown
Contributor Author

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
Copy link
Copy Markdown
Member

S-S-X commented Jul 9, 2021

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
Copy link
Copy Markdown
Contributor Author

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... 👀

Comment thread technic/max_lag.lua Outdated
@S-S-X
Copy link
Copy Markdown
Member

S-S-X commented Jul 11, 2021

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
Copy link
Copy Markdown

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

@OgelGames OgelGames merged commit b37229c into master Jul 11, 2021
@S-S-X S-S-X mentioned this pull request Oct 6, 2021
S-S-X added a commit that referenced this pull request Oct 18, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
S-S-X added a commit that referenced this pull request Oct 18, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
OgelGames added a commit that referenced this pull request Oct 19, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
OgelGames added a commit that referenced this pull request Oct 19, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
OgelGames added a commit that referenced this pull request Oct 19, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
@OgelGames OgelGames deleted the lag-calc-fix branch October 19, 2021 08:43
S-S-X added a commit that referenced this pull request Oct 20, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
S-S-X added a commit that referenced this pull request Oct 20, 2021
* Monitor max lag from mod
* Add new max lag for technic_get_active_networks command

Co-authored-by: SX <50966843+S-S-X@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Bug fix Enhancement New feature or request

Projects

None yet

Development

Successfully merging this pull request may close these issues.

ServerError: AsyncErr: environment_Step: Runtime error from mod 'technic' in callback environment_Step() Fix max_lag stuff

3 participants