Deep sendmaps profiling (tgstation#59581)

* Adds in support for basic send maps profiling, I'd still like to get something that tracks with the round a bit
better, but we can worry about that later

* Adds a debug verb that displays the sendmaps profiling page, as basic as it is

* Define respect

* Patches over an error where profiles would persist through rounds, somehow. Adds the maptick stuff to performance logging, so we can look at how things change over a short period of time

Author: LemonInTheDark

code/__DEFINES/_profile.dm

@@ -1,4 +1,4 @@
 #if DM_BUILD >= 1506
 // We don't actually care about storing the output here, this is just an easy way to ensure the profile runs first.
-GLOBAL_REAL_VAR(world_init_profiler) = world.Profile(PROFILE_START)
+GLOBAL_REAL_VAR(world_init_profiler) = world.Profile(PROFILE_RESTART)
 #endif

code/_compile_options.dm

@@ -61,6 +61,10 @@
 #if DM_VERSION < 514 && DM_BUILD < 1540
 #define USE_EXTOOLS
 #endif
+//Log the full sendmaps profile on 514.1556+, any earlier and we get bugs or it not existing
+#if DM_VERSION >= 514 && DM_BUILD >= 1556
+#define SENDMAPS_PROFILE
+#endif
 
 //Additional code for the above flags.
 #ifdef TESTING

code/controllers/subsystem/profiler.dm

@@ -1,5 +1,10 @@
 #define PROFILER_FILENAME "profiler.json"
 
+#ifdef SENDMAPS_PROFILE
+#define SENDMAPS_FILENAME "sendmaps.json"
+GLOBAL_REAL_VAR(world_init_maptick_profiler) = world.Profile(PROFILE_RESTART, type = "sendmaps")
+#endif
+
 SUBSYSTEM_DEF(profiler)
 	name = "Profiler"
 	init_order = INIT_ORDER_PROFILER
@@ -27,6 +32,9 @@ SUBSYSTEM_DEF(profiler)
 /datum/controller/subsystem/profiler/Shutdown()
 	if(CONFIG_GET(flag/auto_profile))
 		DumpFile()
+#ifdef SENDMAPS_PROFILE
+		world.Profile(PROFILE_CLEAR, type = "sendmaps")
+#endif
 	return ..()
 
 /datum/controller/subsystem/profiler/proc/StartProfiling()
@@ -35,11 +43,18 @@ SUBSYSTEM_DEF(profiler)
 	CONFIG_SET(flag/auto_profile, FALSE)
 #else
 	world.Profile(PROFILE_START)
+#ifdef SENDMAPS_PROFILE
+	world.Profile(PROFILE_START, type = "sendmaps")
+#endif
+
 #endif
 
 /datum/controller/subsystem/profiler/proc/StopProfiling()
 #if DM_BUILD >= 1506
 	world.Profile(PROFILE_STOP)
+#ifdef SENDMAPS_PROFILE
+	world.Profile(PROFILE_STOP, type = "sendmaps")
+#endif
 #endif
 
 /datum/controller/subsystem/profiler/proc/DumpFile()
@@ -48,15 +63,30 @@ SUBSYSTEM_DEF(profiler)
 	CONFIG_SET(flag/auto_profile, FALSE)
 #else
 	var/timer = TICK_USAGE_REAL
-	var/current_profile_data = world.Profile(PROFILE_REFRESH,format="json")
+	var/current_profile_data = world.Profile(PROFILE_REFRESH, format = "json")
+#ifdef SENDMAPS_PROFILE
+	var/current_sendmaps_data = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json")
+#endif
 	fetch_cost = MC_AVERAGE(fetch_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
 	CHECK_TICK
+
 	if(!length(current_profile_data)) //Would be nice to have explicit proc to check this
 		stack_trace("Warning, profiling stopped manually before dump.")
-	var/json_file = file("[GLOB.log_directory]/[PROFILER_FILENAME]")
-	if(fexists(json_file))
-		fdel(json_file)
+	var/prof_file = file("[GLOB.log_directory]/[PROFILER_FILENAME]")
+	if(fexists(prof_file))
+		fdel(prof_file)
+#ifdef SENDMAPS_PROFILE
+	if(!length(current_sendmaps_data)) //Would be nice to have explicit proc to check this
+		stack_trace("Warning, sendmaps profiling stopped manually before dump.")
+	var/sendmaps_file = file("[GLOB.log_directory]/[SENDMAPS_FILENAME]")
+	if(fexists(sendmaps_file))
+		fdel(sendmaps_file)
+#endif
+
 	timer = TICK_USAGE_REAL
-	WRITE_FILE(json_file, current_profile_data)
+	WRITE_FILE(prof_file, current_profile_data)
+#ifdef SENDMAPS_PROFILE
+	WRITE_FILE(sendmaps_file, current_sendmaps_data)
+#endif
 	write_cost = MC_AVERAGE(write_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
 #endif

code/controllers/subsystem/time_track.dm

@@ -15,10 +15,45 @@ SUBSYSTEM_DEF(time_track)
 	var/last_tick_realtime = 0
 	var/last_tick_byond_time = 0
 	var/last_tick_tickcount = 0
+#ifdef SENDMAPS_PROFILE
+	var/list/sendmaps_names_map = list(
+		"SendMaps" = "send_maps",
+		"SendMaps: Initial housekeeping" = "initial_house",
+		"SendMaps: Cleanup" = "cleanup",
+		"SendMaps: Client loop" = "client_loop",
+		"SendMaps: Per client" = "per_client",
+		"SendMaps: Per client: Deleted images" = "deleted_images",
+		"SendMaps: Per client: HUD update" = "hud_update",
+		"SendMaps: Per client: Statpanel update" = "statpanel_update",
+		"SendMaps: Per client: Map data" = "map_data",
+		"SendMaps: Per client: Map data: Check eye position" = "check_eye_pos",
+		"SendMaps: Per client: Map data: Update chunks" = "update_chunks",
+		"SendMaps: Per client: Map data: Send turfmap updates" = "turfmap_updates",
+		"SendMaps: Per client: Map data: Send changed turfs" = "changed_turfs",
+		"SendMaps: Per client: Map data: Send turf chunk info" = "turf_chunk_info",
+		"SendMaps: Per client: Map data: Send obj changes" = "obj_changes",
+		"SendMaps: Per client: Map data: Send mob changes" = "mob_changes",
+		"SendMaps: Per client: Map data: Send notable turf visual contents" = "send_turf_vis_conts",
+		"SendMaps: Per client: Map data: Send pending animations" = "pending_animations",
+		"SendMaps: Per client: Map data: Look for movable changes" = "look_for_movable_changes",
+		"SendMaps: Per client: Map data: Look for movable changes: Check notable turf visual contents" = "check_turf_vis_conts",
+		"SendMaps: Per client: Map data: Look for movable changes: Check HUD/image visual contents" = "check_hud/image_vis_contents",
+		"SendMaps: Per client: Map data: Look for movable changes: Loop through turfs in range" = "turfs_in_range",
+		"SendMaps: Per client: Map data: Look for movable changes: Movables examined" = "movables_examined",
+	)
+#endif
 
 /datum/controller/subsystem/time_track/Initialize(start_timeofday)
 	. = ..()
 	GLOB.perf_log = "[GLOB.log_directory]/perf-[GLOB.round_id ? GLOB.round_id : "NULL"]-[SSmapping.config?.map_name].csv"
+#ifdef SENDMAPS_PROFILE
+	world.Profile(PROFILE_RESTART, type = "sendmaps")
+	//Need to do the sendmaps stuff in its own file, since it works different then everything else
+	var/list/sendmaps_shorthands = list()
+	for(var/proper_name in sendmaps_names_map)
+		sendmaps_shorthands += sendmaps_names_map[proper_name]
+		sendmaps_shorthands += "[sendmaps_names_map[proper_name]]_count"
+#endif
 	log_perf(
 		list(
 			"time",
@@ -42,7 +77,11 @@ SUBSYSTEM_DEF(time_track)
 			"air_network_count",
 			"air_delta_count",
 			"air_superconductive_count"
+#ifdef SENDMAPS_PROFILE
+		) + sendmaps_shorthands
+#else
 		)
+#endif
 	)
 
 /datum/controller/subsystem/time_track/fire()
@@ -65,6 +104,21 @@ SUBSYSTEM_DEF(time_track)
 	last_tick_realtime = current_realtime
 	last_tick_byond_time = current_byondtime
 	last_tick_tickcount = current_tickcount
+
+#ifdef SENDMAPS_PROFILE
+	var/sendmaps_json = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json")
+	var/list/send_maps_data = json_decode(sendmaps_json)
+	var/send_maps_sort = send_maps_data.Copy() //Doing it like this guarentees us a properly sorted list
+
+	for(var/list/packet in send_maps_data)
+		send_maps_sort[packet["name"]] = packet
+
+	var/list/send_maps_values = list()
+	for(var/list/packet in send_maps_sort)
+		send_maps_values += packet["value"]
+		send_maps_values += packet["calls"]
+#endif
+
 	SSblackbox.record_feedback("associative", "time_dilation_current", 1, list("[SQLtime()]" = list("current" = "[time_dilation_current]", "avg_fast" = "[time_dilation_avg_fast]", "avg" = "[time_dilation_avg]", "avg_slow" = "[time_dilation_avg_slow]")))
 	log_perf(
 		list(
@@ -89,5 +143,21 @@ SUBSYSTEM_DEF(time_track)
 			length(SSair.networks),
 			length(SSair.high_pressure_delta),
 			length(SSair.active_super_conductivity)
+#ifdef SENDMAPS_PROFILE
+		) + send_maps_values
+#else
 		)
+#endif
 	)
+
+#ifdef SENDMAPS_PROFILE
+/datum/controller/subsystem/time_track/proc/scream_maptick_data()
+	var/current_profile_data = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json")
+	log_world(current_profile_data)
+	current_profile_data = json_decode(current_profile_data)
+	var/output = ""
+	for(var/list/entry in current_profile_data)
+		output += "[entry["name"]],[entry["value"]],[entry["calls"]]\n"
+	log_world(output)
+	return output
+#endif

code/modules/admin/admin_verbs.dm

@@ -183,6 +183,9 @@ GLOBAL_PROTECT(admin_verbs_debug)
 	/client/proc/export_dynamic_json,
 	/client/proc/run_dynamic_simulations,
 	#endif
+	#ifdef SENDMAPS_PROFILE
+	/client/proc/display_sendmaps,
+	#endif
 	/datum/admins/proc/create_or_modify_area,
 	/client/proc/check_timer_sources,
 	/client/proc/toggle_cdn,
@@ -810,3 +813,11 @@ GLOBAL_PROTECT(admin_verbs_hideable)
 
 	var/datum/admins/admin = GLOB.admin_datums[ckey]
 	admin?.associate(src)
+
+#ifdef SENDMAPS_PROFILE
+/client/proc/display_sendmaps()
+	set name = "Send Maps Profile"
+	set category = "Debug"
+
+	src << link("?debug=profile&type=sendmaps&window=test")
+#endif