Azelf reports: Crafting large quantities of i ... #3838

New Issue

yourland-report · 2023-02-17T12:35:00Z

yourland-report commented

2023-02-17 12:35:00 +00:00

Azelf reports a bug:

Crafting large quantities of items which have large recepies (recepies that take up 8/9 slots on the recipe) causes massive lag spikes

Player position:

{
	x = 146.50698852539,
	y = -4158.4990234375,
	z = -3062.080078125
}

Player look:

{
	x = -0.73598808050156,
	y = -0.29687491059303,
	z = -0.6084298491478
}

Player information:

{
	min_jitter = 0,
	max_jitter = 7.6770000457764,
	avg_jitter = 0,
	connection_uptime = 5583,
	serialization_version = 29,
	max_rtt = 7.8499999046326,
	minor = 6,
	major = 5,
	version_string = "5.6.1",
	state = "Active",
	formspec_version = 6,
	protocol_version = 41,
	patch = 1,
	lang_code = "",
	ip_version = 6,
	min_rtt = 0.17000000178814,
	avg_rtt = 0.17200000584126
}

Player meta:

{
	fields = {
		arenalib_infobox_arenaID = "0",
		digged_nodes = "213952",
		["stamina:level"] = "6",
		died = "75",
		["stamina:poisoned"] = "no",
		crafted = "109212",
		["stamina:exhaustion"] = "129.5",
		jointime = "1659363683",
		punch_count = "108365",
		xp = "314464",
		yl_commons_player_created = "1659363683",
		yl_commons_player_joined = "1676631744",
		["3d_armor_inventory"] = "return {\"shields:shield_rainbow 1 13504\", \"3d_armor:enchanted_chestplate_mithril_strong 1 23604\", \"3d_armor:enchanted_helmet_mithril_strong 1 23604\", \"3d_armor:enchanted_leggings_mithril_strong 1 23604\", \"\", \"3d_armor:boots_crystal 1 9500\"}",
		partychat = "party",
		hud_state = "on",
		yl_church = "return {[\"last_death_portal\"] = 1676630781, [\"last_death\"] = {[\"x\"] = 2240, [\"y\"] = -23003, [\"z\"] = 1607}, [\"last_heal\"] = 1673918726}",
		["signslib:pos"] = "(149,-4161,-3061)",
		["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}",
		placed_nodes = "63119",
		inflicted_damage = "2324268",
		["ocean_build.ocean_built"] = "11",
		repellant = "0",
		yl_commons_thankyou = "20",
		bitten = "0",
		["ocean_build.last_warning"] = "1.67602e+09",
		played_time = "1464778"
	}
}

Log identifier


[MOD] yl_report log identifier = mquOfZaww8aQQJvXD8tHgQukqTl2g90Z

Profiler save:

profile-20230217T123500.json_prettyEE

Status:

# Server: version: 5.6.1-yl | game: Minetest Game | uptime: 1d 9h 45min 3s | max lag: 38.7s | clients (21/52): 9T9, AliasAlreadyTaken, Aliza, Antimatter_76, Aries, Azelf, Bailiff, BibaBoba, bizon, daydream, Ernesto, flux, JeCel, Murmel, Nibsokube, Oakenshield, Pecka, Qichta29, Service, Spongeboi, Sysmatic

Teleport command:

/teleport xyz 147 -4158 -3062

Compass command:

/give_compass Construction mquOfZaww8aQQJvXD8tHgQukqTl2g90Z D2691E 147 -4158 -3062

Azelf reports a bug: > Crafting large quantities of items which have large recepies (recepies that take up 8/9 slots on the recipe) causes massive lag spikes Player position: ``` { x = 146.50698852539, y = -4158.4990234375, z = -3062.080078125 } ``` Player look: ``` { x = -0.73598808050156, y = -0.29687491059303, z = -0.6084298491478 } ``` Player information: ``` { min_jitter = 0, max_jitter = 7.6770000457764, avg_jitter = 0, connection_uptime = 5583, serialization_version = 29, max_rtt = 7.8499999046326, minor = 6, major = 5, version_string = "5.6.1", state = "Active", formspec_version = 6, protocol_version = 41, patch = 1, lang_code = "", ip_version = 6, min_rtt = 0.17000000178814, avg_rtt = 0.17200000584126 } ``` Player meta: ``` { fields = { arenalib_infobox_arenaID = "0", digged_nodes = "213952", ["stamina:level"] = "6", died = "75", ["stamina:poisoned"] = "no", crafted = "109212", ["stamina:exhaustion"] = "129.5", jointime = "1659363683", punch_count = "108365", xp = "314464", yl_commons_player_created = "1659363683", yl_commons_player_joined = "1676631744", ["3d_armor_inventory"] = "return {\"shields:shield_rainbow 1 13504\", \"3d_armor:enchanted_chestplate_mithril_strong 1 23604\", \"3d_armor:enchanted_helmet_mithril_strong 1 23604\", \"3d_armor:enchanted_leggings_mithril_strong 1 23604\", \"\", \"3d_armor:boots_crystal 1 9500\"}", partychat = "party", hud_state = "on", yl_church = "return {[\"last_death_portal\"] = 1676630781, [\"last_death\"] = {[\"x\"] = 2240, [\"y\"] = -23003, [\"z\"] = 1607}, [\"last_heal\"] = 1673918726}", ["signslib:pos"] = "(149,-4161,-3061)", ["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}", placed_nodes = "63119", inflicted_damage = "2324268", ["ocean_build.ocean_built"] = "11", repellant = "0", yl_commons_thankyou = "20", bitten = "0", ["ocean_build.last_warning"] = "1.67602e+09", played_time = "1464778" } } ``` Log identifier ``` [MOD] yl_report log identifier = mquOfZaww8aQQJvXD8tHgQukqTl2g90Z ``` Profiler save: ``` profile-20230217T123500.json_prettyEE ``` Status: ``` # Server: version: 5.6.1-yl | game: Minetest Game | uptime: 1d 9h 45min 3s | max lag: 38.7s | clients (21/52): 9T9, AliasAlreadyTaken, Aliza, Antimatter_76, Aries, Azelf, Bailiff, BibaBoba, bizon, daydream, Ernesto, flux, JeCel, Murmel, Nibsokube, Oakenshield, Pecka, Qichta29, Service, Spongeboi, Sysmatic ``` Teleport command: ``` /teleport xyz 147 -4158 -3062 ``` Compass command: ``` /give_compass Construction mquOfZaww8aQQJvXD8tHgQukqTl2g90Z D2691E 147 -4158 -3062 ```

AliasAlreadyTaken was assigned by yourland-report

2023-02-17 12:35:00 +00:00

flux added the

1. kind/bug

3. source/lag

labels 2023-02-17 16:10:30 +00:00

flux commented

2023-02-17 16:12:00 +00:00

i can't replicate this

flux added the

4. step/needs confirmation

label 2023-02-17 16:12:20 +00:00

flux added the

4. step/question

label 2023-02-17 16:15:13 +00:00

flux commented

2023-02-17 16:15:25 +00:00

mail to Azelf:

greetings,

what exactly are you trying to craft? are you using the "craft all" button, or manually crafting the items? can you describe the lag spike - does it affect the entire server, or just your client? 

i've personally never noticed lag that was *caused* by crafting, though the "all" button is certainly subject to the effects of lag caused by other things. 

thanks,

~flux

mail to Azelf: ``` greetings, what exactly are you trying to craft? are you using the "craft all" button, or manually crafting the items? can you describe the lag spike - does it affect the entire server, or just your client? i've personally never noticed lag that was *caused* by crafting, though the "all" button is certainly subject to the effects of lag caused by other things. thanks, ~flux ```

flux added

2. prio/elevated

and removed

4. step/question

4. step/needs confirmation

labels 2023-02-18 02:50:33 +00:00

flux commented

2023-02-18 02:52:07 +00:00

after talking w/ Azelf, i have a reliable replication:

fill up crafting grid w/ 8 stacks of sunflower seeds, 1 stack of empty bottles, to craft 1 stack of sunflower oil
click "craft all"
28.5 second lag spike on the main server, consistently.

after talking w/ Azelf, i have a reliable replication: * fill up crafting grid w/ 8 stacks of sunflower seeds, 1 stack of empty bottles, to craft 1 stack of sunflower oil * click "craft all" * 28.5 second lag spike on the main server, consistently.

👍 1

flux commented

2023-02-18 03:24:52 +00:00

see https://github.com/minetest-mods/crafting_bench/pull/9#discussion_r1090072884 for some discussion about what i think the problem is. caching craft results for unified_inventory_plus might make this go away, but that needs tested.

flux commented

2023-02-19 00:56:34 +00:00

result of today's testing:

a single call to minetest.get_craft_result can take up to .4 seconds locally
- the main culprit, is it seems the more group:... items are in the recipe, the longer it takes, but this should be more thoroughly tested.
trying to dump the state of minetest's internal craft system is terrible. so many poor design decisions (the "width" of a cooking recipe is the cooktime? seriously? and there's no way to extract the replacements? and fuel recipes are stored internally as cooking recipes w/ no output?)
existing attempts to separate the items and craft recipes from the rest of the server code have not yet resulted in the same terrible performance, but this might be because i haven't yet successfully dumped that data fully (see above). probably i'm just going to have to capture and log every single call to register_craft and clear_craft while the server starts up, and replay that.
possibly other things i haven't investigated are also contributing to the performance, e.g. aliases
luajit may support more than 1gig of memory now, but it's still limited to 65536 constants in a file? blech. fortunately the "split" command works well for this.

result of today's testing: * a single call to `minetest.get_craft_result` can take up to .4 seconds locally * the main culprit, is it seems the more `group:...` items are in the recipe, the longer it takes, but this should be more thoroughly tested. * trying to dump the state of minetest's internal craft system is terrible. so many poor design decisions (the "width" of a cooking recipe is the cooktime? seriously? and there's no way to extract the replacements? and fuel recipes are stored internally as cooking recipes w/ no output?) * existing attempts to separate the items and craft recipes from the rest of the server code have not yet resulted in the same terrible performance, but this might be because i haven't yet successfully dumped that data fully (see above). probably i'm just going to have to capture and log every single call to `register_craft` and `clear_craft` while the server starts up, and replay that. * possibly other things i haven't investigated are also contributing to the performance, e.g. aliases * luajit may support more than 1gig of memory now, but it's still limited to 65536 constants in a file? blech. fortunately the "split" command works well for this.

flux referenced this issue

2023-02-19 16:06:15 +00:00

Azelf reports: Crafting large stack of bloomi ... #3850

flux added the

3. source/engine

label 2023-02-19 17:05:23 +00:00

flux commented

2023-02-19 17:05:37 +00:00

upstream issue: https://github.com/minetest/minetest/issues/13231

flux commented

2023-02-19 20:07:19 +00:00

upstream was closed in favor of an older issue, maybe related, maybe not: https://github.com/minetest/minetest/issues/11224

which now has an upstream PR: https://github.com/minetest/minetest/pull/13234

upstream was closed in favor of an older issue, maybe related, maybe not: https://github.com/minetest/minetest/issues/11224 which now has an upstream PR: https://github.com/minetest/minetest/pull/13234

flux added the

4. step/blocked

label 2023-02-19 22:53:03 +00:00

AliasAlreadyTaken commented

2023-02-22 05:53:49 +00:00

That's something I should compile into the testserver, right?

flux commented

2023-02-22 06:26:20 +00:00

That's something I should compile into the testserver, right?

unless you think this is really urgent, let's wait until upstream gets merged. this is the sort of thing that should be dealt w/ in a few weeks, the fix is solid, but non-trivial.

> That's something I should compile into the testserver, right? unless you think this is really urgent, let's wait until upstream gets merged. this is the sort of thing that should be dealt w/ in a few weeks, the fix is solid, but non-trivial.

👍 1

flux commented

2023-03-09 01:23:49 +00:00

this didn't make it into 5.7.0, which i assumed it would. this is a source of huge lag spikes, so probably we should patch this into our server. we need a process for adding cherry-picked commits to the server source code, i think.

this *didn't* make it into 5.7.0, which i assumed it would. this is a source of huge lag spikes, so probably we should patch this into our server. we need a process for adding cherry-picked commits to the server source code, i think.

flux referenced this issue

2023-03-09 15:59:42 +00:00

toomanycharacter2 reports: Crafting a few stacks using "c ... #3962

flux commented

2023-03-16 23:22:22 +00:00

the engine fix actually takes off about 15 seconds from my local server startup time (when unified_inventory initializes).

AzelfYL commented

2023-09-09 01:42:22 +00:00

No longer facing these issues when crafting in bulk for a while now, so mark as closed?

flux commented

2023-10-31 01:18:25 +00:00

No longer facing these issues when crafting in bulk for a while now, so mark as closed?

hm. i feel like we should wait for the 5.8.0 release to close this, so we can use that as a base for future server builds instead of cherry-picked commits?

> No longer facing these issues when crafting in bulk for a while now, so mark as closed? hm. i feel like we should wait for the 5.8.0 release to close this, so we can use that as a base for future server builds instead of cherry-picked commits?

👍 1

rewired_X commented

2024-03-15 16:48:37 +00:00

5.8.0 has been out for a bit, what's the plan?
running craft all w/ the example given doesn't lag the server to high heaven anymore.

5.8.0 has been out for a bit, what's the plan? running craft all w/ the example given doesn't lag the server to high heaven anymore.

flux commented

2024-03-16 04:07:02 +00:00

what's the plan?

hopefully sometime in the next week or so i'll get around to documenting all the issues that got fixed with 1.1.123. i'll close this then.

> what's the plan? hopefully sometime in the next week or so i'll get around to documenting all the issues that got fixed with 1.1.123. i'll close this then.

AliasAlreadyTaken commented

2024-03-16 15:52:41 +00:00

Please hold off on this one until we deliver 5.8.0

Now with 1.1.123 out, I'll focus on testing 5.8.0, on the testserver it's already running for a while. Plus, there may be commits we want to cherrypick from 5.9.0

Please hold off on this one until we deliver 5.8.0 Now with 1.1.123 out, I'll focus on testing 5.8.0, on the testserver it's already running for a while. Plus, there may be commits we want to cherrypick from 5.9.0

👍 1

flux added this to the minetest 5.8.0 milestone 2024-03-31 01:06:22 +00:00

Sign in to join this conversation.