Test_User reports: /mail is slow, hangs the serve ... #4531

New Issue

yourland-report · 2023-05-18T19:38:36Z

yourland-report commented

2023-05-18 19:38:36 +00:00

Test_User reports a bug:

/mail is slow, hangs the server ~2.5s to open mine

Player position:

{
	z = 2692.2180175781,
	x = 6450.6967773438,
	y = 4.625
}

Player look:

{
	z = -0.15547348558903,
	x = -0.50194466114044,
	y = -0.85081112384796
}

Player information:

{
	major = 5,
	state = "Active",
	protocol_version = 41,
	version_string = "5.6.0",
	max_rtt = 5.5590000152588,
	ip_version = 6,
	avg_rtt = 0.22200000286102,
	min_jitter = 0,
	max_jitter = 5.3649997711182,
	minor = 6,
	connection_uptime = 3372,
	min_rtt = 0.1169999986887,
	patch = 0,
	serialization_version = 29,
	formspec_version = 6,
	avg_jitter = 0.092000007629395,
	lang_code = ""
}

Player meta:

{
	fields = {
		digged_nodes = "256330",
		placed_nodes = "34452",
		died = "344",
		punch_count = "21697",
		partypvp = "true",
		["stamina:exhaustion"] = "104.5",
		["petz:werewolf_vignette_id"] = "19",
		["petz:old_override_table"] = "return {[\"new_move\"] = true, [\"sneak\"] = true, [\"sneak_glitch\"] = false, [\"jump\"] = 1.5, [\"speed\"] = 2, [\"gravity\"] = 1}",
		["3d_armor_inventory"] = "return {\"3d_armor:helmet_crystal 1 12283\", \"\", \"3d_armor:chestplate_crystal 1 12083\", \"3d_armor:leggings_crystal 1 12033\", \"3d_armor:boots_crystal 1 14475\", \"shields:shield_crystal 1 11940\"}",
		inflicted_damage = "340540",
		crafted = "45805",
		["petz:pre_werewolf_animation"] = "return {[\"animation\"] = \"stand\", [\"textures\"] = {\"player.Test_User.0.png\", \"blank.png\", \"3d_armor_trans.png^3d_armor_helmet_crystal.png^3d_armor_chestplate_crystal.png^3d_armor_leggings_crystal.png^3d_armor_boots_crystal.png^shields_shield_crystal.png\", \"mobs_pick_lava.png\"}, [\"model\"] = \"skinsdb_3d_armor_character_5.b3d\", [\"animation_speed\"] = 30}",
		hud_state = "on",
		jointime = "1614192315",
		bitten = "0",
		yl_commons_player_joined = "1684435363",
		["stamina:level"] = "16",
		yl_commons_thankyou = "14",
		["stamina:poisoned"] = "no",
		arenalib_infobox_arenaID = "0",
		yl_commons_player_created = "1614192315",
		["signslib:pos"] = "(1042,17,1985)",
		partychat = "main",
		["petz:werewolf"] = "1",
		["petz:werewolf_clan_idx"] = "1",
		["petz:lycanthropy"] = "1",
		repellant = "0",
		xp = "175916",
		yl_church = "return {[\"last_heal\"] = 1622582060, [\"last_death\"] = {[\"y\"] = 69, [\"z\"] = 456, [\"x\"] = 2753}, [\"last_death_portal\"] = 1678915250}",
		["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}",
		played_time = "3026624"
	}
}

Log identifier


[MOD] yl_report log identifier = 4fI3Gz2xgTkbggeGd9PVkqSmN4dF1Hen

Profiler save:

profile-20230518T193836.json_prettyEE

Status:

# Server: version: 5.6.1-yl | game: Minetest Game | uptime: 17h 42min 48s | max lag: 2.21s | clients (31/52): AliasAlreadyTaken, AspireMint, Bailiff, Bishiro, bizon, Boot, Chameleon, daydream, Diaeresis, Ecklair, flux, flux_testing, JeCel, laira, MineWorlds, Murmel, niceride, Papi, Ravise, rheo, Scathach, Service, shanish2, Sir_Henry_the_MXII, STEALTH, Sysmatic, Test_User, tfweyrur, the_chosen_one, whosit, WoS

Teleport command:

/teleport xyz 6451 5 2692

Compass command:

/give_compass Construction 4fI3Gz2xgTkbggeGd9PVkqSmN4dF1Hen D2691E 6451 5 2692

Test_User reports a bug: > /mail is slow, hangs the server ~2.5s to open mine Player position: ``` { z = 2692.2180175781, x = 6450.6967773438, y = 4.625 } ``` Player look: ``` { z = -0.15547348558903, x = -0.50194466114044, y = -0.85081112384796 } ``` Player information: ``` { major = 5, state = "Active", protocol_version = 41, version_string = "5.6.0", max_rtt = 5.5590000152588, ip_version = 6, avg_rtt = 0.22200000286102, min_jitter = 0, max_jitter = 5.3649997711182, minor = 6, connection_uptime = 3372, min_rtt = 0.1169999986887, patch = 0, serialization_version = 29, formspec_version = 6, avg_jitter = 0.092000007629395, lang_code = "" } ``` Player meta: ``` { fields = { digged_nodes = "256330", placed_nodes = "34452", died = "344", punch_count = "21697", partypvp = "true", ["stamina:exhaustion"] = "104.5", ["petz:werewolf_vignette_id"] = "19", ["petz:old_override_table"] = "return {[\"new_move\"] = true, [\"sneak\"] = true, [\"sneak_glitch\"] = false, [\"jump\"] = 1.5, [\"speed\"] = 2, [\"gravity\"] = 1}", ["3d_armor_inventory"] = "return {\"3d_armor:helmet_crystal 1 12283\", \"\", \"3d_armor:chestplate_crystal 1 12083\", \"3d_armor:leggings_crystal 1 12033\", \"3d_armor:boots_crystal 1 14475\", \"shields:shield_crystal 1 11940\"}", inflicted_damage = "340540", crafted = "45805", ["petz:pre_werewolf_animation"] = "return {[\"animation\"] = \"stand\", [\"textures\"] = {\"player.Test_User.0.png\", \"blank.png\", \"3d_armor_trans.png^3d_armor_helmet_crystal.png^3d_armor_chestplate_crystal.png^3d_armor_leggings_crystal.png^3d_armor_boots_crystal.png^shields_shield_crystal.png\", \"mobs_pick_lava.png\"}, [\"model\"] = \"skinsdb_3d_armor_character_5.b3d\", [\"animation_speed\"] = 30}", hud_state = "on", jointime = "1614192315", bitten = "0", yl_commons_player_joined = "1684435363", ["stamina:level"] = "16", yl_commons_thankyou = "14", ["stamina:poisoned"] = "no", arenalib_infobox_arenaID = "0", yl_commons_player_created = "1614192315", ["signslib:pos"] = "(1042,17,1985)", partychat = "main", ["petz:werewolf"] = "1", ["petz:werewolf_clan_idx"] = "1", ["petz:lycanthropy"] = "1", repellant = "0", xp = "175916", yl_church = "return {[\"last_heal\"] = 1622582060, [\"last_death\"] = {[\"y\"] = 69, [\"z\"] = 456, [\"x\"] = 2753}, [\"last_death_portal\"] = 1678915250}", ["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}", played_time = "3026624" } } ``` Log identifier ``` [MOD] yl_report log identifier = 4fI3Gz2xgTkbggeGd9PVkqSmN4dF1Hen ``` Profiler save: ``` profile-20230518T193836.json_prettyEE ``` Status: ``` # Server: version: 5.6.1-yl | game: Minetest Game | uptime: 17h 42min 48s | max lag: 2.21s | clients (31/52): AliasAlreadyTaken, AspireMint, Bailiff, Bishiro, bizon, Boot, Chameleon, daydream, Diaeresis, Ecklair, flux, flux_testing, JeCel, laira, MineWorlds, Murmel, niceride, Papi, Ravise, rheo, Scathach, Service, shanish2, Sir_Henry_the_MXII, STEALTH, Sysmatic, Test_User, tfweyrur, the_chosen_one, whosit, WoS ``` Teleport command: ``` /teleport xyz 6451 5 2692 ``` Compass command: ``` /give_compass Construction 4fI3Gz2xgTkbggeGd9PVkqSmN4dF1Hen D2691E 6451 5 2692 ```

AliasAlreadyTaken was assigned by yourland-report

2023-05-18 19:38:36 +00:00

AliasAlreadyTaken added the

1. kind/bug

3. source/mod upstream

labels 2023-05-18 19:50:43 +00:00

flux added the

2. prio/elevated

3. source/lag

labels 2023-05-19 00:16:49 +00:00

flux commented

2023-05-19 00:17:15 +00:00

according to the profiler, mail can take up to 5.8s on a server step.

AzelfYL referenced this issue

2023-05-26 14:49:57 +00:00

Azelf reports: Massive lag spikes for no appr ... #4604

whosit commented

2023-05-27 11:15:46 +00:00

There are multiple problems with the mail implementation:

mail.get_storage_entry() is often called to get user's mailbox. Mailbox is stored as monolithic JSON string of all inbox/outbox mails, and it's parsed each and every time (with 100+ mails it starts becoming noticeable and server spends significant amount of time doing Json::OurReader::decodeString):
02853fc3d0/storage.lua (L17)
Each mail has UUID assigned, but it's not used in a smart way. For example, function for deleting mails just iterates over every mail in a mailbox and every to-be-deleted id. Basically this code has quadratic-like running time: O(total_mails*ids_to_delete). As an added bonus: no early break when mail is found. Should just use lua tables properly to lookup mail in constant time.
9679251249/storage.lua (L112)
just iterates over every mail when it's not necessary, e.g. to count unread ones:
9679251249/hud.lua (L45)

local mail_spam = function(playername, param)
    local number = tonumber(param)
    if not number then
        number = 10
    end
    for i = 0, number do
        local success, err = mail.send({
                from = "singleplayer",
                to = playername,
                cc = "",
                bcc = "",
                subject = string.format("subject line %04d", i),
                body = "mail body test test"
        })
    end
end


minetest.register_chatcommand("mail_spam", {
    params = "[how_many]",
    description = "Spam a mailbox of user with mails",
    privs = { server = true },
    func = mail_spam
})

There are multiple problems with the mail implementation: - `mail.get_storage_entry()` is often called to get user's mailbox. Mailbox is stored as monolithic JSON string of all inbox/outbox mails, and it's parsed each and every time (with 100+ mails it starts becoming noticeable and server spends significant amount of time doing `Json::OurReader::decodeString`): https://github.com/mt-mods/mail/blob/02853fc3d0dc6a8da7f770c0e843ccf3d76b312e/storage.lua#L17 - Each mail has UUID assigned, but it's not used in a smart way. For example, function for deleting mails just _iterates_ over every mail in a mailbox and every to-be-deleted id. Basically this code has quadratic-like running time: `O(total_mails*ids_to_delete)`. As an added bonus: no early `break` when mail is found. Should just use lua tables properly to lookup mail in constant time. https://github.com/mt-mods/mail/blob/9679251249e243fd9d08faf2240cd16c89438f11/storage.lua#L112 - just iterates over every mail when it's not necessary, e.g. to count unread ones: https://github.com/mt-mods/mail/blob/9679251249e243fd9d08faf2240cd16c89438f11/hud.lua#L45 ```lua local mail_spam = function(playername, param) local number = tonumber(param) if not number then number = 10 end for i = 0, number do local success, err = mail.send({ from = "singleplayer", to = playername, cc = "", bcc = "", subject = string.format("subject line %04d", i), body = "mail body test test" }) end end minetest.register_chatcommand("mail_spam", { params = "[how_many]", description = "Spam a mailbox of user with mails", privs = { server = true }, func = mail_spam }) ```

AliasAlreadyTaken commented

2023-05-27 14:09:41 +00:00

I migrated the modstorage on the testserver to postgres.

Want to try again there?

I migrated the modstorage on the testserver to postgres. Want to try again there?

whosit commented

2023-05-27 15:20:52 +00:00

Turns out, for each mail displayed, get_setting() is called:
9679251249/ui/inbox.lua (L63)
which in turn calls mail.get_storage_entry(playername)
9679251249/storage.lua (L275)

That means, for every mail in the mailbox, it re-reads and re-parses the JSON string containing the whole mailbox.

If we just move this get_setting() outside the loop, at least the display will lag server much less. Same could apply to other parts of the code it seems.

Turns out, for each mail displayed, `get_setting()` is called: https://github.com/mt-mods/mail/blob/9679251249e243fd9d08faf2240cd16c89438f11/ui/inbox.lua#L63 which in turn calls `mail.get_storage_entry(playername)` https://github.com/mt-mods/mail/blob/9679251249e243fd9d08faf2240cd16c89438f11/storage.lua#L275 That means, for every mail in the mailbox, it re-reads and re-parses the JSON string containing the whole mailbox. If we just move this get_setting() outside the loop, at least the display will lag server much less. Same could apply to other parts of the code it seems.

whosit referenced this issue

2023-06-04 09:32:46 +00:00

Mail client lag #4548

Boot commented

2023-06-11 11:21:09 +00:00

It might be helpful if no mails of the /bug and /reports were sent in the time until the bug is fixed. It's enough to get them displayed in the chat and here on Gitea.

whosit commented

2023-06-11 12:27:31 +00:00

How to use mailing lists?
Maybe make bugreport mails subscribe only mailing list?
And since they are public anyway, it's not a problem if non-staff subscribe to them.
Other mails are much more rare and less of a problem.

How to use mailing lists? Maybe make bugreport mails subscribe only mailing list? And since they are public anyway, it's not a problem if non-staff subscribe to them. Other mails are much more rare and less of a problem.

Boot commented

2023-06-15 17:29:47 +00:00

A big thank you to @whosit for solving the mail problem.

👍 1

flux commented

2024-03-31 01:03:41 +00:00

@whosit is this live? or fixed?

Sign in to join this conversation.