flux reports: when re-generating an entity v ... #2416

Open
opened 2022-08-07 04:24:30 +00:00 by yourland-report · 17 comments

flux reports a bug:

when re-generating an entity via an LBM, possibly we do that in an minetest.after callback, w/ a random step of 0-5 server ticks, or such

Player position:

{
	y = 14.5,
	z = 1155.9250488281,
	x = 2083.5869140625
}

Player look:

{
	y = 0.15160585939884,
	z = -0.96786898374557,
	x = -0.20061227679253
}

Player information:

{
	patch = 0,
	formspec_version = 6,
	lang_code = "",
	major = 5,
	minor = 6,
	version_string = "5.6.0",
	state = "Active",
	min_rtt = 0.16400000452995,
	ip_version = 6,
	protocol_version = 40,
	max_rtt = 5.7540001869202,
	avg_rtt = 0.17499999701977,
	min_jitter = 0,
	max_jitter = 5.5830001831055,
	avg_jitter = 0,
	connection_uptime = 44010,
	serialization_version = 29
}

Player meta:

{
	fields = {
		["petz:werewolf"] = "1",
		["stamina:level"] = "16",
		["signslib:pos"] = "(1273,69,540)",
		["petz:old_override_table"] = "return {[\"new_move\"] = true, [\"sneak\"] = true, [\"sneak_glitch\"] = false, [\"jump\"] = 1.5, [\"speed\"] = 2, [\"gravity\"] = 1}",
		yl_church = "return {[\"last_death_portal\"] = 1653796347, [\"last_death\"] = {[\"y\"] = 26, [\"z\"] = 2823, [\"x\"] = 7034}, [\"last_heal\"] = 1615504208}",
		punch_count = "89340",
		jointime = "1615351173",
		inflicted_damage = "1482270",
		arenalib_infobox_arenaID = "0",
		partychat = "party",
		["petz:werewolf_clan_idx"] = "1",
		["stamina:exhaustion"] = "86.5",
		yl_commons_player_created = "1615351173",
		["unified_inventory:bags"] = "return {\"water_life:croc_bag\", \"water_life:croc_bag\", \"water_life:croc_bag\", \"water_life:croc_bag\"}",
		["petz:werewolf_vignette_id"] = "20",
		xp = "1280822",
		yl_commons_thankyou = "136",
		["petz:lycanthropy"] = "1",
		bitten = "0",
		played_time = "21271695",
		digged_nodes = "1087226",
		placed_nodes = "353207",
		died = "67",
		crafted = "39489",
		yl_commons_player_joined = "1659802287",
		["stamina:poisoned"] = "no",
		hud_state = "on",
		repellant = "0",
		["3d_armor_inventory"] = "return {\"3d_armor:helmet_nether 1 2280\", \"3d_armor:chestplate_nether 1 4560\", \"3d_armor:leggings_nether 1 4560\", \"nether_mobs:dragon_shield 1 2280\", \"nether_mobs:dragon_boots 1 2280\", \"\"}"
	}
}

Log identifier


[MOD] yl_report log identifier = Cmcp1G11JYiRYFZ3UqQqsQq1QhGrnscl

Profiler save:

profile-20220807T042429.json_prettyEE

Status:

# Server: version: 5.5.1-yl | game: Minetest Game | uptime: 7d 1h 2min 29s | max lag: 1.87s | clients: bluattire, Woodman1234, Aayush0350C, dragon014, Azelf, evil123, jerry, acen2006, Ivanhoe, daydream, Lupercus, Onlan, hbreturns, the_chosen_one, Bailiff, AliasAlreadyTaken, digdeeper, digdeep, Winter_Tundra, Yuki567, Service, flux

Teleport command:

/teleport xyz 2084 15 1156

Compass command:

/give_compass Construction Cmcp1G11JYiRYFZ3UqQqsQq1QhGrnscl D2691E 2084 15 1156
flux reports a bug: > when re-generating an entity via an LBM, possibly we do that in an `minetest.after` callback, w/ a random step of 0-5 server ticks, or such Player position: ``` { y = 14.5, z = 1155.9250488281, x = 2083.5869140625 } ``` Player look: ``` { y = 0.15160585939884, z = -0.96786898374557, x = -0.20061227679253 } ``` Player information: ``` { patch = 0, formspec_version = 6, lang_code = "", major = 5, minor = 6, version_string = "5.6.0", state = "Active", min_rtt = 0.16400000452995, ip_version = 6, protocol_version = 40, max_rtt = 5.7540001869202, avg_rtt = 0.17499999701977, min_jitter = 0, max_jitter = 5.5830001831055, avg_jitter = 0, connection_uptime = 44010, serialization_version = 29 } ``` Player meta: ``` { fields = { ["petz:werewolf"] = "1", ["stamina:level"] = "16", ["signslib:pos"] = "(1273,69,540)", ["petz:old_override_table"] = "return {[\"new_move\"] = true, [\"sneak\"] = true, [\"sneak_glitch\"] = false, [\"jump\"] = 1.5, [\"speed\"] = 2, [\"gravity\"] = 1}", yl_church = "return {[\"last_death_portal\"] = 1653796347, [\"last_death\"] = {[\"y\"] = 26, [\"z\"] = 2823, [\"x\"] = 7034}, [\"last_heal\"] = 1615504208}", punch_count = "89340", jointime = "1615351173", inflicted_damage = "1482270", arenalib_infobox_arenaID = "0", partychat = "party", ["petz:werewolf_clan_idx"] = "1", ["stamina:exhaustion"] = "86.5", yl_commons_player_created = "1615351173", ["unified_inventory:bags"] = "return {\"water_life:croc_bag\", \"water_life:croc_bag\", \"water_life:croc_bag\", \"water_life:croc_bag\"}", ["petz:werewolf_vignette_id"] = "20", xp = "1280822", yl_commons_thankyou = "136", ["petz:lycanthropy"] = "1", bitten = "0", played_time = "21271695", digged_nodes = "1087226", placed_nodes = "353207", died = "67", crafted = "39489", yl_commons_player_joined = "1659802287", ["stamina:poisoned"] = "no", hud_state = "on", repellant = "0", ["3d_armor_inventory"] = "return {\"3d_armor:helmet_nether 1 2280\", \"3d_armor:chestplate_nether 1 4560\", \"3d_armor:leggings_nether 1 4560\", \"nether_mobs:dragon_shield 1 2280\", \"nether_mobs:dragon_boots 1 2280\", \"\"}" } } ``` Log identifier ``` [MOD] yl_report log identifier = Cmcp1G11JYiRYFZ3UqQqsQq1QhGrnscl ``` Profiler save: ``` profile-20220807T042429.json_prettyEE ``` Status: ``` # Server: version: 5.5.1-yl | game: Minetest Game | uptime: 7d 1h 2min 29s | max lag: 1.87s | clients: bluattire, Woodman1234, Aayush0350C, dragon014, Azelf, evil123, jerry, acen2006, Ivanhoe, daydream, Lupercus, Onlan, hbreturns, the_chosen_one, Bailiff, AliasAlreadyTaken, digdeeper, digdeep, Winter_Tundra, Yuki567, Service, flux ``` Teleport command: ``` /teleport xyz 2084 15 1156 ``` Compass command: ``` /give_compass Construction Cmcp1G11JYiRYFZ3UqQqsQq1QhGrnscl D2691E 2084 15 1156 ```
AliasAlreadyTaken was assigned by yourland-report 2022-08-07 04:24:30 +00:00
AliasAlreadyTaken added the
1. kind/enhancement
label 2022-08-07 06:05:01 +00:00
flux self-assigned this 2022-08-07 16:58:58 +00:00
flux added this to the flux's TODO list project 2022-08-07 16:59:01 +00:00
flux added the
3. source/lag
2. prio/interesting
labels 2022-08-07 16:59:20 +00:00
AliasAlreadyTaken was unassigned by flux 2022-08-07 17:01:34 +00:00
Member

perhaps i could create a generalized "add_entity_queue", which adds at most a fixed # of these "create on load" entities every server tick.

mods which should use this:

  • anvil (cottages)
  • display_modpack
  • itemframes
  • itemshelf
  • signs_lib
  • smartshop
perhaps i could create a generalized "add_entity_queue", which adds at most a fixed # of these "create on load" entities every server tick. mods which should use this: * [ ] anvil (cottages) * [ ] display_modpack * [ ] itemframes * [ ] itemshelf * [ ] signs_lib * [ ] smartshop
Member

from alias:

what min us max us avg us min % max % avg %
smartshop: 0 104671 556 0.0 53.4 0.5
- on_player_receive_fields[1] 1 4 2 0.0 0.0 0.0
- LBM 'smartshop:load_shop' 14064 88890 51477 39.4 45.3 42.4
- LBM 'smartshop:repay_lost_stuff' 1942 15781 8861 5.4 8.0 6.7
from alias: | what | min us | max us | avg us | min % | max % | avg % | | -------- | -------- | -------- |-------- | -------- | -------- | -------- | |smartshop: | 0 | 104671 | 556 | 0.0 | 53.4 | 0.5 | - on_player_receive_fields[1] | 1 | 4 | 2 | 0.0 | 0.0 | 0.0 | - LBM 'smartshop:load_shop' | 14064 | 88890 | 51477 | 39.4 | 45.3 | 42.4 | - LBM 'smartshop:repay_lost_stuff' | 1942 | 15781 | 8861 | 5.4 | 8.0 | 6.7
Member

ugh. this became a rabbit hole.

  1. the LBMs are still quite expensive even if the stuff is queued to execute across multiple server steps
  2. i (re?)discovered that LBMs run when a block becomes active (active_block_range=1), not when it's loaded (max_block_send_distance=10), nor when the entities in the block would normally be loaded (active_object_send_range_blocks=3). this meant that a lot of times, i was throwing away and re-creating entities when i didn't need to be. that wasn't hard to fix - the LBM needed to check to see if the existing entities matched what was expected to be there, and only re-create them then. however, doing those checks is almost as expensive as just re-creating them... but it looks a bit better.
  3. there's no way to spread out sending already loaded entities to clients, so the client still gets a huge lag spike when they wander into an area w/ a huge number of loaded entities.

this lead me into trying to identify ways to only keep the entities loaded if a player is close enough to see it well. this may have to be an ABM, which ... may help the clients, but will certainly create a lot of processing load.

ugh. this became a rabbit hole. 1. the LBMs are still quite expensive even if the stuff is queued to execute across multiple server steps 2. i (re?)discovered that LBMs run when a block becomes *active* (`active_block_range=1`), not when it's *loaded* (`max_block_send_distance=10`), nor when the entities in the block would normally be loaded (`active_object_send_range_blocks=3`). this meant that a lot of times, i was throwing away and re-creating entities when i didn't need to be. that wasn't hard to fix - the LBM needed to check to see if the existing entities matched what was expected to be there, and only re-create them then. however, doing those checks is almost as expensive as just re-creating them... but it looks a bit better. 3. there's no way to spread out sending *already loaded* entities to clients, so the client still gets a huge lag spike when they wander into an area w/ a huge number of loaded entities. this lead me into trying to identify ways to only keep the entities loaded if a player is close enough to see it well. this may have to be an ABM, which ... may help the clients, but will certainly create a lot of processing load.
Member

i wonder if i should just go back to having statically-saved entities and double-checking the state of things whenever one loads (whether via add_entity or statically). given that there's only 1 thread, there's ways to avoid the "race condition".

i wonder if i should just go back to having statically-saved entities and double-checking the state of things whenever one loads (whether via `add_entity` or statically). given that there's only 1 thread, there's ways to avoid the "race condition".
Member

if we remain non-static, i wonder if we could benefit of from manually restricting outselves to the declared max_objects_per_block=512 value. like, if there's that many entities nearby, refuse to create more. then again, a single mapblock rarely has that many entities in it, usually at most a couple hundred.

options:

  • lower max_objects_per_block and implement the idea above. downside to that would be that if e.g. several hundred pets unloaded, not all of them might survive.
  • allow specifying a limit specifically for smartshop nodes (and possibly for other "node-bound" entities)
if we remain non-static, i wonder if we could benefit of from manually restricting outselves to the declared `max_objects_per_block=512` value. like, if there's that many entities nearby, refuse to create more. then again, a single mapblock rarely has *that* many entities in it, usually at most a couple hundred. options: * lower `max_objects_per_block` and implement the idea above. downside to that would be that if e.g. several hundred pets unloaded, not all of them might survive. * allow specifying a limit specifically for smartshop nodes (and possibly for other "node-bound" entities)
Member

perhaps i should just create a "node_entities" mod to make managing them unified and sensical

perhaps i should just create a "node_entities" mod to make managing them unified and sensical
flux added the
4. step/at work
label 2022-08-11 00:06:05 +00:00
Member

testing...

testing...

testing... ![testing...](https://gitea.your-land.de/attachments/e1d02c56-761e-417a-ac49-4de43ca179e9)
Member

want to finish the cottages update before i work on this more. it's turned into a huge thing.

want to finish the cottages update before i work on this more. it's turned into a huge thing.
Member

this turned into 3 mods:

see #2623 for more info.

this issue should stay open, as a tracker of progress in making use of node_entity_queue for the various mods.

this turned into 3 mods: * https://github.com/fluxionary/minetest-futil * https://github.com/fluxionary/minetest-action_queues * https://github.com/fluxionary/minetest-node_entity_queue see #2623 for more info. this issue should stay open, as a tracker of progress in making use of node_entity_queue for the various mods.

Could the engine be optimized in this place? If you need to jump through several API hoops to achieve a small loadbalancing effect, maybe engine upstream needs to improve at this point?

Could the engine be optimized in this place? If you need to jump through several API hoops to achieve a small loadbalancing effect, maybe engine upstream needs to improve at this point?
Member

Could the engine be optimized in this place? If you need to jump through several API hoops to achieve a small loadbalancing effect, maybe engine upstream needs to improve at this point?

yes, i believe there's several proposals to help out w/ entity and LBM stuff.

  • node bound entities - which hasn't been commented on since 2019, but shows that people have discussed various optimizations for such entities
  • add bulk ABMs; there's also discussion there of bulk LBMs
> Could the engine be optimized in this place? If you need to jump through several API hoops to achieve a small loadbalancing effect, maybe engine upstream needs to improve at this point? yes, i believe there's several proposals to help out w/ entity and LBM stuff. * [node bound entities](https://github.com/minetest/minetest/issues/6963) - which hasn't been commented on since 2019, but shows that people have discussed various optimizations for such entities * [add bulk ABMs](https://github.com/minetest/minetest/pull/12128); there's also discussion there of bulk LBMs
Member

i do think i can create a mod which defines a canonical interface for creating such entities, but it's a non-trivial amount of work. it might be a good API mod to incorporate into a game (your-land/administration#174), but it'll be an uphill battle to make other mods depend on it.

i do think i can create a mod which defines a canonical interface for creating such entities, but it's a non-trivial amount of work. it might be a good API mod to incorporate into a game (https://gitea.your-land.de/your-land/administration/issues/174), but it'll be an uphill battle to make other mods depend on it.
Member

upstream engine issue about this, which i should get around to reading sometime https://github.com/minetest/minetest/issues/6963

upstream engine issue about this, which i should get around to reading sometime https://github.com/minetest/minetest/issues/6963
flux removed the
4. step/at work
label 2022-11-03 12:52:19 +00:00

If it's in the base game, all mods using this game as a basis will depend on it.

Making all modmokers reotroactively add support will be next to impossible.

If it's in the base game, all mods using this game as a basis will depend on it. Making all modmokers reotroactively add support will be next to impossible.
flux added the
4. step/ready to QA test
label 2023-05-02 21:55:37 +00:00

QA

How would I test this?

QA How would I test this?
AliasAlreadyTaken added the
4. step/question
label 2023-12-06 19:07:47 +00:00
Member

How would I test this?

note: this is only "fixed" for smartshops - other node entities, e.g. signs and item frames, don't make use of the queue.

first, you need to modify the instrumentation code so that you can see the source of various callbacks in order to differentiate them:

diff --git a/builtin/profiler/instrumentation.lua b/builtin/profiler/instrumentation.lua
index 5c1cb191b..42b1c0c5a 100644
--- a/builtin/profiler/instrumentation.lua
+++ b/builtin/profiler/instrumentation.lua
@@ -61,11 +61,9 @@ local function generate_name(def)
        elseif label == false then
                return format("%s", class or func_name):trim()
        end
-
-       local index_id = def.mod .. (class or func_name)
-       local index = counts[index_id] or 1
-       counts[index_id] = index + 1
-       return format("%s[%d] %s", class or func_name, index, class and func_name or ""):trim()
+       local info = debug.getinfo(def.func)
+       local worldpath = minetest.get_worldpath()
+       return format("%s %s#%s", class or func_name, info.source:gsub(worldpath, ""), info.linedefined)
 end
 
 ---
diff --git a/builtin/profiler/reporter.lua b/builtin/profiler/reporter.lua
index 5928a3718..2e24a1fe0 100644
--- a/builtin/profiler/reporter.lua
+++ b/builtin/profiler/reporter.lua
@@ -77,7 +77,7 @@ local Formatter = {
        end
 }
 
-local widths = { 55, 9, 9, 9, 5, 5, 5 }
+local widths = { 80, 9, 9, 9, 5, 5, 5 }
 local txt_row_format = sprintf(" %%-%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds", unpack(widths))
 
 local HR = {}

then, you need to create a giant wall of smartshops w/ random items in them. mark two positions with worldedit, and run the following snippet (change "flux" to your name):

local player_name = "flux"
local items = {}
for item in pairs(minetest.registered_items) do
 table.insert(items, item)
end
local non_nodes = {}
for item in pairs(minetest.registered_tools) do
 table.insert(non_nodes, item)
end
for item in pairs(minetest.registered_craftitems) do
 table.insert(non_nodes, item)
end

local f = minetest.get_player_by_name(player_name)

local p1 = worldedit.pos1[player_name]
local p2 = worldedit.pos2[player_name]
local v = VoxelArea:new({MinEdge = p1, MaxEdge = p2})

for i in v:iterp(worldedit.pos1.flux, worldedit.pos2.flux) do
 local p = v:position(i)
 local n = minetest.get_node(p)
 if n.name ~= "smartshop.shop" then
  minetest.item_place_node(ItemStack("smartshop:shop"), f, {type = "node", under=p, above=p}, 0)
 end
 local shop = smartshop.api.get_object(p)
 local inv = shop.inv
 if p.y % 2 == 0 then
  for i = 1, 4 do
   inv:set_stack(("pay%i"):format(i), 1,  non_nodes[math.random(1, #non_nodes)])
   inv:set_stack(("give%i"):format(i), 1,  non_nodes[math.random(1, #non_nodes)])
  end
 else
  for i = 1, 4 do
   inv:set_stack(("pay%i"):format(i), 1,  items[math.random(1, #items)])
   inv:set_stack(("give%i"):format(i), 1,  items[math.random(1, #items)])
  end
 end
 shop:update_entities()
end

image

now, you need to turn off node_entity_queue and restart the server. when you log back in next to the wall of smartshops, you can check the performance of the smartshop callbacks:

image

now, re-enable node_entity_queue and restart the server again. check the performance again:

image

the performance isn't as incredible as i wish it were, but it's reducing the size of the biggest lag spike to 1/3 the previous duration.

> How would I test this? note: this is only "fixed" for smartshops - other node entities, e.g. signs and item frames, don't make use of the queue. first, you need to modify the instrumentation code so that you can see the *source* of various callbacks in order to differentiate them: ```diff diff --git a/builtin/profiler/instrumentation.lua b/builtin/profiler/instrumentation.lua index 5c1cb191b..42b1c0c5a 100644 --- a/builtin/profiler/instrumentation.lua +++ b/builtin/profiler/instrumentation.lua @@ -61,11 +61,9 @@ local function generate_name(def) elseif label == false then return format("%s", class or func_name):trim() end - - local index_id = def.mod .. (class or func_name) - local index = counts[index_id] or 1 - counts[index_id] = index + 1 - return format("%s[%d] %s", class or func_name, index, class and func_name or ""):trim() + local info = debug.getinfo(def.func) + local worldpath = minetest.get_worldpath() + return format("%s %s#%s", class or func_name, info.source:gsub(worldpath, ""), info.linedefined) end --- diff --git a/builtin/profiler/reporter.lua b/builtin/profiler/reporter.lua index 5928a3718..2e24a1fe0 100644 --- a/builtin/profiler/reporter.lua +++ b/builtin/profiler/reporter.lua @@ -77,7 +77,7 @@ local Formatter = { end } -local widths = { 55, 9, 9, 9, 5, 5, 5 } +local widths = { 80, 9, 9, 9, 5, 5, 5 } local txt_row_format = sprintf(" %%-%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds", unpack(widths)) local HR = {} ``` then, you need to create a giant wall of smartshops w/ random items in them. mark two positions with worldedit, and run the following snippet (change "flux" to your name): ```lua local player_name = "flux" local items = {} for item in pairs(minetest.registered_items) do table.insert(items, item) end local non_nodes = {} for item in pairs(minetest.registered_tools) do table.insert(non_nodes, item) end for item in pairs(minetest.registered_craftitems) do table.insert(non_nodes, item) end local f = minetest.get_player_by_name(player_name) local p1 = worldedit.pos1[player_name] local p2 = worldedit.pos2[player_name] local v = VoxelArea:new({MinEdge = p1, MaxEdge = p2}) for i in v:iterp(worldedit.pos1.flux, worldedit.pos2.flux) do local p = v:position(i) local n = minetest.get_node(p) if n.name ~= "smartshop.shop" then minetest.item_place_node(ItemStack("smartshop:shop"), f, {type = "node", under=p, above=p}, 0) end local shop = smartshop.api.get_object(p) local inv = shop.inv if p.y % 2 == 0 then for i = 1, 4 do inv:set_stack(("pay%i"):format(i), 1, non_nodes[math.random(1, #non_nodes)]) inv:set_stack(("give%i"):format(i), 1, non_nodes[math.random(1, #non_nodes)]) end else for i = 1, 4 do inv:set_stack(("pay%i"):format(i), 1, items[math.random(1, #items)]) inv:set_stack(("give%i"):format(i), 1, items[math.random(1, #items)]) end end shop:update_entities() end ``` ![image](/attachments/a19ba004-4638-49ee-9130-82abde6e6958) now, you need to turn off node_entity_queue and restart the server. when you log back in next to the wall of smartshops, you can check the performance of the smartshop callbacks: ![image](/attachments/7d6a29ef-e427-460f-8007-ffd8100c210a) now, re-enable node_entity_queue and restart the server again. check the performance again: ![image](/attachments/b5844f53-c73a-46ff-ba4e-2edfa15fde68) the performance isn't as incredible as i wish it were, but it's reducing the size of the biggest lag spike to 1/3 the previous duration.
640 KiB
976 KiB
1.3 MiB
Member

the node_entity_queue is now live, though only smartshops make use of it. there's still far more sign and itemframe entities around in general.

the node_entity_queue is now live, though only smartshops make use of it. there's still far more sign and itemframe entities around in general.
Sign in to join this conversation.
No Milestone
No Assignees
3 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: your-land/bugtracker#2416
No description provided.