diff --git a/code/__defines/MC.dm b/code/__defines/MC.dm index fb15a693bf..b2f3c814fe 100644 --- a/code/__defines/MC.dm +++ b/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;\ diff --git a/code/__defines/tick.dm b/code/__defines/_tick.dm similarity index 51% rename from code/__defines/tick.dm rename to code/__defines/_tick.dm index 4c88fd643e..2c761b86f9 100644 --- a/code/__defines/tick.dm +++ b/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 diff --git a/code/__defines/math.dm b/code/__defines/math.dm index 0729a4526d..79dc1b4d24 100644 --- a/code/__defines/math.dm +++ b/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) ) diff --git a/code/__defines/process_scheduler.dm b/code/__defines/process_scheduler.dm index f1e30c23ed..4bc841022f 100644 --- a/code/__defines/process_scheduler.dm +++ b/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() diff --git a/code/__defines/qdel.dm b/code/__defines/qdel.dm index 168a6adf0c..c444f49fc9 100644 --- a/code/__defines/qdel.dm +++ b/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 diff --git a/code/_helpers/mobs.dm b/code/_helpers/mobs.dm index eb1ef73eb7..1dffebf607 100644 --- a/code/_helpers/mobs.dm +++ b/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) diff --git a/code/_helpers/sorts/comparators.dm b/code/_helpers/sorts/comparators.dm index 8c1f954a00..58f9251392 100644 --- a/code/_helpers/sorts/comparators.dm +++ b/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 diff --git a/code/_helpers/time.dm b/code/_helpers/time.dm index 3a6bcedcd1..6dad42e128 100644 --- a/code/_helpers/time.dm +++ b/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 \ No newline at end of file diff --git a/code/controllers/ProcessScheduler/core/process.dm b/code/controllers/ProcessScheduler/core/process.dm index 9f08241978..2965a52abe 100644 --- a/code/controllers/ProcessScheduler/core/process.dm +++ b/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 diff --git a/code/controllers/master.dm b/code/controllers/master.dm index 4ca4bebf0a..3ecb3b7fcb 100644 --- a/code/controllers/master.dm +++ b/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 diff --git a/code/controllers/subsystem.dm b/code/controllers/subsystem.dm index 7dff609c76..bd9a2aeafb 100644 --- a/code/controllers/subsystem.dm +++ b/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) diff --git a/code/controllers/subsystems/garbage.dm b/code/controllers/subsystems/garbage.dm index d6db860d5d..32acbb272a 100644 --- a/code/controllers/subsystems/garbage.dm +++ b/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 - // 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/pass_counts + var/list/fail_counts - 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/items = list() // Holds our qdel_item statistics datums - 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 + // 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/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) - 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" + //Adds the del() log to the qdel log file + var/list/dellog = list() + + //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 + 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) - if (MC_TICK_CHECK) - break - var/ref = tobequeued[1] - Queue(ref) - tobequeued.Cut(1, 2) +/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) -/datum/controller/subsystem/garbage/proc/HandleQueue() - 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) + for (var/ref in tobequeued) + count++ + Queue(ref, GC_QUEUE_PREQUEUE+1) if (MC_TICK_CHECK) break - var/refID = queue[1] + if (count) + tobequeued.Cut(1,count+1) + count = 0 + +/datum/controller/subsystem/garbage/proc/HandleQueue(level = GC_QUEUE_CHECK) + if (level == GC_QUEUE_CHECK) + delslasttick = 0 + gcedlasttick = 0 + 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) - queue.Cut(1, 2) + count++ + if (MC_TICK_CHECK) + break 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]"]++ - - HardDelete(A) + var/datum/D + D = locate(refID) - ++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 - - var/type = A.type - var/refID = "\ref[A]" - - del(A) - - tick = (world.tick_usage-tick+((world.time-ticktime)/world.tick_lag*100)) + ++delslasttick + ++totaldels + var/type = D.type + var/refID = "\ref[D]" + + 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) + + 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) - -/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 + postpone(time) + +/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 = "List of things that have been qdel()eted this round

" - - 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
" - - 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] - 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 + 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)) + 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 diff --git a/code/controllers/subsystems/lighting.dm b/code/controllers/subsystems/lighting.dm index 01875cc397..8817d83ad5 100644 --- a/code/controllers/subsystems/lighting.dm +++ b/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 diff --git a/code/modules/admin/admin_verbs.dm b/code/modules/admin/admin_verbs.dm index 0235293a72..b5c405288e 100644 --- a/code/modules/admin/admin_verbs.dm +++ b/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, diff --git a/code/modules/admin/verbs/debug.dm b/code/modules/admin/verbs/debug.dm index 02c3fbc7b6..f7a5d79c03 100644 --- a/code/modules/admin/verbs/debug.dm +++ b/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("List of things that have gone through qdel this round

    ") + 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 += "
  1. [path]
  2. " + + dellog += "
" + + 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" diff --git a/code/modules/client/client procs.dm b/code/modules/client/client procs.dm index d085e5cec0..6a85924c4d 100644 --- a/code/modules/client/client procs.dm +++ b/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 diff --git a/code/modules/mob/living/simple_animal/simple_animal.dm b/code/modules/mob/living/simple_animal/simple_animal.dm index 231db2866a..338b66e43f 100644 --- a/code/modules/mob/living/simple_animal/simple_animal.dm +++ b/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 diff --git a/html/changelogs/Leshana-tgport.yml b/html/changelogs/Leshana-tgport.yml new file mode 100644 index 0000000000..eeceacc2e7 --- /dev/null +++ b/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." diff --git a/polaris.dme b/polaris.dme index aa828d2631..e09ddb0026 100644 --- a/polaris.dme +++ b/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"