rheo reports: huge, ongoing lag ... #5732

Open
opened 2023-12-18 22:36:49 +00:00 by yourland-report · 6 comments

rheo reports a bug:

huge, ongoing lag

Player position:

{
	x = -5.7979998588562,
	y = -20284.48046875,
	z = 6.9120001792908
}

Player look:

{
	x = 0.17081464827061,
	y = -0.58240675926208,
	z = -0.79474818706512
}

Player information:

{
	lang_code = "",
	version_string = "5.9.0-dev-454dd8576",
	major = 5,
	protocol_version = 42,
	formspec_version = 7,
	ip_version = 6,
	max_rtt = 4.5359997749329,
	avg_rtt = 0.18000000715256,
	min_jitter = 0,
	max_jitter = 4.356999874115,
	avg_jitter = 0.0010000020265579,
	connection_uptime = 15519,
	serialization_version = 29,
	patch = 0,
	state = "Active",
	minor = 9,
	min_rtt = 0.16899999976158
}

Player meta:

{
	fields = {
		["ethereal:fly_timer"] = "-99",
		["stamina:poisoned"] = "no",
		placed_nodes = "20527",
		died = "2",
		crafted = "2220",
		arenalib_infobox_arenaID = "0",
		["ocean_build.last_warning"] = "1.66814e+09",
		punch_count = "1229",
		inflicted_damage = "257022",
		partychat = "party",
		hud_state = "off",
		xp = "0",
		yl_church = "return {[\"last_death\"] = {[\"y\"] = 15, [\"x\"] = 1353, [\"z\"] = 1089}}",
		yl_commons_player_created = "1644205752",
		yl_commons_player_joined = "1702923507",
		["petz:werewolf"] = "0",
		yl_commons_thankyou = "70",
		["signslib:pos"] = "(1984,14,1099)",
		["3d_armor_inventory"] = "return {\"3d_armor:boots_quickrun\", \"\", \"\", \"\", \"\", \"\"}",
		["hud_manager:spawnit:hud_enabled"] = "y",
		["petz:old_override_table"] = "return {[\"sneak\"] = true, [\"speed\"] = 2, [\"new_move\"] = true, [\"jump\"] = 1.5, [\"gravity\"] = 1, [\"sneak_glitch\"] = false}",
		["petz:werewolf_clan_idx"] = "2",
		repellant = "0",
		played_time = "6874584",
		jointime = "1644205752",
		bitten = "0",
		["ocean_build.ocean_built"] = "6",
		["petz:lycanthropy"] = "0",
		["stamina:exhaustion"] = "15.5",
		digged_nodes = "18746",
		["petz:werewolf_vignette_id"] = "16",
		["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}",
		["stamina:level"] = "0"
	}
}

Log identifier


[MOD] yl_report log identifier = 1mMdVQJ7pBEAejxxy1u1E8Let6E1kM9a

Profiler save:

profile-20231218T223649.json_prettyEE

Status:

# Server: version: 5.7.0-yl-thx-tmm | game: Minetest Game | uptime: 1d 17h 23min 41s | max lag: 2.66s | clients (21/52): AliasAlreadyTaken, Bailiff, Chache, crankyape, Deathwing, ffelder, flux, Hallifax, Heron, Historia_reiss, Keya, LA55, Lucien_II, Lupercus, mahou, Nomtom, Parrish, poppyasdan, rheo, Service, tour

Teleport command:

/teleport xyz -6 -20284 7

Compass command:

/give_compass Construction 1mMdVQJ7pBEAejxxy1u1E8Let6E1kM9a D2691E -6 -20284 7
rheo reports a bug: > huge, ongoing lag Player position: ``` { x = -5.7979998588562, y = -20284.48046875, z = 6.9120001792908 } ``` Player look: ``` { x = 0.17081464827061, y = -0.58240675926208, z = -0.79474818706512 } ``` Player information: ``` { lang_code = "", version_string = "5.9.0-dev-454dd8576", major = 5, protocol_version = 42, formspec_version = 7, ip_version = 6, max_rtt = 4.5359997749329, avg_rtt = 0.18000000715256, min_jitter = 0, max_jitter = 4.356999874115, avg_jitter = 0.0010000020265579, connection_uptime = 15519, serialization_version = 29, patch = 0, state = "Active", minor = 9, min_rtt = 0.16899999976158 } ``` Player meta: ``` { fields = { ["ethereal:fly_timer"] = "-99", ["stamina:poisoned"] = "no", placed_nodes = "20527", died = "2", crafted = "2220", arenalib_infobox_arenaID = "0", ["ocean_build.last_warning"] = "1.66814e+09", punch_count = "1229", inflicted_damage = "257022", partychat = "party", hud_state = "off", xp = "0", yl_church = "return {[\"last_death\"] = {[\"y\"] = 15, [\"x\"] = 1353, [\"z\"] = 1089}}", yl_commons_player_created = "1644205752", yl_commons_player_joined = "1702923507", ["petz:werewolf"] = "0", yl_commons_thankyou = "70", ["signslib:pos"] = "(1984,14,1099)", ["3d_armor_inventory"] = "return {\"3d_armor:boots_quickrun\", \"\", \"\", \"\", \"\", \"\"}", ["hud_manager:spawnit:hud_enabled"] = "y", ["petz:old_override_table"] = "return {[\"sneak\"] = true, [\"speed\"] = 2, [\"new_move\"] = true, [\"jump\"] = 1.5, [\"gravity\"] = 1, [\"sneak_glitch\"] = false}", ["petz:werewolf_clan_idx"] = "2", repellant = "0", played_time = "6874584", jointime = "1644205752", bitten = "0", ["ocean_build.ocean_built"] = "6", ["petz:lycanthropy"] = "0", ["stamina:exhaustion"] = "15.5", digged_nodes = "18746", ["petz:werewolf_vignette_id"] = "16", ["unified_inventory:bags"] = "return {\"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\", \"unified_inventory:bag_large\"}", ["stamina:level"] = "0" } } ``` Log identifier ``` [MOD] yl_report log identifier = 1mMdVQJ7pBEAejxxy1u1E8Let6E1kM9a ``` Profiler save: ``` profile-20231218T223649.json_prettyEE ``` Status: ``` # Server: version: 5.7.0-yl-thx-tmm | game: Minetest Game | uptime: 1d 17h 23min 41s | max lag: 2.66s | clients (21/52): AliasAlreadyTaken, Bailiff, Chache, crankyape, Deathwing, ffelder, flux, Hallifax, Heron, Historia_reiss, Keya, LA55, Lucien_II, Lupercus, mahou, Nomtom, Parrish, poppyasdan, rheo, Service, tour ``` Teleport command: ``` /teleport xyz -6 -20284 7 ``` Compass command: ``` /give_compass Construction 1mMdVQJ7pBEAejxxy1u1E8Let6E1kM9a D2691E -6 -20284 7 ```
AliasAlreadyTaken was assigned by yourland-report 2023-12-18 22:36:49 +00:00
flux added the
1. kind/bug
2. prio/critical
3. source/lag
labels 2023-12-18 22:48:40 +00:00
Member

all server steps over 2 seconds

all server steps over 2 seconds

dtime's been hovering 1.7-2.5s

dtime's been hovering 1.7-2.5s
Member

this has stopped now, but still needs more investigation

this has stopped now, but still needs more investigation

check the memory? could be #4943

check the memory? could be https://gitea.your-land.de/your-land/bugtracker/issues/4943

Some candidates:

 total:                                                  |      1732 |   1687665 |     84718 | 100.0 | 100.0 | 100.0

 yl_statuseffects:                                       |      1351 |    908066 |      4865 |   0.2 |  94.6 |   6.2
  - on_joinplayer[2] ..................................  |        25 |       126 |        73 |   0.0 |   0.1 |   0.0
  - on_player_receive_fields[1] .......................  |        29 |      4380 |       102 |   0.0 |   3.5 |   0.1
  - globalstep[3] .....................................  |         1 |       134 |         2 |   0.0 |   0.2 |   0.0
  - globalstep[2] .....................................  |         1 |      1313 |       155 |   0.0 |   3.2 |   0.2
  - globalstep[1] .....................................  |      1349 |    907375 |      4732 |   0.2 |  94.6 |   6.0
  - on_leaveplayer[3] .................................  |        36 |       161 |        90 |   0.0 |   0.5 |   0.1
  - on_leaveplayer[2] .................................  |        67 |      1020 |       177 |   0.0 |   0.5 |   0.2
  - on_leaveplayer[1] .................................  |         1 |         1 |         1 |   0.0 |   0.0 |   0.0
  - on_joinplayer[1] ..................................  |        96 |      1281 |       345 |   0.1 |   0.7 |   0.2

 party:                                                  |         0 |   1637986 |       111 |   0.0 |  97.1 |   0.0
  - /p ................................................  |     34630 |   1637986 |    436767 |  30.4 |  97.1 |  56.4
  - on_newplayer[1] ...................................  |     71786 |    145519 |     99898 |  22.4 |  44.4 |  35.4
  - on_joinplayer[1] ..................................  |     23659 |    141654 |     39410 |   8.5 |  30.6 |  17.3
  - on_joinplayer[2] ..................................  |       108 |      2581 |       394 |   0.0 |   0.9 |   0.2
  - on_punchplayer[1] .................................  |        78 |       692 |       212 |   0.0 |   1.7 |   0.3
  - on_leaveplayer[1] .................................  |         4 |        55 |        11 |   0.0 |   0.1 |   0.0

 default:                                                |        26 |    307632 |      4472 |   0.0 |  45.9 |   4.7
  - ABM 'Grass spread' ................................  |        21 |      1650 |       192 |   0.0 |   4.2 |   0.2
  - ABM 'Grow cactus' .................................  |         1 |       311 |        94 |   0.0 |   0.3 |   0.1
  - ABM 'Grass covered' ...............................  |        72 |      6107 |       470 |   0.0 |   4.7 |   0.6
  - ABM 'Lava cooling' ................................  |        64 |      2850 |       284 |   0.0 |   2.6 |   0.4
  - ABM 'Moss growth' .................................  |         1 |       661 |       166 |   0.0 |   0.8 |   0.2
  - on_step[1] ........................................  |       101 |    307482 |      4197 |   0.0 |  45.9 |   4.5
  - on_craft[1] .......................................  |         1 |        59 |         5 |   0.0 |   0.1 |   0.0
  - on_player_receive_fields[1] .......................  |         1 |        25 |         1 |   0.0 |   0.1 |   0.0
  - on_leaveplayer[1] .................................  |         1 |         1 |         1 |   0.0 |   0.0 |   0.0
  - on_leaveplayer[2] .................................  |         1 |         3 |         1 |   0.0 |   0.0 |   0.0
  - get_staticdata[1] .................................  |         5 |     37076 |       206 |   0.0 |  14.5 |   0.1
  - on_joinplayer[1] ..................................  |         8 |       241 |        36 |   0.0 |   0.1 |   0.0
  - on_player_receive_fields[2] .......................  |         1 |       306 |         4 |   0.0 |   0.6 |   0.0
  - on_activate[1] ....................................  |         5 |     48115 |       227 |   0.0 |  18.5 |   0.2
  - on_punch[1] .......................................  |        27 |       277 |        69 |   0.0 |   0.7 |   0.1

 darkage:                                                |         0 |     82808 |         8 |   0.0 |  58.7 |   0.0
  - on_generated[1] ...................................  |     16507 |     82808 |     34113 |   8.1 |  58.7 |  30.9

 wielded_light:                                          |        27 |    312978 |      4934 |   0.1 |  46.2 |   5.4
  - on_punch[1] .......................................  |        28 |       279 |        70 |   0.0 |   0.7 |   0.1
  - globalstep[1] .....................................  |         1 |     23779 |       341 |   0.0 |  35.0 |   0.5
  - get_staticdata[1] .................................  |         5 |     37291 |       211 |   0.0 |  14.6 |   0.1
  - on_step[1] ........................................  |       117 |    312391 |      4406 |   0.0 |  46.1 |   4.8
  - on_activate[1] ....................................  |         6 |     48347 |       232 |   0.0 |  18.8 |   0.2

 water_life:                                             |       229 |    444121 |      6008 |   0.1 |  89.9 |   7.5

 smartshop:                                              |         0 |    299127 |       956 |   0.0 |  42.0 |   0.4
  - LBM 'smartshop:fix_orientation' ...................  |         1 |       181 |        12 |   0.0 |   0.0 |   0.0
  - on_activate[2] ....................................  |       171 |      6781 |      1133 |   0.0 |   3.0 |   0.6
  - on_activate[3] ....................................  |       159 |    110199 |      3831 |   0.0 |  15.1 |   1.4
  - on_leaveplayer[1] .................................  |         5 |        32 |         9 |   0.0 |   0.0 |   0.0
  - on_player_receive_fields[1] .......................  |         1 |     17110 |       164 |   0.0 |  11.1 |   0.2
  - LBM 'smartshop:repay_lost_stuff' ..................  |       119 |     47066 |      4916 |   0.0 |  11.0 |   1.9
  - get_staticdata[2] .................................  |         6 |      1756 |       162 |   0.0 |   1.0 |   0.1
  - get_staticdata[1] .................................  |        10 |     13276 |      1033 |   0.0 |   4.8 |   0.5
  - on_activate[4] ....................................  |       162 |     12457 |      1274 |   0.0 |   3.4 |   0.7
  - get_staticdata[4] .................................  |         8 |      2062 |       173 |   0.0 |   1.1 |   0.1
  - on_activate[1] ....................................  |       173 |    139825 |      6055 |   0.0 |  21.0 |   2.4
  - get_staticdata[3] .................................  |         5 |      5615 |       511 |   0.0 |   2.3 |   0.2

 signs_lib:                                              |         0 |    287496 |      2797 |   0.0 |  74.2 |   1.2
  - LBM 'Restore sign text' ...........................  |       152 |    285580 |     31447 |   0.1 |  73.5 |  13.9
  - ...st of loaded blocks, log only those with signs'   |         2 |      1389 |        94 |   0.0 |   0.4 |   0.0
  - on_activate[1] ....................................  |         2 |      3642 |       209 |   0.0 |   0.6 |   0.1
  - on_player_receive_fields[1] .......................  |         1 |      3279 |        38 |   0.0 |   3.3 |   0.0

 signs_api:                                              |         0 |    112925 |       428 |   0.0 |  20.0 |   0.2
  - LBM 'Update signs_api formspecs' ..................  |        54 |       190 |       122 |   0.0 |   0.1 |   0.1
  - on_activate[1] ....................................  |        17 |     88696 |      3238 |   0.0 |  18.0 |   1.4
  - get_staticdata[1] .................................  |         5 |     48247 |      1434 |   0.0 |  14.0 |   0.7

 itemframes:                                             |         0 |    149792 |      1176 |   0.0 |  63.5 |   0.6
  - LBM 'Restore itemframe entities' ..................  |       133 |    149792 |     13739 |   0.0 |  63.5 |   6.8
  - on_activate[1] ....................................  |         2 |      1121 |        45 |   0.0 |   0.4 |   0.0

 petz:                                                   |      4001 |    220641 |     22076 |   1.0 |  75.1 |  31.2

None of them amount to 2.66s though, as shown in the max_lag

Some candidates: ``` total: | 1732 | 1687665 | 84718 | 100.0 | 100.0 | 100.0 yl_statuseffects: | 1351 | 908066 | 4865 | 0.2 | 94.6 | 6.2 - on_joinplayer[2] .................................. | 25 | 126 | 73 | 0.0 | 0.1 | 0.0 - on_player_receive_fields[1] ....................... | 29 | 4380 | 102 | 0.0 | 3.5 | 0.1 - globalstep[3] ..................................... | 1 | 134 | 2 | 0.0 | 0.2 | 0.0 - globalstep[2] ..................................... | 1 | 1313 | 155 | 0.0 | 3.2 | 0.2 - globalstep[1] ..................................... | 1349 | 907375 | 4732 | 0.2 | 94.6 | 6.0 - on_leaveplayer[3] ................................. | 36 | 161 | 90 | 0.0 | 0.5 | 0.1 - on_leaveplayer[2] ................................. | 67 | 1020 | 177 | 0.0 | 0.5 | 0.2 - on_leaveplayer[1] ................................. | 1 | 1 | 1 | 0.0 | 0.0 | 0.0 - on_joinplayer[1] .................................. | 96 | 1281 | 345 | 0.1 | 0.7 | 0.2 party: | 0 | 1637986 | 111 | 0.0 | 97.1 | 0.0 - /p ................................................ | 34630 | 1637986 | 436767 | 30.4 | 97.1 | 56.4 - on_newplayer[1] ................................... | 71786 | 145519 | 99898 | 22.4 | 44.4 | 35.4 - on_joinplayer[1] .................................. | 23659 | 141654 | 39410 | 8.5 | 30.6 | 17.3 - on_joinplayer[2] .................................. | 108 | 2581 | 394 | 0.0 | 0.9 | 0.2 - on_punchplayer[1] ................................. | 78 | 692 | 212 | 0.0 | 1.7 | 0.3 - on_leaveplayer[1] ................................. | 4 | 55 | 11 | 0.0 | 0.1 | 0.0 default: | 26 | 307632 | 4472 | 0.0 | 45.9 | 4.7 - ABM 'Grass spread' ................................ | 21 | 1650 | 192 | 0.0 | 4.2 | 0.2 - ABM 'Grow cactus' ................................. | 1 | 311 | 94 | 0.0 | 0.3 | 0.1 - ABM 'Grass covered' ............................... | 72 | 6107 | 470 | 0.0 | 4.7 | 0.6 - ABM 'Lava cooling' ................................ | 64 | 2850 | 284 | 0.0 | 2.6 | 0.4 - ABM 'Moss growth' ................................. | 1 | 661 | 166 | 0.0 | 0.8 | 0.2 - on_step[1] ........................................ | 101 | 307482 | 4197 | 0.0 | 45.9 | 4.5 - on_craft[1] ....................................... | 1 | 59 | 5 | 0.0 | 0.1 | 0.0 - on_player_receive_fields[1] ....................... | 1 | 25 | 1 | 0.0 | 0.1 | 0.0 - on_leaveplayer[1] ................................. | 1 | 1 | 1 | 0.0 | 0.0 | 0.0 - on_leaveplayer[2] ................................. | 1 | 3 | 1 | 0.0 | 0.0 | 0.0 - get_staticdata[1] ................................. | 5 | 37076 | 206 | 0.0 | 14.5 | 0.1 - on_joinplayer[1] .................................. | 8 | 241 | 36 | 0.0 | 0.1 | 0.0 - on_player_receive_fields[2] ....................... | 1 | 306 | 4 | 0.0 | 0.6 | 0.0 - on_activate[1] .................................... | 5 | 48115 | 227 | 0.0 | 18.5 | 0.2 - on_punch[1] ....................................... | 27 | 277 | 69 | 0.0 | 0.7 | 0.1 darkage: | 0 | 82808 | 8 | 0.0 | 58.7 | 0.0 - on_generated[1] ................................... | 16507 | 82808 | 34113 | 8.1 | 58.7 | 30.9 wielded_light: | 27 | 312978 | 4934 | 0.1 | 46.2 | 5.4 - on_punch[1] ....................................... | 28 | 279 | 70 | 0.0 | 0.7 | 0.1 - globalstep[1] ..................................... | 1 | 23779 | 341 | 0.0 | 35.0 | 0.5 - get_staticdata[1] ................................. | 5 | 37291 | 211 | 0.0 | 14.6 | 0.1 - on_step[1] ........................................ | 117 | 312391 | 4406 | 0.0 | 46.1 | 4.8 - on_activate[1] .................................... | 6 | 48347 | 232 | 0.0 | 18.8 | 0.2 water_life: | 229 | 444121 | 6008 | 0.1 | 89.9 | 7.5 smartshop: | 0 | 299127 | 956 | 0.0 | 42.0 | 0.4 - LBM 'smartshop:fix_orientation' ................... | 1 | 181 | 12 | 0.0 | 0.0 | 0.0 - on_activate[2] .................................... | 171 | 6781 | 1133 | 0.0 | 3.0 | 0.6 - on_activate[3] .................................... | 159 | 110199 | 3831 | 0.0 | 15.1 | 1.4 - on_leaveplayer[1] ................................. | 5 | 32 | 9 | 0.0 | 0.0 | 0.0 - on_player_receive_fields[1] ....................... | 1 | 17110 | 164 | 0.0 | 11.1 | 0.2 - LBM 'smartshop:repay_lost_stuff' .................. | 119 | 47066 | 4916 | 0.0 | 11.0 | 1.9 - get_staticdata[2] ................................. | 6 | 1756 | 162 | 0.0 | 1.0 | 0.1 - get_staticdata[1] ................................. | 10 | 13276 | 1033 | 0.0 | 4.8 | 0.5 - on_activate[4] .................................... | 162 | 12457 | 1274 | 0.0 | 3.4 | 0.7 - get_staticdata[4] ................................. | 8 | 2062 | 173 | 0.0 | 1.1 | 0.1 - on_activate[1] .................................... | 173 | 139825 | 6055 | 0.0 | 21.0 | 2.4 - get_staticdata[3] ................................. | 5 | 5615 | 511 | 0.0 | 2.3 | 0.2 signs_lib: | 0 | 287496 | 2797 | 0.0 | 74.2 | 1.2 - LBM 'Restore sign text' ........................... | 152 | 285580 | 31447 | 0.1 | 73.5 | 13.9 - ...st of loaded blocks, log only those with signs' | 2 | 1389 | 94 | 0.0 | 0.4 | 0.0 - on_activate[1] .................................... | 2 | 3642 | 209 | 0.0 | 0.6 | 0.1 - on_player_receive_fields[1] ....................... | 1 | 3279 | 38 | 0.0 | 3.3 | 0.0 signs_api: | 0 | 112925 | 428 | 0.0 | 20.0 | 0.2 - LBM 'Update signs_api formspecs' .................. | 54 | 190 | 122 | 0.0 | 0.1 | 0.1 - on_activate[1] .................................... | 17 | 88696 | 3238 | 0.0 | 18.0 | 1.4 - get_staticdata[1] ................................. | 5 | 48247 | 1434 | 0.0 | 14.0 | 0.7 itemframes: | 0 | 149792 | 1176 | 0.0 | 63.5 | 0.6 - LBM 'Restore itemframe entities' .................. | 133 | 149792 | 13739 | 0.0 | 63.5 | 6.8 - on_activate[1] .................................... | 2 | 1121 | 45 | 0.0 | 0.4 | 0.0 petz: | 4001 | 220641 | 22076 | 1.0 | 75.1 | 31.2 ``` None of them amount to 2.66s though, as shown in the max_lag
Member

None of them amount to 2.66s though, as shown in the max_lag

yeah, and i'd expect to see something that dramatically increased the average usage, not just do a single maximal usage.

what logs the profiler stuff? probably it should also reset the profiler every time it writes to disk - this way, we can get a better notion of the usage for a particular period

> None of them amount to 2.66s though, as shown in the max_lag yeah, and i'd expect to see something that dramatically increased the average usage, not just do a single maximal usage. what logs the profiler stuff? probably it should also *reset* the profiler every time it writes to disk - this way, we can get a better notion of the usage for a particular period
Sign in to join this conversation.
No Milestone
No project
No Assignees
5 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#5732
No description provided.