AliasAlreadyTaken reports: instrument_mod of debuggery do ... #5746

Closed
opened 2023-12-19 12:24:15 +00:00 by yourland-report · 23 comments

AliasAlreadyTaken reports a bug:

instrument_mod of debuggery doesn't write to log anymore

Player position:

{
	x = 2042.919921875,
	y = 15.5,
	z = 1226.5209960938
}

Player look:

{
	x = 0.034909933805466,
	y = -0.36617639660835,
	z = 0.92989039421082
}

Player information:

{
	lang_code = "de",
	version_string = "5.8.0",
	ip_version = 6,
	min_rtt = 0.014999999664724,
	avg_rtt = 0.018999999389052,
	major = 5,
	max_jitter = 0.56299996376038,
	avg_jitter = 0,
	connection_uptime = 33953,
	protocol_version = 42,
	patch = 0,
	formspec_version = 7,
	max_rtt = 0.60000002384186,
	state = "Active",
	serialization_version = 29,
	minor = 8,
	min_jitter = 0
}

Player meta:

{
	fields = {
		played_time = "97207186",
		digged_nodes = "140492",
		placed_nodes = "181872",
		died = "1591",
		crafted = "4788",
		["ocean_build.last_warning"] = "1.67421e+09",
		["ocean_build.forbidden"] = "true",
		["ocean_build.ocean_built"] = "12",
		xp_redo_hud_color = "0xFFFF00",
		partychat = "party",
		hud_state = "on",
		["sethome:home"] = "(1983.4349365234,17.5,1183.5950927734)",
		partypvp = "true",
		team = "STAFF",
		yl_church = "return {[\"last_heal\"] = 1683837139, [\"last_death\"] = {[\"x\"] = 2251, [\"y\"] = -164, [\"z\"] = 1401}, [\"last_death_portal\"] = 1683839371}",
		yl_commons_player_joined = "1702954728",
		["petz:werewolf"] = "0",
		["petz:lycanthropy"] = "0",
		lagometer = "1",
		["signslib:pos"] = "(1993,17,990)",
		["ethereal:fly_timer"] = "-99",
		yl_audio_state = "off",
		["3d_armor_inventory"] = "return {\"\", \"\", \"\", \"\", \"\", \"\"}",
		["hud_manager:spawnit:hud_enabled"] = "y",
		["petz:old_override_table"] = "return {[\"speed\"] = 1, [\"new_move\"] = true, [\"sneak_glitch\"] = false, [\"gravity\"] = 1, [\"jump\"] = 1, [\"sneak\"] = true}",
		["arena_lib_editor.players_number"] = "0",
		["stamina:poisoned"] = "no",
		punch_count = "65132",
		["petz:werewolf_clan_idx"] = "4",
		szutil_watch = "return {}",
		["arena_lib_editor.spawner_ID"] = "0",
		repellant = "0",
		arenalib_watchID = "0",
		["arena_lib_editor.team_ID"] = "0",
		xp = "0",
		bitten = "0",
		inflicted_damage = "2991830",
		["petz:werewolf_vignette_id"] = "19",
		arenalib_infobox_arenaID = "0",
		yl_commons_thankyou = "1397",
		["stamina:exhaustion"] = "81.5",
		["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 = 6qbNBWbnRtq3zu1J2Im1DkL8PSK8hvpI

Profiler save:

profile-20231219T122415.json_prettyEE

Status:

# Server: version: 5.7.0-yl-thx-tmm | game: Minetest Game | uptime: 2d 7h 27min 24s | max lag: 1.51s | clients (14/52): ALCOHOL3, AliasAlreadyTaken, Bailiff, Boris, Chache, Davidsoft, daydream, Ecklair, Heron, Murmel, nazthelizard122, Nomtom, Service, Silph

Teleport command:

/teleport xyz 2043 16 1227

Compass command:

/give_compass Construction 6qbNBWbnRtq3zu1J2Im1DkL8PSK8hvpI D2691E 2043 16 1227
AliasAlreadyTaken reports a bug: > instrument_mod of debuggery doesn't write to log anymore Player position: ``` { x = 2042.919921875, y = 15.5, z = 1226.5209960938 } ``` Player look: ``` { x = 0.034909933805466, y = -0.36617639660835, z = 0.92989039421082 } ``` Player information: ``` { lang_code = "de", version_string = "5.8.0", ip_version = 6, min_rtt = 0.014999999664724, avg_rtt = 0.018999999389052, major = 5, max_jitter = 0.56299996376038, avg_jitter = 0, connection_uptime = 33953, protocol_version = 42, patch = 0, formspec_version = 7, max_rtt = 0.60000002384186, state = "Active", serialization_version = 29, minor = 8, min_jitter = 0 } ``` Player meta: ``` { fields = { played_time = "97207186", digged_nodes = "140492", placed_nodes = "181872", died = "1591", crafted = "4788", ["ocean_build.last_warning"] = "1.67421e+09", ["ocean_build.forbidden"] = "true", ["ocean_build.ocean_built"] = "12", xp_redo_hud_color = "0xFFFF00", partychat = "party", hud_state = "on", ["sethome:home"] = "(1983.4349365234,17.5,1183.5950927734)", partypvp = "true", team = "STAFF", yl_church = "return {[\"last_heal\"] = 1683837139, [\"last_death\"] = {[\"x\"] = 2251, [\"y\"] = -164, [\"z\"] = 1401}, [\"last_death_portal\"] = 1683839371}", yl_commons_player_joined = "1702954728", ["petz:werewolf"] = "0", ["petz:lycanthropy"] = "0", lagometer = "1", ["signslib:pos"] = "(1993,17,990)", ["ethereal:fly_timer"] = "-99", yl_audio_state = "off", ["3d_armor_inventory"] = "return {\"\", \"\", \"\", \"\", \"\", \"\"}", ["hud_manager:spawnit:hud_enabled"] = "y", ["petz:old_override_table"] = "return {[\"speed\"] = 1, [\"new_move\"] = true, [\"sneak_glitch\"] = false, [\"gravity\"] = 1, [\"jump\"] = 1, [\"sneak\"] = true}", ["arena_lib_editor.players_number"] = "0", ["stamina:poisoned"] = "no", punch_count = "65132", ["petz:werewolf_clan_idx"] = "4", szutil_watch = "return {}", ["arena_lib_editor.spawner_ID"] = "0", repellant = "0", arenalib_watchID = "0", ["arena_lib_editor.team_ID"] = "0", xp = "0", bitten = "0", inflicted_damage = "2991830", ["petz:werewolf_vignette_id"] = "19", arenalib_infobox_arenaID = "0", yl_commons_thankyou = "1397", ["stamina:exhaustion"] = "81.5", ["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 = 6qbNBWbnRtq3zu1J2Im1DkL8PSK8hvpI ``` Profiler save: ``` profile-20231219T122415.json_prettyEE ``` Status: ``` # Server: version: 5.7.0-yl-thx-tmm | game: Minetest Game | uptime: 2d 7h 27min 24s | max lag: 1.51s | clients (14/52): ALCOHOL3, AliasAlreadyTaken, Bailiff, Boris, Chache, Davidsoft, daydream, Ecklair, Heron, Murmel, nazthelizard122, Nomtom, Service, Silph ``` Teleport command: ``` /teleport xyz 2043 16 1227 ``` Compass command: ``` /give_compass Construction 6qbNBWbnRtq3zu1J2Im1DkL8PSK8hvpI D2691E 2043 16 1227 ```
AliasAlreadyTaken was assigned by yourland-report 2023-12-19 12:24:15 +00:00
AliasAlreadyTaken added the
1. kind/bug
label 2023-12-19 12:30:11 +00:00
flux added this to the flux's TODO list project 2023-12-19 20:58:16 +00:00
AliasAlreadyTaken was unassigned by flux 2023-12-19 20:58:22 +00:00
flux self-assigned this 2023-12-19 20:58:22 +00:00
flux added the
3. source/mod upstream
label 2023-12-19 20:58:30 +00:00
flux added the
4. step/help wanted
label 2023-12-19 21:08:41 +00:00
Member

it's working fine for me locally:

2023-12-19 13:08:00: ACTION[Server]: [instrument_mod] in 1017028us,
2023-12-19 13:08:00: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 42 us
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] in 1010959us,
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).intersects was called 1 times, used 20 us
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).is_a was called 1 times, used 2 us
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).iterate was called 1 times, used 4 us
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).size was called 2 times, used 2 us
2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 50 us
2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] in 1032512us,
2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] getmetatable(spawnit._callback_queue).size was called 2 times, used 1 us
2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 8 times, used 110 us
2023-12-19 13:08:02: ACTION[Server]: [yl_commons] lua is using 205.1 MB
2023-12-19 13:08:03: ACTION[Server]: [instrument_mod] in 1002857us,
2023-12-19 13:08:03: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 68 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] in 1015362us,
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).contains was called 1 times, used 2 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).intersects was called 1 times, used 20 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).is_a was called 1 times, used 1 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).iterate was called 1 times, used 1 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).size was called 2 times, used 3 us
2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 56 us
it's working fine for me locally: ``` 2023-12-19 13:08:00: ACTION[Server]: [instrument_mod] in 1017028us, 2023-12-19 13:08:00: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 42 us 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] in 1010959us, 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).intersects was called 1 times, used 20 us 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).is_a was called 1 times, used 2 us 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).iterate was called 1 times, used 4 us 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).size was called 2 times, used 2 us 2023-12-19 13:08:01: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 50 us 2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] in 1032512us, 2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] getmetatable(spawnit._callback_queue).size was called 2 times, used 1 us 2023-12-19 13:08:02: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 8 times, used 110 us 2023-12-19 13:08:02: ACTION[Server]: [yl_commons] lua is using 205.1 MB 2023-12-19 13:08:03: ACTION[Server]: [instrument_mod] in 1002857us, 2023-12-19 13:08:03: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 68 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] in 1015362us, 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).contains was called 1 times, used 2 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).intersects was called 1 times, used 20 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).is_a was called 1 times, used 1 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).iterate was called 1 times, used 1 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] getmetatable(spawnit._relevant_mobs).size was called 2 times, used 3 us 2023-12-19 13:08:04: ACTION[Server]: [instrument_mod] spawnit._get_forceloaded was called 7 times, used 56 us ```
Member

i've discovered that it doesn't work specifically for yl_statuseffects for reasons i don't understand, i'm investigating.

i've discovered that it doesn't work specifically for yl_statuseffects for reasons i don't understand, i'm investigating.
flux added
4. step/at work
and removed
4. step/help wanted
labels 2023-12-19 23:30:25 +00:00
flux added
4. step/question
and removed
4. step/at work
labels 2023-12-19 23:42:35 +00:00
Member

the problem was with structure of the yl_statuseffects, not with anything in debuggery. possibly this can be closed. see comments in #5747

the problem was with structure of the yl_statuseffects, not with anything in debuggery. possibly this can be closed. see comments in #5747

Let's keep it open for testing, even though the culprit has changed :D

Do we have similar mods that cannot be profiled properly?

Let's keep it open for testing, even though the culprit has changed :D Do we have similar mods that cannot be profiled properly?
AliasAlreadyTaken added
4. step/ready to QA test
and removed
4. step/question
labels 2023-12-20 02:00:23 +00:00
AliasAlreadyTaken added this to the 1.1.123 milestone 2023-12-20 02:00:26 +00:00
Member

Do we have similar mods that cannot be profiled properly?

i need to audit my mods; it follows a pattern i know i've used repeatedly. i'm considering it an antipattern now, but i'm not sure what the best way to fix it is in general. i used that pattern as a marginal performance improvement in some places, and to improve legibility in others.

> Do we have similar mods that cannot be profiled properly? i need to audit my mods; it follows a pattern i know i've used repeatedly. i'm considering it an antipattern now, but i'm not sure what the best way to fix it is in general. i used that pattern as a marginal performance improvement in some places, and to improve legibility in others.

Shall we count this issue OK if it can instrument yl_statuseffects now? Coz a whole audit of your whole mods or even the whole of YL seems out of scope.

What's this antipattern though? Localizing a table?

Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent /instrument_mod yl_statuseffects, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage?

Shall we count this issue OK if it can instrument yl_statuseffects now? Coz a whole audit of your whole mods or even the whole of YL seems out of scope. What's this antipattern though? Localizing a table? Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent `/instrument_mod yl_statuseffects`, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage?
AliasAlreadyTaken added the
ugh/QA NOK
label 2024-01-26 00:34:37 +00:00
Member

Shall we count this issue OK if it can instrument yl_statuseffects now? Coz a whole audit of your whole mods or even the whole of YL seems out of scope.

that seems reasonable. it's going to be a lot of work to fix all the other places where i store local references to functions.

What's this antipattern though? Localizing a table?

yup, local reference to a table of functions, or to the functions themselves

Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent /instrument_mod yl_statuseffects, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage?

hm, i'll look into it

> Shall we count this issue OK if it can instrument yl_statuseffects now? Coz a whole audit of your whole mods or even the whole of YL seems out of scope. that seems reasonable. it's going to be a lot of work to fix all the other places where i store local references to functions. > What's this antipattern though? Localizing a table? yup, local reference to a table of functions, or to the functions themselves > Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent `/instrument_mod yl_statuseffects`, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage? hm, i'll look into it
Member

Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent /instrument_mod yl_statuseffects, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage?

when i do this locally, i get:

<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] in 1095206us,
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.allow_fly was called 4 times, used 241 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_nearby_area_positions was called 4 times, used 1753 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_nearby_positions was called 48 times, used 1380 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_remaining_time was called 12 times, used 96 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.has_builders_flight was called 4 times, used 16 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.has_flight was called 4 times, used 341 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.in_valid_area was called 4 times, used 219 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_hud_enabled was called 4 times, used 16 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_particles_enabled was called 4 times, used 10 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_valid_area was called 56 times, used 62 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.on_ground was called 4 times, used 27 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.set_remaining_time was called 4 times, used 129 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.show_particles was called 4 times, used 2849 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.update_hud was called 4 times, used 84 us
<ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.stun.get_remaining_time was called 1 times, used 5 us
> Btw I still can't get it to be instrumented, but neither can I see any other. Am I doing something wrong? I sent /instrument_mod yl_statuseffects, it told me it would do so now and I can see in the log all the functions that are now meant to be instrumented, but neither the log nor ingame says anything about usage? when i do this locally, i get: ``` <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] in 1095206us, <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.allow_fly was called 4 times, used 241 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_nearby_area_positions was called 4 times, used 1753 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_nearby_positions was called 48 times, used 1380 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.get_remaining_time was called 12 times, used 96 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.has_builders_flight was called 4 times, used 16 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.has_flight was called 4 times, used 341 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.in_valid_area was called 4 times, used 219 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_hud_enabled was called 4 times, used 16 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_particles_enabled was called 4 times, used 10 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.is_valid_area was called 56 times, used 62 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.on_ground was called 4 times, used 27 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.set_remaining_time was called 4 times, used 129 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.show_particles was called 4 times, used 2849 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.builders_flight.update_hud was called 4 times, used 84 us <ACTION> 2024-01-28 13:36:20: [Server] [instrument_mod] yl_statuseffects.stun.get_remaining_time was called 1 times, used 5 us ```

When I do this I get

2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting yl_statuseffects
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.dofile"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.in_valid_area"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_nearby_positions"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.update_hud"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_hud_enabled"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_nearby_area_positions"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.allow_fly"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.enable_flight"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_particles_enabled"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_particles_enabled"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.disable_flight"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_remaining_time"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_remaining_time"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_hud_enabled"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.has_flight"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.has_builders_flight"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.show_particles"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.on_ground"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_valid_area"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.disable_stun"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.enable_stun"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.show_formspec"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.enable_hud"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.disable_hud"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.get_remaining_time"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.set_remaining_time"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.S"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.loadfile"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.apply"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.combine"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.fold"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.on_change"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).add_change"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).value"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).del_change"
2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.log"
2024-01-29 09:35:25: ACTION[Server]: [yl_commons] lua is using 389.0 MB
2024-01-29 09:35:35: ACTION[Server]: [yl_commons] lua is using 452.9 MB
2024-01-29 09:35:45: ACTION[Server]: [yl_commons] lua is using 272.4 MB
2024-01-29 09:35:52: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:35:55: ACTION[Server]: [yl_commons] lua is using 376.9 MB
2024-01-29 09:36:02: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:04: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:04: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:04: ACTION[Server]: [yl_commons] lua is using 246.5 MB
2024-01-29 09:36:07: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:08: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:10: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:11: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:13: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:14: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:14: ACTION[Server]: [yl_commons] lua is using 381.4 MB
2024-01-29 09:36:16: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:17: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:19: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:20: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:22: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris
2024-01-29 09:36:22: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris
2024-01-29 09:36:24: ACTION[Server]: [yl_commons] lua is using 335.1 MB
2024-01-29 09:36:25: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris

Waiiiit.

2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.log"

I can't find that file? Where does it go to?

When I do this I get ``` 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting yl_statuseffects 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.dofile" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.in_valid_area" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_nearby_positions" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.update_hud" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_hud_enabled" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_nearby_area_positions" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.allow_fly" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.enable_flight" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_particles_enabled" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_particles_enabled" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.disable_flight" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.get_remaining_time" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.set_remaining_time" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_hud_enabled" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.has_flight" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.has_builders_flight" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.show_particles" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.on_ground" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.builders_flight.is_valid_area" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.disable_stun" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.enable_stun" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.show_formspec" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.enable_hud" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.disable_hud" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.get_remaining_time" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.stun.set_remaining_time" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.S" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.loadfile" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.apply" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.combine" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.fold" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.interact_monoid.def.on_change" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).add_change" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).value" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "getmetatable(yl_statuseffects.interact_monoid).del_change" 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.log" 2024-01-29 09:35:25: ACTION[Server]: [yl_commons] lua is using 389.0 MB 2024-01-29 09:35:35: ACTION[Server]: [yl_commons] lua is using 452.9 MB 2024-01-29 09:35:45: ACTION[Server]: [yl_commons] lua is using 272.4 MB 2024-01-29 09:35:52: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:35:55: ACTION[Server]: [yl_commons] lua is using 376.9 MB 2024-01-29 09:36:02: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:04: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:04: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:04: ACTION[Server]: [yl_commons] lua is using 246.5 MB 2024-01-29 09:36:07: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:08: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:10: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:11: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:13: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:14: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:14: ACTION[Server]: [yl_commons] lua is using 381.4 MB 2024-01-29 09:36:16: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:17: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:19: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:20: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:22: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris 2024-01-29 09:36:22: ACTION[Server]: [yl_statuseffects] builders' flight disabled for Boris 2024-01-29 09:36:24: ACTION[Server]: [yl_commons] lua is using 335.1 MB 2024-01-29 09:36:25: ACTION[Server]: [yl_statuseffects] builders' flight enabled for Boris ``` Waiiiit. 2024-01-29 09:35:25: ACTION[Server]: [debuggery] instrumenting "yl_statuseffects.log" I can't find that file? Where does it go to?
Member

"yl_statuseffects.log"

that's a function, not a file

When I do this I get

hmmmmmmmmmm you're certain it's the right version of yl_statuseffects installed? i have no other idea.

> "yl_statuseffects.log" that's a function, not a file > When I do this I get hmmmmmmmmmm you're certain it's the right version of yl_statuseffects installed? i have no other idea.

"yl_statuseffects.log"

that's a function, not a file

lolol, I'm an idiot

When I do this I get

hmmmmmmmmmm you're certain it's the right version of yl_statuseffects installed? i have no other idea.

Maybe a setting? Wrong log level?

yl_statuseffects is on this commit: 540ccfcca46e9e362b66cfeaf324891590ca68f9

> > "yl_statuseffects.log" > > that's a function, not a file lolol, I'm an idiot > > When I do this I get > > hmmmmmmmmmm you're certain it's the right version of yl_statuseffects installed? i have no other idea. Maybe a setting? Wrong log level? yl_statuseffects is on this commit: 540ccfcca46e9e362b66cfeaf324891590ca68f9
Member

yl_statuseffects is on this commit: 540ccfcca46e9e362b66cfeaf324891590ca68f9

alright, same here...

Maybe a setting? Wrong log level?

the logs are all at the "action" level, so that can't be it. there's no relevant setting.

does it work if you try to instrument a different mod?

> yl_statuseffects is on this commit: 540ccfcca46e9e362b66cfeaf324891590ca68f9 alright, same here... > Maybe a setting? Wrong log level? the logs are all at the "action" level, so that can't be it. there's no relevant setting. does it work if you try to instrument a different mod?

No. I tried areas, I even tried "minetest". It says it will now go ahead and isntrument all of it, then doesn't. Or at least not reveal to the log what it does.

No. I tried areas, I even tried "minetest". It says it will now go ahead and isntrument all of it, then doesn't. Or at least not reveal to the log what it does.
Member

this is happening on the test server or the main server?

this is happening on the test server or the main server?

This happens on the testserver, with latest updates to the mods involved.

This happens on the testserver, with latest updates to the mods involved.
Member

i've got no real idea why this is failing. i'm probably going to ignore this for a while in favor of trying to fix the major issues with ballistics/y_bows.

i've got no real idea why this is failing. i'm probably going to ignore this for a while in favor of trying to fix the major issues with ballistics/y_bows.

If it works for you, but doesn't for me, then there must be some difference. I'll try to reduce modset and find a workable solution, but it's certainly not high prio atm

If it works for you, but doesn't for me, then there must be some difference. I'll try to reduce modset and find a workable solution, but it's certainly not high prio atm
flux added
4. step/at work
and removed
4. step/ready to QA test
labels 2024-02-04 00:55:28 +00:00

Wellll, if one looks at the right spot, the stuff does get instrumented.

For future reference and especially for smol brain Alias: It's the debug.txt, stupid!

NOT the usual Minetest_live.out log

That's how it looks like:

2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] in 1027442us,
2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.canInteract was called 1 times, used 325 us
2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.getAreasAtPos was called 5 times, used 43 us
2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.getExternalHudEntries was called 2 times, used 3 us
2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.get_banned_players was called 4 times, used 7 us

Wellll, if one looks at the right spot, the stuff does get instrumented. For future reference and especially for smol brain Alias: It's the debug.txt, stupid! NOT the usual Minetest_live.out log That's how it looks like: 2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] in 1027442us, 2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.canInteract was called 1 times, used 325 us 2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.getAreasAtPos was called 5 times, used 43 us 2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.getExternalHudEntries was called 2 times, used 3 us 2024-02-28 23:13:14: INFO[Server]: [debuggery] [instrument_mod] areas.get_banned_players was called 4 times, used 7 us
AliasAlreadyTaken added
ugh/QA OK
and removed
ugh/QA NOK
labels 2024-02-28 23:14:49 +00:00
Member

For future reference and especially for smol brain Alias: It's the debug.txt, stupid!

NOT the usual Minetest_live.out log

instrument_mod from debuggery is just using minetest.log ultimately - i have no idea how or why it's not showing up in the console log.

> For future reference and especially for smol brain Alias: It's the debug.txt, stupid! > > NOT the usual Minetest_live.out log instrument_mod from debuggery is just using `minetest.log` ultimately - i have no idea how or why it's not showing up in the console log.
Member

hm i should at least check if it shows up in my local server console output tho

hm i should at least check if it shows up in my local server console output tho
Member

i can't validate whether this is live on main

i can't validate whether this is live on main
flux added
4. step/ready to QA test
and removed
4. step/at work
labels 2024-04-03 19:39:38 +00:00

I can see it logging to the debug.txt, IMO it should log to where minetest.log writes to as well. Still, it works nicely :)

I can see it logging to the debug.txt, IMO it should log to where minetest.log writes to as well. Still, it works nicely :)
AliasAlreadyTaken added
5. result/fixed
and removed
4. step/ready to QA test
labels 2024-04-20 05:15:03 +00:00
Member

I can see it logging to the debug.txt, IMO it should log to where minetest.log writes to as well. Still, it works nicely :)

i still don't understand why something would log to debug.txt but not the console, outside of logging levels. this message is logged at "action" level - maybe the console is only logging warning or above? i'm pretty sure that's not the case though?

> I can see it logging to the debug.txt, IMO it should log to where minetest.log writes to as well. Still, it works nicely :) i still don't understand why something would log to debug.txt but not the console, outside of logging levels. this message is logged at "action" level - maybe the console is only logging warning or above? i'm pretty sure that's not the case though?
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#5746
No description provided.