SSoverlay improvements and tweaks (#32371)

* Overlay per-type cost logging.

Overlays will now log how long each type took to process.

Changed up how overlays was done to account for the fact its a queue and not a processor. (it was using almost none of the processing subsystem framework)

Made the overlay loop faster by making it not cut the list until the end.

Added a simple generic benchmark stat tracking system.

I don't know how much overhead this adds to overlays. i may put it behind testing or something, but i do want to test this on the serbers to get some stats.

* Removes flush() as it was creating race conditions

* Use ref

* text2file

* Atoms added as an overlay will have their pending overlays compiled before being converted to an appearance

code/__DEFINES/stat_tracking.dm

@@ -0,0 +1,17 @@
+#define STAT_ENTRY_TIME 1
+#define STAT_ENTRY_COUNT 2
+#define STAT_ENTRY_LENGTH 2
+
+
+#define STAT_START_STOPWATCH var/STAT_STOP_WATCH = TICK_USAGE
+#define STAT_STOP_STOPWATCH var/STAT_TIME = TICK_USAGE_TO_MS(STAT_STOP_WATCH)
+#define STAT_LOG_ENTRY(entrylist, entryname) \
+	var/list/STAT_ENTRY = entrylist[entryname] || (entrylist[entryname] = new /list(STAT_ENTRY_LENGTH));\
+	STAT_ENTRY[STAT_ENTRY_TIME] += STAT_TIME;\
+	var/STAT_INCR_AMOUNT = min(1, 2**round((STAT_ENTRY[STAT_ENTRY_COUNT] || 0)/SHORT_REAL_LIMIT));\
+	if (STAT_INCR_AMOUNT == 1 || prob(100/STAT_INCR_AMOUNT)) {\
+		STAT_ENTRY[STAT_ENTRY_COUNT] += STAT_INCR_AMOUNT;\
+	};\
+
+
+

code/__DEFINES/subsystems.dm

@@ -76,3 +76,27 @@
 #define RUNLEVEL_POSTGAME 8
 
 #define RUNLEVELS_DEFAULT (RUNLEVEL_SETUP | RUNLEVEL_GAME | RUNLEVEL_POSTGAME)
+
+
+
+
+#define COMPILE_OVERLAYS(A)\
+	if (TRUE) {\
+		var/list/oo = A.our_overlays;\
+		var/list/po = A.priority_overlays;\
+		if(LAZYLEN(po)){\
+			if(LAZYLEN(oo)){\
+				A.overlays = oo + po;\
+			}\
+			else{\
+				A.overlays = po;\
+			}\
+		}\
+		else if(LAZYLEN(oo)){\
+			A.overlays = oo;\
+		}\
+		else{\
+			A.overlays.Cut();\
+		}\
+		A.flags_1 &= ~OVERLAY_QUEUED_1;\
+	}

code/__HELPERS/cmp.dm

@@ -58,7 +58,12 @@ GLOBAL_VAR_INIT(cmp_field, "name")
 		. = B.failures - A.failures
 	if (!.)
 		. = B.qdels - A.qdels
-    
+
+/proc/cmp_generic_stat_item_time(list/A, list/B)
+	. = B[STAT_ENTRY_TIME] - A[STAT_ENTRY_TIME]
+	if (!.)
+		. = B[STAT_ENTRY_COUNT] - A[STAT_ENTRY_COUNT]
+
 /proc/cmp_profile_avg_time_dsc(list/A, list/B)
 	return (B[PROFILE_ITEM_TIME]/(B[PROFILE_ITEM_COUNT] || 1)) - (A[PROFILE_ITEM_TIME]/(A[PROFILE_ITEM_COUNT] || 1))
 

code/__HELPERS/icons.dm

@@ -1006,23 +1006,26 @@ GLOBAL_LIST_EMPTY(friendly_animal_types)
 		if(J)
 			J.equip(body, TRUE, FALSE)
 
-		SSoverlays.Flush()
 
 		var/icon/out_icon = icon('icons/effects/effects.dmi', "nothing")
 
 		body.setDir(NORTH)
+		COMPILE_OVERLAYS(body)
 		var/icon/partial = getFlatIcon(body)
 		out_icon.Insert(partial,dir=NORTH)
 
 		body.setDir(SOUTH)
+		COMPILE_OVERLAYS(body)
 		partial = getFlatIcon(body)
 		out_icon.Insert(partial,dir=SOUTH)
 
 		body.setDir(WEST)
+		COMPILE_OVERLAYS(body)
 		partial = getFlatIcon(body)
 		out_icon.Insert(partial,dir=WEST)
 
 		body.setDir(EAST)
+		COMPILE_OVERLAYS(body)
 		partial = getFlatIcon(body)
 		out_icon.Insert(partial,dir=EAST)
 

code/__HELPERS/stat_tracking.dm

@@ -0,0 +1,13 @@
+/proc/render_stats(list/stats, user, sort = /proc/cmp_generic_stat_item_time)
+	sortTim(stats, sort, TRUE)
+
+	var/list/lines = list()
+
+	for (var/entry in stats)
+		var/list/data = stats[entry]
+		lines += "[entry] => [num2text(data[STAT_ENTRY_TIME], 10)]ms ([data[STAT_ENTRY_COUNT]]) (avg:[num2text(data[STAT_ENTRY_TIME]/(data[STAT_ENTRY_COUNT] || 1), 99)])"
+
+	if (user)
+		user << browse("<ol><li>[lines.Join("</li><li>")]</li></ol>", "window=[url_encode("stats:[REF(stats)]")]")
+
+	. = lines.Join("\n")

code/controllers/subsystem/overlays.dm

@@ -1,4 +1,4 @@
-PROCESSING_SUBSYSTEM_DEF(overlays)
+SUBSYSTEM_DEF(overlays)
 	name = "Overlay"
 	flags = SS_TICKER
 	wait = 1
@@ -6,62 +6,63 @@ PROCESSING_SUBSYSTEM_DEF(overlays)
 	init_order = INIT_ORDER_OVERLAY
 	runlevels = RUNLEVELS_DEFAULT | RUNLEVEL_SETUP
 
-	stat_tag = "Ov"
-	currentrun = null
+	var/list/queue
+	var/list/stats
 	var/list/overlay_icon_state_caches
 	var/list/overlay_icon_cache
 	var/initialized = FALSE
 
-/datum/controller/subsystem/processing/overlays/PreInit()
-	LAZYINITLIST(overlay_icon_state_caches)
-	LAZYINITLIST(overlay_icon_cache)
+/datum/controller/subsystem/overlays/PreInit()
+	overlay_icon_state_caches = list()
+	overlay_icon_cache = list()
+	queue = list()
+	stats = list()
 
-/datum/controller/subsystem/processing/overlays/Initialize()
+/datum/controller/subsystem/overlays/Initialize()
 	initialized = TRUE
-	Flush()
+	fire(mc_check = FALSE)
 	..()
 
-/datum/controller/subsystem/processing/overlays/Recover()
+
+/datum/controller/subsystem/overlays/stat_entry()
+	..("Ov:[length(queue)]")
+
+
+/datum/controller/subsystem/overlays/Shutdown()
+	text2file("[GLOB.log_directory]/overlay.log", render_stats(stats))
+
+
+/datum/controller/subsystem/overlays/Recover()
 	overlay_icon_state_caches = SSoverlays.overlay_icon_state_caches
 	overlay_icon_cache = SSoverlays.overlay_icon_cache
-	processing = SSoverlays.processing
+	queue = SSoverlays.queue
 
-#define COMPILE_OVERLAYS(A)\
-	var/list/oo = A.our_overlays;\
-	var/list/po = A.priority_overlays;\
-	if(LAZYLEN(po)){\
-		if(LAZYLEN(oo)){\
-			A.overlays = oo + po;\
-		}\
-		else{\
-			A.overlays = po;\
-		}\
-	}\
-	else if(LAZYLEN(oo)){\
-		A.overlays = oo;\
-	}\
-	else{\
-		A.overlays.Cut();\
-	}\
-	A.flags_1 &= ~OVERLAY_QUEUED_1
 
-/datum/controller/subsystem/processing/overlays/fire(resumed = FALSE, mc_check = TRUE)
-	var/list/processing = src.processing
-	while(processing.len)
-		var/atom/thing = processing[processing.len]
-		processing.len--
+/datum/controller/subsystem/overlays/fire(resumed = FALSE, mc_check = TRUE)
+	var/list/queue = src.queue
+	var/static/count = 0
+	if (count)
+		var/c = count
+		count = 0 //so if we runtime on the Cut, we don't try again.
+		queue.Cut(1,c+1)
+
+	for (var/thing in queue)
+		count++
 		if(thing)
-			COMPILE_OVERLAYS(thing)
+			STAT_START_STOPWATCH
+			var/atom/A = thing
+			COMPILE_OVERLAYS(A)
+			STAT_STOP_STOPWATCH
+			STAT_LOG_ENTRY(stats, A.type)
 		if(mc_check)
 			if(MC_TICK_CHECK)
 				break
 		else
 			CHECK_TICK
 
-/datum/controller/subsystem/processing/overlays/proc/Flush()
-	if(processing.len)
-		testing("Flushing [processing.len] overlays")
-		fire(mc_check = FALSE)	//pair this thread up with the MC to get extra compile time
+	if (count)
+		queue.Cut(1,count+1)
+		count = 0
 
 /proc/iconstate2appearance(icon, iconstate)
 	var/static/image/stringbro = new()
@@ -102,6 +103,10 @@ PROCESSING_SUBSYSTEM_DEF(overlays)
 		else if(isicon(overlay))
 			new_overlays += icon2appearance(overlay)
 		else
+			if(isloc(overlay))
+				var/atom/A = overlay
+				if (A.flags_1 & OVERLAY_QUEUED_1)
+					COMPILE_OVERLAYS(A)
 			appearance_bro.appearance = overlay //this works for images and atoms too!
 			if(!ispath(overlay))
 				var/image/I = overlay
@@ -110,7 +115,7 @@ PROCESSING_SUBSYSTEM_DEF(overlays)
 	return new_overlays
 
 #define NOT_QUEUED_ALREADY (!(flags_1 & OVERLAY_QUEUED_1))
-#define QUEUE_FOR_COMPILE flags_1 |= OVERLAY_QUEUED_1; SSoverlays.processing += src;
+#define QUEUE_FOR_COMPILE flags_1 |= OVERLAY_QUEUED_1; SSoverlays.queue += src;
 /atom/proc/cut_overlays(priority = FALSE)
 	var/list/cached_overlays = our_overlays
 	var/list/cached_priority = priority_overlays

code/controllers/subsystem/ticker.dm

@@ -263,8 +263,6 @@ SUBSYSTEM_DEF(ticker)
 	collect_minds()
 	equip_characters()
 
-	SSoverlays.Flush()	//Flush the majority of the shit
-
 	GLOB.data_core.manifest()
 
 	transfer_characters()	//transfer keys to the new mobs

code/game/atoms.dm

@@ -99,7 +99,6 @@
 
 	LAZYCLEARLIST(overlays)
 	LAZYCLEARLIST(priority_overlays)
-	//SSoverlays.processing -= src	//we COULD do this, but it's better to just let it fall out of the processing queue
 
 	QDEL_NULL(light)
 

code/game/world.dm

@@ -123,7 +123,7 @@ GLOBAL_PROTECT(security_mode)
 		if(I in input)
 			handler = topic_handlers[I]
 			break
-	
+
 	if((!handler || initial(handler.log)) && config && CONFIG_GET(flag/log_world_topic))
 		WRITE_FILE(GLOB.world_game_log, "TOPIC: \"[T]\", from:[addr], master:[master], key:[key]")
 

code/modules/admin/admin_verbs.dm

@@ -156,7 +156,8 @@ GLOBAL_LIST_INIT(admin_verbs_debug, world.AVerbsDebug())
 	/client/proc/toggle_medal_disable,
 	/client/proc/view_runtimes,
 	/client/proc/pump_random_event,
-	/client/proc/cmd_display_init_log
+	/client/proc/cmd_display_init_log,
+	/client/proc/cmd_display_overlay_log
 	)
 GLOBAL_PROTECT(admin_verbs_possess)
 GLOBAL_LIST_INIT(admin_verbs_possess, list(/proc/possess, /proc/release))

code/modules/admin/verbs/debug.dm

@@ -796,6 +796,13 @@ GLOBAL_PROTECT(LastAdminCalledProc)
 
 	usr << browse(dellog.Join(), "window=dellog")
 
+/client/proc/cmd_display_overlay_log()
+	set category = "Debug"
+	set name = "Display overlay Log"
+	set desc = "Display SSoverlays log of everything that's passed through it."
+
+	render_stats(SSoverlays.stats, src)
+
 /client/proc/cmd_display_init_log()
 	set category = "Debug"
 	set name = "Display Initialize() Log"

tgstation.dme

@@ -74,6 +74,7 @@
 #include "code\__DEFINES\sight.dm"
 #include "code\__DEFINES\sound.dm"
 #include "code\__DEFINES\stat.dm"
+#include "code\__DEFINES\stat_tracking.dm"
 #include "code\__DEFINES\status_effects.dm"
 #include "code\__DEFINES\subsystems.dm"
 #include "code\__DEFINES\tgui.dm"
@@ -102,6 +103,7 @@
 #include "code\__HELPERS\radio.dm"
 #include "code\__HELPERS\sanitize_values.dm"
 #include "code\__HELPERS\shell.dm"
+#include "code\__HELPERS\stat_tracking.dm"
 #include "code\__HELPERS\text.dm"
 #include "code\__HELPERS\time.dm"
 #include "code\__HELPERS\type2type.dm"
@@ -200,6 +202,7 @@
 #include "code\controllers\subsystem\mobs.dm"
 #include "code\controllers\subsystem\npcpool.dm"
 #include "code\controllers\subsystem\orbit.dm"
+#include "code\controllers\subsystem\overlays.dm"
 #include "code\controllers\subsystem\pai.dm"
 #include "code\controllers\subsystem\parallax.dm"
 #include "code\controllers\subsystem\persistence.dm"
@@ -224,7 +227,6 @@
 #include "code\controllers\subsystem\processing\fields.dm"
 #include "code\controllers\subsystem\processing\flightpacks.dm"
 #include "code\controllers\subsystem\processing\obj.dm"
-#include "code\controllers\subsystem\processing\overlays.dm"
 #include "code\controllers\subsystem\processing\processing.dm"
 #include "code\controllers\subsystem\processing\projectiles.dm"
 #include "code\datums\action.dm"