Merge pull request #4463 from VOREStation/bay-tg-mc-update

Port /tg Master Controller & Garbage Collection Enhancements

code/__defines/MC.dm

@@ -1,10 +1,10 @@
-#define MC_TICK_CHECK ( ( world.tick_usage > Master.current_ticklimit || src.state != SS_RUNNING ) ? pause() : 0 )
+#define MC_TICK_CHECK ( ( TICK_USAGE > Master.current_ticklimit || src.state != SS_RUNNING ) ? pause() : 0 )
 
 // Used for splitting up your remaining time into phases, if you want to evenly divide it.
 #define MC_SPLIT_TICK_INIT(phase_count) var/original_tick_limit = Master.current_ticklimit; var/split_tick_phases = ##phase_count
 #define MC_SPLIT_TICK \
     if(split_tick_phases > 1){\
-        Master.current_ticklimit = ((original_tick_limit - world.tick_usage) / split_tick_phases) + world.tick_usage;\
+        Master.current_ticklimit = ((original_tick_limit - TICK_USAGE) / split_tick_phases) + TICK_USAGE;\
         --split_tick_phases;\
     } else {\
         Master.current_ticklimit = original_tick_limit;\

code/__defines/_tick.dm

@@ -1,7 +1,9 @@
 #define TICK_LIMIT_RUNNING 80
-#define TICK_LIMIT_TO_RUN 78
+#define TICK_LIMIT_TO_RUN 70
 #define TICK_LIMIT_MC 70
 #define TICK_LIMIT_MC_INIT_DEFAULT 98
 
-#define TICK_CHECK ( world.tick_usage > Master.current_ticklimit )
+#define TICK_CHECK ( TICK_USAGE > Master.current_ticklimit )
 #define CHECK_TICK if TICK_CHECK stoplag()
+
+#define TICK_USAGE world.tick_usage

code/__defines/math.dm

@@ -2,9 +2,13 @@
 //percent_of_tick_used * (ticklag * 100(to convert to ms)) / 100(percent ratio)
 //collapsed to percent_of_tick_used * tick_lag
 #define TICK_DELTA_TO_MS(percent_of_tick_used) ((percent_of_tick_used) * world.tick_lag)
-#define TICK_USAGE_TO_MS(starting_tickusage) (TICK_DELTA_TO_MS(world.tick_usage-starting_tickusage))
+#define TICK_USAGE_TO_MS(starting_tickusage) (TICK_DELTA_TO_MS(TICK_USAGE-starting_tickusage))
 
 //time of day but automatically adjusts to the server going into the next day within the same round.
 //for when you need a reliable time number that doesn't depend on byond time.
 #define REALTIMEOFDAY (world.timeofday + (MIDNIGHT_ROLLOVER * MIDNIGHT_ROLLOVER_CHECK))
 #define MIDNIGHT_ROLLOVER_CHECK ( rollovercheck_last_timeofday != world.timeofday ? update_midnight_rollover() : midnight_rollovers )
+
+#define CEILING(x, y) ( -round(-(x) / (y)) * (y) )
+// round() acts like floor(x, 1) by default but can't handle other values
+#define FLOOR(x, y) ( round((x) / (y)) * (y) )

code/__defines/process_scheduler.dm

@@ -15,4 +15,4 @@
 #define PROCESS_DEFAULT_DEFER_USAGE       90  // 90% of a tick
 
 // Sleep check macro
-#define SCHECK if(world.tick_usage >= next_sleep_usage) defer()
+#define SCHECK if(TICK_USAGE >= next_sleep_usage) defer()

code/__defines/qdel.dm

@@ -9,6 +9,11 @@
 								  //if TESTING is enabled, qdel will call this object's find_references() verb.
 //defines for the gc_destroyed var
 
+#define GC_QUEUE_PREQUEUE 1
+#define GC_QUEUE_CHECK 2
+#define GC_QUEUE_HARDDELETE 3
+#define GC_QUEUE_COUNT 3 //increase this when adding more steps.
+
 #define GC_QUEUED_FOR_QUEUING       -1
 #define GC_QUEUED_FOR_HARD_DEL      -2
 #define GC_CURRENTLY_BEING_QDELETED -3

code/_helpers/mobs.dm

@@ -182,7 +182,7 @@ Proc for attack log creation, because really why not
 	var/starttime = world.time
 	. = 1
 	while (world.time < endtime)
-		sleep(1)
+		stoplag(1)
 		if (progress)
 			progbar.update(world.time - starttime)
 		if(!user || !target)
@@ -229,7 +229,7 @@ Proc for attack log creation, because really why not
 	var/starttime = world.time
 	. = 1
 	while (world.time < endtime)
-		sleep(1)
+		stoplag(1)
 		if (progress)
 			progbar.update(world.time - starttime)
 

code/_helpers/sorts/comparators.dm

@@ -13,8 +13,18 @@
 
 // Sorts subsystems by init_order
 /proc/cmp_subsystem_init(datum/controller/subsystem/a, datum/controller/subsystem/b)
-	return b.init_order - a.init_order
+	return initial(b.init_order) - initial(a.init_order)	//uses initial() so it can be used on types
 
 // Sorts subsystems by priority
 /proc/cmp_subsystem_priority(datum/controller/subsystem/a, datum/controller/subsystem/b)
 	return a.priority - b.priority
+
+// Sorts qdel statistics recorsd by time and count
+/proc/cmp_qdel_item_time(datum/qdel_item/A, datum/qdel_item/B)
+	. = B.hard_delete_time - A.hard_delete_time
+	if (!.)
+		. = B.destroy_time - A.destroy_time
+	if (!.)
+		. = B.failures - A.failures
+	if (!.)
+		. = B.qdels - A.qdels

code/_helpers/time.dm

@@ -11,7 +11,13 @@
 #define DAYS *864000
 
 #define TimeOfGame (get_game_time())
-#define TimeOfTick (world.tick_usage*0.01*world.tick_lag)
+#define TimeOfTick (TICK_USAGE*0.01*world.tick_lag)
+
+#define TICK *world.tick_lag
+#define TICKS *world.tick_lag
+
+#define DS2TICKS(DS) (DS/world.tick_lag)	// Convert deciseconds to ticks
+#define TICKS2DS(T) (T TICKS) 				// Convert ticks to deciseconds
 
 /proc/get_game_time()
 	var/global/time_offset = 0
@@ -19,7 +25,7 @@
 	var/global/last_usage = 0
 
 	var/wtime = world.time
-	var/wusage = world.tick_usage * 0.01
+	var/wusage = TICK_USAGE * 0.01
 
 	if(last_time < wtime && last_usage > 1)
 		time_offset += last_usage - 1
@@ -111,13 +117,21 @@ var/round_start_time = 0
 
 //Increases delay as the server gets more overloaded,
 //as sleeps aren't cheap and sleeping only to wake up and sleep again is wasteful
-#define DELTA_CALC max(((max(world.tick_usage, world.cpu) / 100) * max(Master.sleep_delta,1)), 1)
+#define DELTA_CALC max(((max(TICK_USAGE, world.cpu) / 100) * max(Master.sleep_delta-1,1)), 1)
 
-/proc/stoplag()
+//returns the number of ticks slept
+/proc/stoplag(initial_delay)
+	if (!Master || !(Master.current_runlevel & RUNLEVELS_DEFAULT))
+		sleep(world.tick_lag)
+		return 1
+	if (!initial_delay)
+		initial_delay = world.tick_lag
 	. = 0
-	var/i = 1
+	var/i = DS2TICKS(initial_delay)
 	do
-		. += round(i*DELTA_CALC)
+		. += CEILING(i*DELTA_CALC, 1)
 		sleep(i*world.tick_lag*DELTA_CALC)
 		i *= 2
-	while (world.tick_usage > min(TICK_LIMIT_TO_RUN, Master.current_ticklimit))
+	while (TICK_USAGE > min(TICK_LIMIT_TO_RUN, Master.current_ticklimit))
+
+#undef DELTA_CALC

code/controllers/ProcessScheduler/core/process.dm

@@ -124,7 +124,7 @@
 	cpu_defer_count = 0
 
 	// Prepare usage tracking (defer() updates these)
-	tick_usage_start = world.tick_usage
+	tick_usage_start = TICK_USAGE
 	tick_usage_accumulated = 0
 
 	running()
@@ -142,7 +142,7 @@
 
 /datum/controller/process/proc/recordRunTime()
 	// Convert from tick usage (100/tick) to seconds of CPU time used
-	var/total_usage = (tick_usage_accumulated + (world.tick_usage - tick_usage_start)) / 1000 * world.tick_lag
+	var/total_usage = (tick_usage_accumulated + (TICK_USAGE - tick_usage_start)) / 1000 * world.tick_lag
 
 	last_run_time = total_usage
 	if(total_usage > highest_run_time)
@@ -222,14 +222,14 @@
 		handleHung()
 		CRASH("Process [name] hung and was restarted.")
 
-	tick_usage_accumulated += (world.tick_usage - tick_usage_start)
-	if(world.tick_usage < defer_usage)
+	tick_usage_accumulated += (TICK_USAGE - tick_usage_start)
+	if(TICK_USAGE < defer_usage)
 		sleep(0)
 	else
 		sleep(world.tick_lag)
 		cpu_defer_count++
-	tick_usage_start = world.tick_usage
-	next_sleep_usage = min(world.tick_usage + sleep_interval, defer_usage)
+	tick_usage_start = TICK_USAGE
+	next_sleep_usage = min(TICK_USAGE + sleep_interval, defer_usage)
 
 /datum/controller/process/proc/update()
 	// Clear delta

code/controllers/master.dm

@@ -12,7 +12,7 @@ var/datum/controller/master/Master = new()
 	name = "Master"
 
 	// Are we processing (higher values increase the processing delay by n ticks)
-	var/processing = 1
+	var/processing = TRUE
 	// How many times have we ran
 	var/iteration = 0
 
@@ -27,7 +27,7 @@ var/datum/controller/master/Master = new()
 	var/init_time
 	var/tickdrift = 0
 
-	var/sleep_delta
+	var/sleep_delta = 1
 
 	var/make_runtime = 0
 
@@ -54,13 +54,17 @@ var/datum/controller/master/Master = new()
 
 /datum/controller/master/New()
 	// Highlander-style: there can only be one! Kill off the old and replace it with the new.
-	subsystems = list()
+	var/list/_subsystems = list()
+	subsystems = _subsystems
 	if (Master != src)
 		if (istype(Master))
 			Recover()
 			qdel(Master)
 		else
-			init_subtypes(/datum/controller/subsystem, subsystems)
+			var/list/subsytem_types = subtypesof(/datum/controller/subsystem)
+			sortTim(subsytem_types, /proc/cmp_subsystem_init)
+			for(var/I in subsytem_types)
+				_subsystems += new I
 		Master = src
 
 /datum/controller/master/Destroy()
@@ -73,7 +77,9 @@ var/datum/controller/master/Master = new()
 	sortTim(subsystems, /proc/cmp_subsystem_init)
 	reverseRange(subsystems)
 	for(var/datum/controller/subsystem/ss in subsystems)
+		log_world("Shutting down [ss.name] subsystem...")
 		ss.Shutdown()
+	log_world("Shutdown complete")
 
 // Returns 1 if we created a new mc, 0 if we couldn't due to a recent restart,
 //	-1 if we encountered a runtime trying to recreate it
@@ -87,7 +93,7 @@ var/datum/controller/master/Master = new()
 	var/delay = 50 * ++Master.restart_count
 	Master.restart_timeout = world.time + delay
 	Master.restart_clear = world.time + (delay * 2)
-	Master.processing = 0 //stop ticking this one
+	Master.processing = FALSE //stop ticking this one
 	try
 		new/datum/controller/master()
 	catch
@@ -114,7 +120,8 @@ var/datum/controller/master/Master = new()
 	var/FireHim = FALSE
 	if(istype(BadBoy))
 		msg = null
-		switch(++BadBoy.failure_strikes)
+		LAZYINITLIST(BadBoy.failure_strikes)
+		switch(++BadBoy.failure_strikes[BadBoy.type])
 			if(2)
 				msg = "The [BadBoy.name] subsystem was the last to fire for 2 controller restarts. It will be recovered now and disabled if it happens again."
 				FireHim = TRUE
@@ -262,35 +269,45 @@ var/datum/controller/master/Master = new()
 
 	iteration = 1
 	var/error_level = 0
-	var/sleep_delta = 0
+	var/sleep_delta = 1
 	var/list/subsystems_to_check
 	//the actual loop.
+
 	while (1)
 		tickdrift = max(0, MC_AVERAGE_FAST(tickdrift, (((REALTIMEOFDAY - init_timeofday) - (world.time - init_time)) / world.tick_lag)))
+		var/starting_tick_usage = TICK_USAGE
 		if (processing <= 0)
 			current_ticklimit = TICK_LIMIT_RUNNING
 			sleep(10)
 			continue
 
-		//if there are mutiple sleeping procs running before us hogging the cpu, we have to run later
-		//	because sleeps are processed in the order received, so longer sleeps are more likely to run first
-		if (world.tick_usage > TICK_LIMIT_MC)
-			sleep_delta += 2
+		//Anti-tick-contention heuristics:
+		//if there are mutiple sleeping procs running before us hogging the cpu, we have to run later.
+		//	(because sleeps are processed in the order received, longer sleeps are more likely to run first)
+		if (starting_tick_usage > TICK_LIMIT_MC) //if there isn't enough time to bother doing anything this tick, sleep a bit.
+			sleep_delta *= 2
 			current_ticklimit = TICK_LIMIT_RUNNING * 0.5
-			sleep(world.tick_lag * (processing + sleep_delta))
+			sleep(world.tick_lag * (processing * sleep_delta))
 			continue
 
-		sleep_delta = MC_AVERAGE_FAST(sleep_delta, 0)
-		if (last_run + (world.tick_lag * processing) > world.time)
-			sleep_delta += 1
-		if (world.tick_usage > (TICK_LIMIT_MC*0.5))
+		//Byond resumed us late. assume it might have to do the same next tick
+		if (last_run + CEILING(world.tick_lag * (processing * sleep_delta), world.tick_lag) < world.time)
 			sleep_delta += 1
 
+		sleep_delta = MC_AVERAGE_FAST(sleep_delta, 1) //decay sleep_delta
+
+		if (starting_tick_usage > (TICK_LIMIT_MC*0.75)) //we ran 3/4 of the way into the tick
+			sleep_delta += 1
+
+		//debug
 		if (make_runtime)
 			var/datum/controller/subsystem/SS
 			SS.can_fire = 0
+
 		if (!Failsafe || (Failsafe.processing_interval > 0 && (Failsafe.lasttick+(Failsafe.processing_interval*5)) < world.time))
 			new/datum/controller/failsafe() // (re)Start the failsafe.
+
+		//now do the actual stuff
 		if (!queue_head || !(iteration % 3))
 			var/checking_runlevel = current_runlevel
 			if(cached_runlevel != checking_runlevel)
@@ -307,6 +324,7 @@ var/datum/controller/master/Master = new()
 			subsystems_to_check = current_runlevel_subsystems
 		else
 			subsystems_to_check = tickersubsystems
+
 		if (CheckQueue(subsystems_to_check) <= 0)
 			if (!SoftReset(tickersubsystems, runlevel_sorted_subsystems))
 				log_world("MC: SoftReset() failed, crashing")
@@ -337,8 +355,10 @@ var/datum/controller/master/Master = new()
 		iteration++
 		last_run = world.time
 		src.sleep_delta = MC_AVERAGE_FAST(src.sleep_delta, sleep_delta)
-		current_ticklimit = TICK_LIMIT_RUNNING - (TICK_LIMIT_RUNNING * 0.25) //reserve the tail 1/4 of the next tick for the mc.
-		sleep(world.tick_lag * (processing + sleep_delta))
+		current_ticklimit = TICK_LIMIT_RUNNING
+		if (processing * sleep_delta <= world.tick_lag)
+			current_ticklimit -= (TICK_LIMIT_RUNNING * 0.25) //reserve the tail 1/4 of the next tick for the mc if we plan on running next tick
+		sleep(world.tick_lag * (processing * sleep_delta))
 
 
 
@@ -389,13 +409,13 @@ var/datum/controller/master/Master = new()
 
 	//keep running while we have stuff to run and we haven't gone over a tick
 	//	this is so subsystems paused eariler can use tick time that later subsystems never used
-	while (ran && queue_head && world.tick_usage < TICK_LIMIT_MC)
+	while (ran && queue_head && TICK_USAGE < TICK_LIMIT_MC)
 		ran = FALSE
 		bg_calc = FALSE
 		current_tick_budget = queue_priority_count
 		queue_node = queue_head
 		while (queue_node)
-			if (ran && world.tick_usage > TICK_LIMIT_RUNNING)
+			if (ran && TICK_USAGE > TICK_LIMIT_RUNNING)
 				break
 
 			queue_node_flags = queue_node.flags
@@ -407,7 +427,7 @@ var/datum/controller/master/Master = new()
 			//(unless we haven't even ran anything this tick, since its unlikely they will ever be able run
 			//	in those cases, so we just let them run)
 			if (queue_node_flags & SS_NO_TICK_CHECK)
-				if (queue_node.tick_usage > TICK_LIMIT_RUNNING - world.tick_usage && ran_non_ticker)
+				if (queue_node.tick_usage > TICK_LIMIT_RUNNING - TICK_USAGE && ran_non_ticker)
 					queue_node.queued_priority += queue_priority_count * 0.10
 					queue_priority_count -= queue_node_priority
 					queue_priority_count += queue_node.queued_priority
@@ -419,19 +439,19 @@ var/datum/controller/master/Master = new()
 				current_tick_budget = queue_priority_count_bg
 				bg_calc = TRUE
 
-			tick_remaining = TICK_LIMIT_RUNNING - world.tick_usage
+			tick_remaining = TICK_LIMIT_RUNNING - TICK_USAGE
 
 			if (current_tick_budget > 0 && queue_node_priority > 0)
 				tick_precentage = tick_remaining / (current_tick_budget / queue_node_priority)
 			else
 				tick_precentage = tick_remaining
 
-			current_ticklimit = world.tick_usage + tick_precentage
+			current_ticklimit = TICK_USAGE + tick_precentage
 
 			if (!(queue_node_flags & SS_TICKER))
 				ran_non_ticker = TRUE
 			ran = TRUE
-			tick_usage = world.tick_usage
+			tick_usage = TICK_USAGE
 			queue_node_paused = (queue_node.state == SS_PAUSED || queue_node.state == SS_PAUSING)
 			last_type_processed = queue_node
 
@@ -441,7 +461,7 @@ var/datum/controller/master/Master = new()
 			if (state == SS_RUNNING)
 				state = SS_IDLE
 			current_tick_budget -= queue_node_priority
-			tick_usage = world.tick_usage - tick_usage
+			tick_usage = TICK_USAGE - tick_usage
 
 			if (tick_usage < 0)
 				tick_usage = 0

code/controllers/subsystem.dm

@@ -28,11 +28,10 @@
 	var/datum/controller/subsystem/queue_next
 	var/datum/controller/subsystem/queue_prev
 
-	var/static/failure_strikes = 0 //How many times we suspect this subsystem has crashed the MC, 3 strikes and you're out!
+	var/static/list/failure_strikes //How many times we suspect a subsystem type has crashed the MC, 3 strikes and you're out!
 
 //Do not override
-/datum/controller/subsystem/New()
-	return
+///datum/controller/subsystem/New()
 
 // Used to initialize the subsystem BEFORE the map has loaded
 // Called AFTER Recover if that is called
@@ -66,7 +65,7 @@
 	can_fire = 0
 	flags |= SS_NO_FIRE
 	Master.subsystems -= src
-
+	return ..()
 
 //Queue it to run.
 //	(we loop thru a linked list until we get to the end or find the right point)

code/controllers/subsystems/garbage.dm

@@ -4,11 +4,12 @@
 SUBSYSTEM_DEF(garbage)
 	name = "Garbage"
 	priority = 15
-	wait = 5
+	wait = 2 SECONDS
 	flags = SS_POST_FIRE_TIMING|SS_BACKGROUND|SS_NO_INIT
 	runlevels = RUNLEVELS_DEFAULT | RUNLEVEL_LOBBY
 
-	var/collection_timeout = 3000// deciseconds to wait to let running procs finish before we just say fuck it and force del() the object
+	var/list/collection_timeout = list(0, 2 MINUTES, 10 SECONDS)	// deciseconds to wait before moving something up in the queue to the next level
+
 	var/delslasttick = 0		// number of del()'s we've done this tick
 	var/gcedlasttick = 0		// number of things that gc'ed last tick
 	var/totaldels = 0
@@ -17,27 +18,32 @@ SUBSYSTEM_DEF(garbage)
 	var/highest_del_time = 0
 	var/highest_del_tickusage = 0
 
-	var/list/queue = list() 	// list of refID's of things that should be garbage collected
+	var/list/pass_counts
+	var/list/fail_counts
+
+	var/list/items = list()			// Holds our qdel_item statistics datums
+
+	// List of Queues
+	// Each queue is a list of refID's of things that should be garbage collected
 	// refID's are associated with the time at which they time out and need to be manually del()
 	// we do this so we aren't constantly locating them and preventing them from being gc'd
+	var/list/queues
 
-	var/list/tobequeued = list()	//We store the references of things to be added to the queue seperately so we can spread out GC overhead over a few ticks
 
-	var/list/didntgc = list()	// list of all types that have failed to GC associated with the number of times that's happened.
-								// the types are stored as strings
-	var/list/sleptDestroy = list()	//Same as above but these are paths that slept during their Destroy call
-
-	var/list/noqdelhint = list()// list of all types that do not return a QDEL_HINT
-	// all types that did not respect qdel(A, force=TRUE) and returned one
-	// of the immortality qdel hints
-	var/list/noforcerespect = list()
-
-#ifdef TESTING
-	var/list/qdel_list = list()	// list of all types that have been qdel()eted
-#endif
+/datum/controller/subsystem/garbage/PreInit()
+	queues = new(GC_QUEUE_COUNT)
+	pass_counts = new(GC_QUEUE_COUNT)
+	fail_counts = new(GC_QUEUE_COUNT)
+	for(var/i in 1 to GC_QUEUE_COUNT)
+		queues[i] = list()
+		pass_counts[i] = 0
+		fail_counts[i] = 0
 
 /datum/controller/subsystem/garbage/stat_entry(msg)
-	msg += "Q:[queue.len]|D:[delslasttick]|G:[gcedlasttick]|"
+	var/list/counts = list()
+	for (var/list/L in queues)
+		counts += length(L)
+	msg += "Q:[counts.Join(",")]|D:[delslasttick]|G:[gcedlasttick]|"
 	msg += "GR:"
 	if (!(delslasttick+gcedlasttick))
 		msg += "n/a|"
@@ -49,116 +55,179 @@ SUBSYSTEM_DEF(garbage)
 		msg += "n/a|"
 	else
 		msg += "TGR:[round((totalgcs/(totaldels+totalgcs))*100, 0.01)]%"
+	msg += " P:[pass_counts.Join(",")]"
+	msg += "|F:[fail_counts.Join(",")]"
 	..(msg)
 
 /datum/controller/subsystem/garbage/Shutdown()
-	//Adds the del() log to world.log in a format condensable by the runtime condenser found in tools
-	if(didntgc.len || sleptDestroy.len)
+	//Adds the del() log to the qdel log file
 	var/list/dellog = list()
-		for(var/path in didntgc)
-			dellog += "Path : [path] \n"
-			dellog += "Failures : [didntgc[path]] \n"
-			if(path in sleptDestroy)
-				dellog += "Sleeps : [sleptDestroy[path]] \n"
-				sleptDestroy -= path
-		for(var/path in sleptDestroy)
-			dellog += "Path : [path] \n"
-			dellog += "Sleeps : [sleptDestroy[path]] \n"
+
+	//sort by how long it's wasted hard deleting
+	sortTim(items, cmp=/proc/cmp_qdel_item_time, associative = TRUE)
+	for(var/path in items)
+		var/datum/qdel_item/I = items[path]
+		dellog += "Path: [path]"
+		if (I.failures)
+			dellog += "\tFailures: [I.failures]"
+		dellog += "\tqdel() Count: [I.qdels]"
+		dellog += "\tDestroy() Cost: [I.destroy_time]ms"
+		if (I.hard_deletes)
+			dellog += "\tTotal Hard Deletes [I.hard_deletes]"
+			dellog += "\tTime Spent Hard Deleting: [I.hard_delete_time]ms"
+		if (I.slept_destroy)
+			dellog += "\tSleeps: [I.slept_destroy]"
+		if (I.no_respect_force)
+			dellog += "\tIgnored force: [I.no_respect_force] times"
+		if (I.no_hint)
+			dellog += "\tNo hint: [I.no_hint] times"
 		log_misc(dellog.Join())
 
 /datum/controller/subsystem/garbage/fire()
-	HandleToBeQueued()
-	if(state == SS_RUNNING)
-		HandleQueue()
+	//the fact that this resets its processing each fire (rather then resume where it left off) is intentional.
+	var/queue = GC_QUEUE_PREQUEUE
+
+	while (state == SS_RUNNING)
+		switch (queue)
+			if (GC_QUEUE_PREQUEUE)
+				HandlePreQueue()
+				queue = GC_QUEUE_PREQUEUE+1
+			if (GC_QUEUE_CHECK)
+				HandleQueue(GC_QUEUE_CHECK)
+				queue = GC_QUEUE_CHECK+1
+			if (GC_QUEUE_HARDDELETE)
+				HandleQueue(GC_QUEUE_HARDDELETE)
+				break
 
 	if (state == SS_PAUSED) //make us wait again before the next run.
 		state = SS_RUNNING
 
 //If you see this proc high on the profile, what you are really seeing is the garbage collection/soft delete overhead in byond.
 //Don't attempt to optimize, not worth the effort.
-/datum/controller/subsystem/garbage/proc/HandleToBeQueued()
-	var/list/tobequeued = src.tobequeued
-	var/starttime = world.time
-	var/starttimeofday = world.timeofday
-	while(tobequeued.len && starttime == world.time && starttimeofday == world.timeofday)
+/datum/controller/subsystem/garbage/proc/HandlePreQueue()
+	var/list/tobequeued = queues[GC_QUEUE_PREQUEUE]
+	var/static/count = 0
+	if (count)
+		var/c = count
+		count = 0 //so if we runtime on the Cut, we don't try again.
+		tobequeued.Cut(1,c+1)
+
+	for (var/ref in tobequeued)
+		count++
+		Queue(ref, GC_QUEUE_PREQUEUE+1)
 		if (MC_TICK_CHECK)
 			break
-		var/ref = tobequeued[1]
-		Queue(ref)
-		tobequeued.Cut(1, 2)
+	if (count)
+		tobequeued.Cut(1,count+1)
+		count = 0
 
-/datum/controller/subsystem/garbage/proc/HandleQueue()
+/datum/controller/subsystem/garbage/proc/HandleQueue(level = GC_QUEUE_CHECK)
+	if (level == GC_QUEUE_CHECK)
 		delslasttick = 0
 		gcedlasttick = 0
-	var/time_to_kill = world.time - collection_timeout // Anything qdel() but not GC'd BEFORE this time needs to be manually del()
-	var/list/queue = src.queue
-	var/starttime = world.time
-	var/starttimeofday = world.timeofday
-	while(queue.len && starttime == world.time && starttimeofday == world.timeofday)
+	var/cut_off_time = world.time - collection_timeout[level] //ignore entries newer then this
+	var/list/queue = queues[level]
+	var/static/lastlevel
+	var/static/count = 0
+	if (count) //runtime last run before we could do this.
+		var/c = count
+		count = 0 //so if we runtime on the Cut, we don't try again.
+		var/list/lastqueue = queues[lastlevel]
+		lastqueue.Cut(1, c+1)
+
+	lastlevel = level
+
+	for (var/refID in queue)
+		if (!refID)
+			count++
 			if (MC_TICK_CHECK)
 				break
-		var/refID = queue[1]
-		if (!refID)
-			queue.Cut(1, 2)
 			continue
 
 		var/GCd_at_time = queue[refID]
-		if(GCd_at_time > time_to_kill)
+		if(GCd_at_time > cut_off_time)
 			break // Everything else is newer, skip them
-		queue.Cut(1, 2)
-		var/datum/A
-		A = locate(refID)
-		if (A && A.gc_destroyed == GCd_at_time) // So if something else coincidently gets the same ref, it's not deleted by mistake
-			#ifdef GC_FAILURE_HARD_LOOKUP
-			A.find_references()
-			#endif
+		count++
 
-			// Something's still referring to the qdel'd object.  Kill it.
-			var/type = A.type
-			testing("GC: -- \ref[A] | [type] was unable to be GC'd and was deleted --")
-			didntgc["[type]"]++
+		var/datum/D
+		D = locate(refID)
 
-			HardDelete(A)
-
-			++delslasttick
-			++totaldels
-		else
+		if (!D || D.gc_destroyed != GCd_at_time) // So if something else coincidently gets the same ref, it's not deleted by mistake
 			++gcedlasttick
 			++totalgcs
+			pass_counts[level]++
+			if (MC_TICK_CHECK)
+				break
+			continue
 
-/datum/controller/subsystem/garbage/proc/QueueForQueuing(datum/A)
-	if (istype(A) && A.gc_destroyed == GC_CURRENTLY_BEING_QDELETED)
-		tobequeued += A
-		A.gc_destroyed = GC_QUEUED_FOR_QUEUING
+		// Something's still referring to the qdel'd object.
+		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[src] | [type] was unable to be GC'd --")
+				I.failures++
+			if (GC_QUEUE_HARDDELETE)
+				HardDelete(D)
+				if (MC_TICK_CHECK)
+					break
+				continue
 
-/datum/controller/subsystem/garbage/proc/Queue(datum/A)
-	if (isnull(A) || (!isnull(A.gc_destroyed) && A.gc_destroyed >= 0))
+		Queue(D, level+1)
+
+		if (MC_TICK_CHECK)
+			break
+	if (count)
+		queue.Cut(1,count+1)
+		count = 0
+
+/datum/controller/subsystem/garbage/proc/PreQueue(datum/D)
+	if (D.gc_destroyed == GC_CURRENTLY_BEING_QDELETED)
+		queues[GC_QUEUE_PREQUEUE] += D
+		D.gc_destroyed = GC_QUEUED_FOR_QUEUING
+
+/datum/controller/subsystem/garbage/proc/Queue(datum/D, level = GC_QUEUE_CHECK)
+	if (isnull(D))
 		return
-	if (A.gc_destroyed == GC_QUEUED_FOR_HARD_DEL)
-		HardDelete(A)
+	if (D.gc_destroyed == GC_QUEUED_FOR_HARD_DEL)
+		level = GC_QUEUE_HARDDELETE
+	if (level > GC_QUEUE_COUNT)
+		HardDelete(D)
 		return
 	var/gctime = world.time
-	var/refid = "\ref[A]"
-
-	A.gc_destroyed = gctime
+	var/refid = "\ref[D]"
 
+	D.gc_destroyed = gctime
+	var/list/queue = queues[level]
 	if (queue[refid])
 		queue -= refid // Removing any previous references that were GC'd so that the current object will be at the end of the list.
 
 	queue[refid] = gctime
 
-//this is purely to seperate things profile wise.
-/datum/controller/subsystem/garbage/proc/HardDelete(datum/A)
+//this is mainly to separate things profile wise.
+/datum/controller/subsystem/garbage/proc/HardDelete(datum/D)
 	var/time = world.timeofday
-	var/tick = world.tick_usage
+	var/tick = TICK_USAGE
 	var/ticktime = world.time
+	++delslasttick
+	++totaldels
+	var/type = D.type
+	var/refID = "\ref[D]"
 
-	var/type = A.type
-	var/refID = "\ref[A]"
+	del(D)
+
+	tick = (TICK_USAGE-tick+((world.time-ticktime)/world.tick_lag*100))
+
+	var/datum/qdel_item/I = items[type]
+
+	I.hard_deletes++
+	I.hard_delete_time += TICK_DELTA_TO_MS(tick)
 
-	del(A)
 
-	tick = (world.tick_usage-tick+((world.time-ticktime)/world.tick_lag*100))
 	if (tick > highest_del_tickusage)
 		highest_del_tickusage = tick
 	time = world.timeofday - time
@@ -169,18 +238,33 @@ SUBSYSTEM_DEF(garbage)
 	if (time > 10)
 		log_game("Error: [type]([refID]) took longer than 1 second to delete (took [time/10] seconds to delete)")
 		message_admins("Error: [type]([refID]) took longer than 1 second to delete (took [time/10] seconds to delete).")
-		postpone(time/5)
+		postpone(time)
 
-/datum/controller/subsystem/garbage/proc/HardQueue(datum/A)
-	if (istype(A) && A.gc_destroyed == GC_CURRENTLY_BEING_QDELETED)
-		tobequeued += A
-		A.gc_destroyed = GC_QUEUED_FOR_HARD_DEL
+/datum/controller/subsystem/garbage/proc/HardQueue(datum/D)
+	if (D.gc_destroyed == GC_CURRENTLY_BEING_QDELETED)
+		queues[GC_QUEUE_PREQUEUE] += D
+		D.gc_destroyed = GC_QUEUED_FOR_HARD_DEL
 
 /datum/controller/subsystem/garbage/Recover()
-	if (istype(SSgarbage.queue))
-		queue |= SSgarbage.queue
-	if (istype(SSgarbage.tobequeued))
-		tobequeued |= SSgarbage.tobequeued
+	if (istype(SSgarbage.queues))
+		for (var/i in 1 to SSgarbage.queues.len)
+			queues[i] |= SSgarbage.queues[i]
+
+
+/datum/qdel_item
+	var/name = ""
+	var/qdels = 0			//Total number of times it's passed thru qdel.
+	var/destroy_time = 0	//Total amount of milliseconds spent processing this type's Destroy()
+	var/failures = 0		//Times it was queued for soft deletion but failed to soft delete.
+	var/hard_deletes = 0 	//Different from failures because it also includes QDEL_HINT_HARDDEL deletions
+	var/hard_delete_time = 0//Total amount of milliseconds spent hard deleting this type.
+	var/no_respect_force = 0//Number of times it's not respected force=TRUE
+	var/no_hint = 0			//Number of times it's not even bother to give a qdel hint
+	var/slept_destroy = 0	//Number of times it's slept in its destroy
+
+/datum/qdel_item/New(mytype)
+	name = "[mytype]"
+
 
 // Should be treated as a replacement for the 'del' keyword.
 // Datums passed to this will be given a chance to clean up references to allow the GC to collect them.
@@ -188,20 +272,26 @@ SUBSYSTEM_DEF(garbage)
 	if(!istype(D))
 		del(D)
 		return
-#ifdef TESTING
-	SSgarbage.qdel_list += D.type
-#endif
+	var/datum/qdel_item/I = SSgarbage.items[D.type]
+	if (!I)
+		I = SSgarbage.items[D.type] = new /datum/qdel_item(D.type)
+	I.qdels++
+
+
 	if(isnull(D.gc_destroyed))
 		D.gc_destroyed = GC_CURRENTLY_BEING_QDELETED
 		var/start_time = world.time
+		var/start_tick = world.tick_usage
 		var/hint = D.Destroy(force) // Let our friend know they're about to get fucked up.
 		if(world.time != start_time)
-			SSgarbage.sleptDestroy[D.type]++
+			I.slept_destroy++
+		else
+			I.destroy_time += TICK_USAGE_TO_MS(start_tick)
 		if(!D)
 			return
 		switch(hint)
 			if (QDEL_HINT_QUEUE)		//qdel should queue the object for deletion.
-				SSgarbage.QueueForQueuing(D)
+				SSgarbage.PreQueue(D)
 			if (QDEL_HINT_IWILLGC)
 				D.gc_destroyed = world.time
 				return
@@ -211,28 +301,33 @@ SUBSYSTEM_DEF(garbage)
 					return
 				// Returning LETMELIVE after being told to force destroy
 				// indicates the objects Destroy() does not respect force
-				if(!SSgarbage.noforcerespect[D.type])
-					SSgarbage.noforcerespect[D.type] = D.type
+				#ifdef TESTING
+				if(!I.no_respect_force)
 					crash_with("[D.type] has been force deleted, but is \
 						returning an immortal QDEL_HINT, indicating it does \
 						not respect the force flag for qdel(). It has been \
 						placed in the queue, further instances of this type \
 						will also be queued.")
-				SSgarbage.QueueForQueuing(D)
+				#endif
+				I.no_respect_force++
+
+				SSgarbage.PreQueue(D)
 			if (QDEL_HINT_HARDDEL)		//qdel should assume this object won't gc, and queue a hard delete using a hard reference to save time from the locate()
 				SSgarbage.HardQueue(D)
 			if (QDEL_HINT_HARDDEL_NOW)	//qdel should assume this object won't gc, and hard del it post haste.
 				SSgarbage.HardDelete(D)
 			if (QDEL_HINT_FINDREFERENCE)//qdel will, if TESTING is enabled, display all references to this object, then queue the object for deletion.
-				SSgarbage.QueueForQueuing(D)
+				SSgarbage.PreQueue(D)
 				#ifdef TESTING
 				D.find_references()
 				#endif
 			else
-				if(!SSgarbage.noqdelhint[D.type])
-					SSgarbage.noqdelhint[D.type] = D.type
+				#ifdef TESTING
+				if(!I.no_hint)
 					crash_with("[D.type] is not returning a qdel hint. It is being placed in the queue. Further instances of this type will also be queued.")
-				SSgarbage.QueueForQueuing(D)
+				#endif
+				I.no_hint++
+				SSgarbage.PreQueue(D)
 	else if(D.gc_destroyed == GC_CURRENTLY_BEING_QDELETED)
 		CRASH("[D.type] destroy proc was called multiple times, likely due to a qdel loop in the Destroy logic")
 
@@ -247,8 +342,6 @@ SUBSYSTEM_DEF(garbage)
 /datum/var/gc_destroyed //Time when this object was destroyed.
 
 #ifdef TESTING
-/datum/var/running_find_references
-/datum/var/last_find_references = 0
 
 /datum/verb/find_refs()
 	set category = "Debug"
@@ -283,9 +376,17 @@ SUBSYSTEM_DEF(garbage)
 
 	testing("Beginning search for references to a [type].")
 	last_find_references = world.time
-	find_references_in_globals()
-	for(var/datum/thing in world)
-		DoSearchVar(thing, "WorldRef: [thing]")
+
+	// DoSearchVar(GLOB) // If we ever implement GLOB this would be the place.
+	for(var/datum/thing in world) //atoms (don't beleive it's lies)
+		DoSearchVar(thing, "World -> [thing]")
+
+	for (var/datum/thing) //datums
+		DoSearchVar(thing, "World -> [thing]")
+
+	for (var/client/thing) //clients
+		DoSearchVar(thing, "World -> [thing]")
+
 	testing("Completed search for references to a [type].")
 	if(usr && usr.client)
 		usr.client.running_find_references = null
@@ -295,16 +396,6 @@ SUBSYSTEM_DEF(garbage)
 	SSgarbage.can_fire = 1
 	SSgarbage.next_fire = world.time + world.tick_lag
 
-/client/verb/purge_all_destroyed_objects()
-	set category = "Debug"
-	if(SSgarbage)
-		while(SSgarbage.queue.len)
-			var/datum/o = locate(SSgarbage.queue[1])
-			if(istype(o) && o.gc_destroyed)
-				del(o)
-				SSgarbage.totaldels++
-			SSgarbage.queue.Cut(1, 2)
-
 /datum/verb/qdel_then_find_references()
 	set category = "Debug"
 	set name = "qdel() then Find References"
@@ -315,61 +406,47 @@ SUBSYSTEM_DEF(garbage)
 	if(!running_find_references)
 		find_references(TRUE)
 
-/client/verb/show_qdeleted()
-	set category = "Debug"
-	set name = "Show qdel() Log"
-	set desc = "Render the qdel() log and display it"
+/datum/proc/DoSearchVar(X, Xname, recursive_limit = 64)
+	if(usr && usr.client && !usr.client.running_find_references)
+		return
+	if (!recursive_limit)
+		return
 
-	var/dat = "<B>List of things that have been qdel()eted this round</B><BR><BR>"
-
-	var/tmplist = list()
-	for(var/elem in SSgarbage.qdel_list)
-		if(!(elem in tmplist))
-			tmplist[elem] = 0
-		tmplist[elem]++
-
-	for(var/path in tmplist)
-		dat += "[path] - [tmplist[path]] times<BR>"
-
-	usr << browse(dat, "window=qdeletedlog")
-
-/datum/proc/DoSearchVar(X, Xname)
-	if(usr && usr.client && !usr.client.running_find_references) return
 	if(istype(X, /datum))
 		var/datum/D = X
 		if(D.last_find_references == last_find_references)
 			return
+
 		D.last_find_references = last_find_references
-		for(var/V in D.vars)
-			for(var/varname in D.vars)
-				var/variable = D.vars[varname]
+		var/list/L = D.vars
+
+		for(var/varname in L)
+			if (varname == "vars")
+				continue
+			var/variable = L[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
+				DoSearchVar(variable, "[Xname] -> list", recursive_limit-1)
+
 	else if(islist(X))
-		if(src in X)
-			testing("Found [src.type] \ref[src] in list [Xname].")
-#ifdef GC_FAILURE_HARD_LOOKUP
+		var/normal = IS_NORMAL_LIST(X)
 		for(var/I in X)
-			DoSearchVar(I, Xname + ": list")
-#else
+			if (I == src)
+				testing("Found [src.type] \ref[src] in list [Xname].")
+
+			else if (I && !isnum(I) && normal && X[I] == src)
+				testing("Found [src.type] \ref[src] in list [Xname]\[[I]\]")
+
+			else if (islist(I))
+				DoSearchVar(I, "[Xname] -> list", recursive_limit-1)
+
+#ifndef FIND_REF_NO_CHECK_TICK
 	CHECK_TICK
 #endif
 
-//if find_references isn't working for some datum
-//update this list using tools/GenerateGlobalVarAccess
-/datum/proc/find_references_in_globals()
-	// TODO - Impement Global Variable Access
-	// for(var/global_var in _all_globals)
-	// 	DoSearchVar(readglobal(global_var), "Global: [global_var]")
 #endif
 
 

code/controllers/subsystems/lighting.dm

@@ -50,27 +50,27 @@ SUBSYSTEM_DEF(lighting)
 		stage = SSLIGHTING_STAGE_LIGHTS // Start with Step 1 of course
 
 	if(stage == SSLIGHTING_STAGE_LIGHTS)
-		timer = world.tick_usage
+		timer = TICK_USAGE
 		internal_process_lights(resumed)
-		cost_lights = MC_AVERAGE(cost_lights, TICK_DELTA_TO_MS(world.tick_usage - timer))
+		cost_lights = MC_AVERAGE(cost_lights, TICK_DELTA_TO_MS(TICK_USAGE - timer))
 		if(state != SS_RUNNING)
 			return
 		resumed = 0
 		stage = SSLIGHTING_STAGE_CORNERS
 
 	if(stage == SSLIGHTING_STAGE_CORNERS)
-		timer = world.tick_usage
+		timer = TICK_USAGE
 		internal_process_corners(resumed)
-		cost_corners = MC_AVERAGE(cost_corners, TICK_DELTA_TO_MS(world.tick_usage - timer))
+		cost_corners = MC_AVERAGE(cost_corners, TICK_DELTA_TO_MS(TICK_USAGE - timer))
 		if(state != SS_RUNNING)
 			return
 		resumed = 0
 		stage = SSLIGHTING_STAGE_OVERLAYS
 
 	if(stage == SSLIGHTING_STAGE_OVERLAYS)
-		timer = world.tick_usage
+		timer = TICK_USAGE
 		internal_process_overlays(resumed)
-		cost_overlays = MC_AVERAGE(cost_overlays, TICK_DELTA_TO_MS(world.tick_usage - timer))
+		cost_overlays = MC_AVERAGE(cost_overlays, TICK_DELTA_TO_MS(TICK_USAGE - timer))
 		if(state != SS_RUNNING)
 			return
 		resumed = 0

code/modules/admin/admin_verbs.dm

@@ -190,6 +190,7 @@ var/list/admin_verbs_debug = list(
 	/client/proc/cmd_admin_delete,
 	/client/proc/cmd_debug_del_all,
 	/client/proc/cmd_debug_tog_aliens,
+	/client/proc/cmd_display_del_log,
 	/client/proc/air_report,
 	/client/proc/reload_admins,
 	/client/proc/reload_eventMs,
@@ -303,6 +304,7 @@ var/list/admin_verbs_hideable = list(
 	/client/proc/cmd_debug_using_map,
 	/client/proc/cmd_debug_del_all,
 	/client/proc/cmd_debug_tog_aliens,
+	/client/proc/cmd_display_del_log,
 	/client/proc/air_report,
 	/client/proc/enable_debug_verbs,
 	/client/proc/roll_dices,

code/modules/admin/verbs/debug.dm

@@ -291,6 +291,36 @@
 	message_admins("[key_name_admin(src)] has turned aliens [config.aliens_allowed ? "on" : "off"].", 0)
 	feedback_add_details("admin_verb","TAL") //If you are copy-pasting this, ensure the 2nd parameter is unique to the new proc!
 
+/client/proc/cmd_display_del_log()
+	set category = "Debug"
+	set name = "Display del() Log"
+	set desc = "Display del's log of everything that's passed through it."
+
+	if(!check_rights(R_DEBUG))	return
+	var/list/dellog = list("<B>List of things that have gone through qdel this round</B><BR><BR><ol>")
+	sortTim(SSgarbage.items, cmp=/proc/cmp_qdel_item_time, associative = TRUE)
+	for(var/path in SSgarbage.items)
+		var/datum/qdel_item/I = SSgarbage.items[path]
+		dellog += "<li><u>[path]</u><ul>"
+		if (I.failures)
+			dellog += "<li>Failures: [I.failures]</li>"
+		dellog += "<li>qdel() Count: [I.qdels]</li>"
+		dellog += "<li>Destroy() Cost: [I.destroy_time]ms</li>"
+		if (I.hard_deletes)
+			dellog += "<li>Total Hard Deletes [I.hard_deletes]</li>"
+			dellog += "<li>Time Spent Hard Deleting: [I.hard_delete_time]ms</li>"
+		if (I.slept_destroy)
+			dellog += "<li>Sleeps: [I.slept_destroy]</li>"
+		if (I.no_respect_force)
+			dellog += "<li>Ignored force: [I.no_respect_force]</li>"
+		if (I.no_hint)
+			dellog += "<li>No hint: [I.no_hint]</li>"
+		dellog += "</ul></li>"
+
+	dellog += "</ol>"
+
+	usr << browse(dellog.Join(), "window=dellog")
+
 /client/proc/cmd_admin_grantfullaccess(var/mob/M in mob_list)
 	set category = "Admin"
 	set name = "Grant Full Access"

code/modules/client/client procs.dm

@@ -296,8 +296,7 @@
 	if (holder)
 		sleep(1)
 	else
-		sleep(5)
-		stoplag()
+		stoplag(5)
 
 /client/proc/last_activity_seconds()
 	return inactivity / 10

code/modules/mob/living/simple_animal/simple_animal.dm

@@ -1165,7 +1165,7 @@
 	//They ran away!
 	else
 		ai_log("AttackTarget() out of range!",3)
-		sleep(1) // Unfortunately this is needed to protect from ClosestDistance() sometimes not updating fast enough to prevent an infinite loop.
+		stoplag(1) // Unfortunately this is needed to protect from ClosestDistance() sometimes not updating fast enough to prevent an infinite loop.
 		handle_stance(STANCE_ATTACK)
 		return 0
 

html/changelogs/Leshana-tgport.yml

@@ -0,0 +1,4 @@
+author: MrStonedOne
+delete-after: True
+changes: 
+  - rscadd: "Added admin verb 'Display del() Log' displaying garabage collector statistics."

polaris.dme

@@ -20,6 +20,7 @@
 #include "code\world.dm"
 #include "code\__defines\_compile_options.dm"
 #include "code\__defines\_planes+layers.dm"
+#include "code\__defines\_tick.dm"
 #include "code\__defines\admin.dm"
 #include "code\__defines\appearance.dm"
 #include "code\__defines\atmos.dm"
@@ -45,7 +46,6 @@
 #include "code\__defines\species_languages.dm"
 #include "code\__defines\subsystems.dm"
 #include "code\__defines\targeting.dm"
-#include "code\__defines\tick.dm"
 #include "code\__defines\turfs.dm"
 #include "code\__defines\unit_tests.dm"
 #include "code\__defines\xenoarcheaology.dm"