Find references fix.

Made it go from taking years to hours

Removed Datum based recursion, this was unneeded.

Fixed it calling a proc for what ended up being a costly noop millions of times (this was a moderate speed up as it would call DoSearchVar on every fucking number or string or null in a things vars list.)

Fixed it calling itself on the vars list. luckily it only checked keys, so this didn't stack overflow.

I'm intentionally leaving the debugging stuff in right now so that its on the record somewhere. I'll remove that when I pr line by line profiling as its own separate thing

code/__DEFINES/profiling.dm

@@ -0,0 +1,16 @@
+
+var/list/PROFILE_STORE
+var/PROFILE_TIME
+var/PROFILE_LINE
+var/PROFILE_FILE
+var/PROFILE_SLEEPCHECK
+
+#define PROFILE_START PROFILE_STORE = list();PROFILE_SET
+
+#define PROFILE_SET PROFILE_TIME = TICK_USAGE_REAL; PROFILE_LINE = __LINE__; PROFILE_FILE = __FILE__; PROFILE_SLEEPCHECK = world.time
+
+#define PROFILE_TICK if (PROFILE_SLEEPCHECK == world.time) {var/list/PROFILE_ITEM = PROFILE_STORE["[PROFILE_FILE]:[PROFILE_LINE] - [__FILE__]:[__LINE__]"]; if (!PROFILE_ITEM) {PROFILE_ITEM = list(); PROFILE_STORE["[PROFILE_FILE]:[PROFILE_LINE] - [__FILE__]:[__LINE__]"] = PROFILE_ITEM} PROFILE_ITEM["TIME"] += TICK_USAGE_TO_MS(PROFILE_TIME);PROFILE_ITEM["COUNT"]++;} PROFILE_SET
+
+#define PROFILE_SHOW(USER) sortTim(PROFILE_STORE, /proc/cmp_profile_avg_time_dsc, TRUE);var/list/HTML_PROFILE_LINES = list();for (var/PROFILE_ENTRY in PROFILE_STORE) {HTML_PROFILE_LINES += "[PROFILE_ENTRY] => [num2text(PROFILE_STORE[PROFILE_ENTRY]["TIME"], 10)]ms ([num2text(PROFILE_STORE[PROFILE_ENTRY]["COUNT"], 10)]) (avg:[num2text(PROFILE_STORE[PROFILE_ENTRY]["TIME"]/(PROFILE_STORE[PROFILE_ENTRY]["COUNT"] || 1), 99)]"};USER << browse("<ol><li>[HTML_PROFILE_LINES.Join("</li><li>")]</li></ol>", "window=url_encode(PROFILE_L[__FILE__]:[__LINE__])")
+
+

code/__HELPERS/cmp.dm

@@ -58,3 +58,6 @@ GLOBAL_VAR_INIT(cmp_field, "name")
 		. = B.failures - A.failures
 	if (!.)
 		. = B.qdels - A.qdels
+
+/proc/cmp_profile_avg_time_dsc(list/A, list/B)
+	return (B["TIME"]/(B["COUNT"] || 1)) - (A["TIME"]/(A["COUNT"] || 1))

code/_compile_options.dm

@@ -1,12 +1,17 @@
 #define DEBUG					//Enables byond profiling and full runtime logs - note, this may also be defined in your .dme file
 								//Enables in-depth debug messages to runtime log (used for debugging)
-//#define TESTING				//By using the testing("message") proc you can create debug-feedback for people with this
+#define TESTING				//By using the testing("message") proc you can create debug-feedback for people with this
 								//uncommented, but not visible in the release version)
 
 #ifdef TESTING
-//#define GC_FAILURE_HARD_LOOKUP	//makes paths that fail to GC call find_references before del'ing.
-									//Also allows for recursive reference searching of datums.
-									//Sets world.loop_checks to false and prevents find references from sleeping
+#define GC_FAILURE_HARD_LOOKUP	//makes paths that fail to GC call find_references before del'ing.
+								//implies FIND_REF_NO_CHECK_TICK
+
+#define FIND_REF_NO_CHECK_TICK	//Sets world.loop_checks to false and prevents find references from sleeping
+
+#ifdef GC_FAILURE_HARD_LOOKUP
+#define FIND_REF_NO_CHECK_TICK
+#endif
 
 //#define VISUALIZE_ACTIVE_TURFS	//Highlights atmos active turfs in green
 #endif

code/controllers/subsystem/garbage.dm

@@ -159,9 +159,12 @@ SUBSYSTEM_DEF(garbage)
 		fail_counts[level]++
 		switch (level)
 			if (GC_QUEUE_CHECK)
+
+			/*
 				#ifdef GC_FAILURE_HARD_LOOKUP
 				D.find_references()
 				#endif
+			*/
 				var/type = D.type
 				var/datum/qdel_item/I = items[type]
 				testing("GC: -- \ref[D] | [type] was unable to be GC'd --")
@@ -361,10 +364,37 @@ SUBSYSTEM_DEF(garbage)
 		usr.client.running_find_references = type
 
 	testing("Beginning search for references to a [type].")
+	PROFILE_START
 	last_find_references = world.time
+	PROFILE_TICK
 	DoSearchVar(GLOB)
-	for(var/datum/thing in world)
-		DoSearchVar(thing, "WorldRef: [thing]")
+	PROFILE_TICK
+	var/starting_time_of_day = REALTIMEOFDAY
+	for(var/datum/thing in world) //atoms (don't beleive it's lies)
+		PROFILE_TICK
+		DoSearchVar(thing, "World -> [thing]")
+		if (starting_time_of_day + 6000 < REALTIMEOFDAY)
+			PROFILE_SHOW(usr)
+			return
+		PROFILE_TICK
+	PROFILE_TICK
+	for (var/datum/thing) //datums
+		PROFILE_TICK
+		DoSearchVar(thing, "World -> [thing]")
+		if (starting_time_of_day + 6000 < REALTIMEOFDAY)
+			PROFILE_SHOW(usr)
+			return
+		PROFILE_TICK
+	PROFILE_TICK
+	for (var/client/thing) //clients
+		PROFILE_TICK
+		DoSearchVar(thing, "World -> [thing]")
+		if (starting_time_of_day + 6000 < REALTIMEOFDAY)
+			PROFILE_SHOW(usr)
+			return
+		PROFILE_TICK
+	PROFILE_TICK
+
 	testing("Completed search for references to a [type].")
 	if(usr && usr.client)
 		usr.client.running_find_references = null
@@ -384,35 +414,66 @@ SUBSYSTEM_DEF(garbage)
 	if(!running_find_references)
 		find_references(TRUE)
 
-/datum/proc/DoSearchVar(X, Xname)
+/datum/proc/DoSearchVar(X, Xname, recursive_limit = 64)
+	PROFILE_TICK
 	if(usr && usr.client && !usr.client.running_find_references)
 		return
+	PROFILE_TICK
+	if (!recursive_limit)
+		return
+	PROFILE_TICK
 	if(istype(X, /datum))
+		PROFILE_TICK
 		var/datum/D = X
+		PROFILE_TICK
 		if(D.last_find_references == last_find_references)
+			PROFILE_TICK
 			return
+		PROFILE_TICK
 		D.last_find_references = last_find_references
-		for(var/V in D.vars)
-			for(var/varname in D.vars)
-				var/variable = D.vars[varname]
-				if(variable == src)
-					testing("Found [src.type] \ref[src] in [D.type]'s [varname] var. [Xname]")
-				else if(islist(variable))
-					if(src in variable)
-						testing("Found [src.type] \ref[src] in [D.type]'s [varname] list var. Global: [Xname]")
-#ifdef GC_FAILURE_HARD_LOOKUP
-					for(var/I in variable)
-						DoSearchVar(I, TRUE)
-				else
-					DoSearchVar(variable, "[Xname]: [varname]")
-#endif
+		PROFILE_TICK
+		var/list/L = D.vars
+		PROFILE_TICK
+		var/list/varslist = L.Copy()
+		PROFILE_TICK
+		for(var/varname in varslist)
+			PROFILE_TICK
+			if (varname == "vars")
+				continue
+			PROFILE_TICK
+			var/variable
+			PROFILE_TICK
+			variable = varslist[varname]
+			PROFILE_TICK
+			if(variable == src)
+				PROFILE_TICK
+				testing("Found [src.type] \ref[src] in [D.type]'s [varname] var. [Xname]")
+				PROFILE_TICK
+			else if(islist(variable))
+				PROFILE_TICK
+				DoSearchVar(variable, "[Xname] -> list", recursive_limit-1)
+				PROFILE_TICK
+			PROFILE_TICK
 	else if(islist(X))
-		if(src in X)
-			testing("Found [src.type] \ref[src] in list [Xname].")
-#ifdef GC_FAILURE_HARD_LOOKUP
+		PROFILE_TICK
+		var/normal = IS_NORMAL_LIST(X)
+		PROFILE_TICK
 		for(var/I in X)
-			DoSearchVar(I, Xname + ": list")
-#else
+			PROFILE_TICK
+			if (I == src)
+				PROFILE_TICK
+				testing("Found [src.type] \ref[src] in list [Xname].")
+				PROFILE_TICK
+			else if (I && !isnum(I) && normal && X[I] == src)
+				PROFILE_TICK
+				testing("Found [src.type] \ref[src] in list [Xname]\[[I]\]")
+				PROFILE_TICK
+			else if (islist(I))
+				PROFILE_TICK
+				DoSearchVar(I, "[Xname] -> list", recursive_limit-1)
+				PROFILE_TICK
+			PROFILE_TICK
+#ifndef FIND_REF_NO_CHECK_TICK
 	CHECK_TICK
 #endif
 

tgstation.dme

@@ -60,6 +60,7 @@
 #include "code\__DEFINES\pinpointers.dm"
 #include "code\__DEFINES\pipe_construction.dm"
 #include "code\__DEFINES\preferences.dm"
+#include "code\__DEFINES\profiling.dm"
 #include "code\__DEFINES\qdel.dm"
 #include "code\__DEFINES\radiation.dm"
 #include "code\__DEFINES\radio.dm"