From bfdebd524d912956e53526728ca705c0ab7e4e29 Mon Sep 17 00:00:00 2001 From: DragonTrance Date: Fri, 11 Nov 2022 09:04:24 -0500 Subject: [PATCH 1/5] port tgstation/tgstation#52409 --- code/__DEFINES/subsystems.dm | 1 + code/controllers/subsystem/timer.dm | 1 + 2 files changed, 2 insertions(+) diff --git a/code/__DEFINES/subsystems.dm b/code/__DEFINES/subsystems.dm index 3ddf29310..be990202a 100644 --- a/code/__DEFINES/subsystems.dm +++ b/code/__DEFINES/subsystems.dm @@ -121,6 +121,7 @@ #define FIRE_PRIORITY_CHAT 400 #define FIRE_PRIORITY_RUNECHAT 410 #define FIRE_PRIORITY_OVERLAYS 500 +#define FIRE_PRIORITY_TIMER 700 #define FIRE_PRIORITY_INPUT 1000 // This must always always be the max highest priority. Player input must never be lost. // SS runlevels diff --git a/code/controllers/subsystem/timer.dm b/code/controllers/subsystem/timer.dm index 34fde8b9e..d8c981724 100644 --- a/code/controllers/subsystem/timer.dm +++ b/code/controllers/subsystem/timer.dm @@ -7,6 +7,7 @@ SUBSYSTEM_DEF(timer) name = "Timer" wait = 1 //SS_TICKER subsystem, so wait is in ticks init_order = INIT_ORDER_TIMER + priority = FIRE_PRIORITY_TIMER flags = SS_TICKER|SS_NO_INIT From 67e365cd1f834b7ef0567428fa2e42492aa00788 Mon Sep 17 00:00:00 2001 From: DragonTrance Date: Fri, 11 Nov 2022 09:30:41 -0500 Subject: [PATCH 2/5] port tgstation/tgstation#52417 --- code/__DEFINES/subsystems.dm | 8 +++ code/controllers/subsystem/timer.dm | 11 +++- .../effects/spawners/xeno_egg_delivery.dm | 2 +- code/game/world.dm | 2 +- code/modules/admin/admin_verbs.dm | 3 +- code/modules/admin/verbs/debug.dm | 59 +++++++++++++++++++ code/modules/jobs/job_types/job.dm | 2 +- 7 files changed, 80 insertions(+), 7 deletions(-) diff --git a/code/__DEFINES/subsystems.dm b/code/__DEFINES/subsystems.dm index be990202a..df54f854f 100644 --- a/code/__DEFINES/subsystems.dm +++ b/code/__DEFINES/subsystems.dm @@ -155,3 +155,11 @@ }\ A.flags_1 &= ~OVERLAY_QUEUED_1;\ } + +/* Creates a new timer and adds it to the queue. + * Arguments: + * * callback the callback to call on timer finish + * * wait deciseconds to run the timer for + * * flags flags for the timer, see: code\__DEFINES\subsystems.dm + */ +#define addtimer(args...) _addtimer(args, file = __FILE__, line = __LINE__) diff --git a/code/controllers/subsystem/timer.dm b/code/controllers/subsystem/timer.dm index d8c981724..5de16d7fb 100644 --- a/code/controllers/subsystem/timer.dm +++ b/code/controllers/subsystem/timer.dm @@ -319,19 +319,21 @@ SUBSYSTEM_DEF(timer) var/wait var/hash var/list/flags + var/source var/spent = 0 //time we ran the timer. var/name //for easy debugging. //cicular doublely linked list var/datum/timedevent/next var/datum/timedevent/prev -/datum/timedevent/New(datum/callback/callBack, wait, flags, hash) +/datum/timedevent/New(datum/callback/callBack, wait, flags, hash, source) var/static/nextid = 1 id = TIMER_ID_NULL src.callBack = callBack src.wait = wait src.flags = flags src.hash = hash + src.source = source if (flags & TIMER_CLIENT_TIME) timeToRun = REALTIMEOFDAY + wait @@ -456,7 +458,10 @@ SUBSYSTEM_DEF(timer) else . = "[callBack.object.type]" -/proc/addtimer(datum/callback/callback, wait = 0, flags = 0) +/* + * Do not call this directly. Instead, use the addtimer() macro, which includes source information + */ +/proc/_addtimer(datum/callback/callback, wait = 0, flags = 0, file, line) if (!callback) CRASH("addtimer called without a callback") @@ -497,7 +502,7 @@ SUBSYSTEM_DEF(timer) else if(flags & TIMER_OVERRIDE) stack_trace("TIMER_OVERRIDE used without TIMER_UNIQUE") - var/datum/timedevent/timer = new(callback, wait, flags, hash) + var/datum/timedevent/timer = new(callback, wait, flags, hash, file && "[file]:[line]") return timer.id /proc/deltimer(id) diff --git a/code/game/objects/effects/spawners/xeno_egg_delivery.dm b/code/game/objects/effects/spawners/xeno_egg_delivery.dm index 9be52dab5..dd4a6ea47 100644 --- a/code/game/objects/effects/spawners/xeno_egg_delivery.dm +++ b/code/game/objects/effects/spawners/xeno_egg_delivery.dm @@ -15,5 +15,5 @@ message_admins("An alien egg has been delivered to [ADMIN_VERBOSEJMP(T)].") log_game("An alien egg has been delivered to [AREACOORD(T)]") var/message = "Attention [station_name()], we have entrusted you with a research specimen in [get_area_name(T, TRUE)]. Remember to follow all safety precautions when dealing with the specimen." - SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, /proc/addtimer, CALLBACK(GLOBAL_PROC, /proc/print_command_report, message), announcement_time)) + SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, /proc/_addtimer, CALLBACK(GLOBAL_PROC, /proc/print_command_report, message), announcement_time)) return INITIALIZE_HINT_QDEL diff --git a/code/game/world.dm b/code/game/world.dm index 8ef4d3719..999704c8a 100644 --- a/code/game/world.dm +++ b/code/game/world.dm @@ -71,7 +71,7 @@ GLOBAL_VAR(restart_counter) #else cb = VARSET_CALLBACK(SSticker, force_ending, TRUE) #endif - SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, /proc/addtimer, cb, 10 SECONDS)) + SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, /proc/_addtimer, cb, 10 SECONDS)) /world/proc/SetupExternalRSC() #if (PRELOAD_RSC == 0) diff --git a/code/modules/admin/admin_verbs.dm b/code/modules/admin/admin_verbs.dm index 399823a2c..0ab3528af 100644 --- a/code/modules/admin/admin_verbs.dm +++ b/code/modules/admin/admin_verbs.dm @@ -177,6 +177,7 @@ GLOBAL_LIST_INIT(admin_verbs_debug, world.AVerbsDebug()) /client/proc/cmd_display_overlay_log, /client/proc/reload_configuration, /datum/admins/proc/create_or_modify_area, + /client/proc/check_timer_sources, /client/proc/generate_wikichem_list //DO NOT PRESS UNLESS YOU WANT SUPERLAG ) GLOBAL_PROTECT(admin_verbs_possess) @@ -728,4 +729,4 @@ GLOBAL_LIST_INIT(admin_verbs_hideable, list( set name = "Debug Stat Panel" set category = "Debug" - src << output("", "statbrowser:create_debug") \ No newline at end of file + src << output("", "statbrowser:create_debug") diff --git a/code/modules/admin/verbs/debug.dm b/code/modules/admin/verbs/debug.dm index f6df2a5d0..cff01ca31 100644 --- a/code/modules/admin/verbs/debug.dm +++ b/code/modules/admin/verbs/debug.dm @@ -822,3 +822,62 @@ return if(alert(usr, "Are you absolutely sure you want to reload the configuration from the default path on the disk, wiping any in-round modificatoins?", "Really reset?", "No", "Yes") == "Yes") config.admin_reload() + +/// A debug verb to check the sources of currently running timers +/client/proc/check_timer_sources() + set category = "Debug" + set name = "Check Timer Sources" + set desc = "Checks the sources of the running timers" + if(!check_rights(R_DEBUG)) + return + + var/bucket_list_output = generate_timer_source_output(SStimer.bucket_list) + var/second_queue = generate_timer_source_output(SStimer.second_queue) + + usr << browse({" +

bucket_list

+ [bucket_list_output] +

second_queue

+ [second_queue] + "}, "window=check_timer_sources;size=700x700") + +/proc/generate_timer_source_output(list/datum/timedevent/events) + var/list/per_source = list() + + // Collate all events and figure out what sources are creating the most + for (var/_event in events) + if (!_event) + continue + var/datum/timedevent/event = _event + + do + if (event.source) + if (per_source[event.source] == null) + per_source[event.source] = 1 + else + per_source[event.source] += 1 + event = event.next + while (event && event != _event) + + // Now, sort them in order + var/list/sorted = list() + for (var/source in per_source) + sorted += list(list("source" = source, "count" = per_source[source])) + sorted = sortTim(sorted, .proc/cmp_timer_data) + + // Now that everything is sorted, compile them into an HTML output + var/output = "" + + for (var/_timer_data in sorted) + var/list/timer_data = _timer_data + output += {" + + + "} + + output += "
[timer_data["source"]][timer_data["count"]]
" + + return output + +/proc/cmp_timer_data(list/a, list/b) + return b["count"] - a["count"] diff --git a/code/modules/jobs/job_types/job.dm b/code/modules/jobs/job_types/job.dm index e3e2ca4f1..fbbdf2504 100644 --- a/code/modules/jobs/job_types/job.dm +++ b/code/modules/jobs/job_types/job.dm @@ -140,7 +140,7 @@ /datum/job/proc/announce_head(var/mob/living/carbon/human/H, var/channels) //tells the given channel that the given mob is the new department head. See communications.dm for valid channels. if(H && GLOB.announcement_systems.len) //timer because these should come after the captain announcement - SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, .proc/addtimer, CALLBACK(pick(GLOB.announcement_systems), /obj/machinery/announcement_system/proc/announce, "NEWHEAD", H.real_name, H.job, H.client?.prefs.alt_titles_preferences[H.job], channels), 1)) + SSticker.OnRoundstart(CALLBACK(GLOBAL_PROC, .proc/_addtimer, CALLBACK(pick(GLOB.announcement_systems), /obj/machinery/announcement_system/proc/announce, "NEWHEAD", H.real_name, H.job, H.client?.prefs.alt_titles_preferences[H.job], channels), 1)) //If the configuration option is set to require players to be logged as old enough to play certain jobs, then this proc checks that they are, otherwise it just returns 1 /datum/job/proc/player_old_enough(client/C) From bb9bacf7dc098be729e4ade459a492880daa9edc Mon Sep 17 00:00:00 2001 From: DragonTrance Date: Fri, 11 Nov 2022 09:43:15 -0500 Subject: [PATCH 3/5] port tgstation/tgstation#54977 --- code/controllers/subsystem/timer.dm | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/code/controllers/subsystem/timer.dm b/code/controllers/subsystem/timer.dm index 5de16d7fb..259dd7be8 100644 --- a/code/controllers/subsystem/timer.dm +++ b/code/controllers/subsystem/timer.dm @@ -73,10 +73,12 @@ SUBSYSTEM_DEF(timer) for(var/I in second_queue) log_world(get_timer_debug_string(I)) - var/next_clienttime_timer_index = 0 - var/len = length(clienttime_timers) + var/static/next_clienttime_timer_index = 0 + if (next_clienttime_timer_index) + clienttime_timers.Cut(1, next_clienttime_timer_index+1) + next_clienttime_timer_index = 0 - for (next_clienttime_timer_index in 1 to len) + for (next_clienttime_timer_index in 1 to length(clienttime_timers)) if (MC_TICK_CHECK) next_clienttime_timer_index-- break @@ -87,7 +89,6 @@ SUBSYSTEM_DEF(timer) var/datum/callback/callBack = ctime_timer.callBack if (!callBack) - clienttime_timers.Cut(next_clienttime_timer_index,next_clienttime_timer_index+1) CRASH("Invalid timer: [get_timer_debug_string(ctime_timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset], REALTIMEOFDAY: [REALTIMEOFDAY]") ctime_timer.spent = REALTIMEOFDAY @@ -103,6 +104,7 @@ SUBSYSTEM_DEF(timer) if (next_clienttime_timer_index) clienttime_timers.Cut(1, next_clienttime_timer_index+1) + next_clienttime_timer_index = 0 if (MC_TICK_CHECK) return From 55aecea4a6ccf51b079317a0b92b00f601d24820 Mon Sep 17 00:00:00 2001 From: DragonTrance Date: Fri, 11 Nov 2022 10:00:39 -0500 Subject: [PATCH 4/5] port tgstation/tgstation#55140 --- code/controllers/subsystem/timer.dm | 123 ++++++++-------------------- 1 file changed, 35 insertions(+), 88 deletions(-) diff --git a/code/controllers/subsystem/timer.dm b/code/controllers/subsystem/timer.dm index 259dd7be8..e88f42a02 100644 --- a/code/controllers/subsystem/timer.dm +++ b/code/controllers/subsystem/timer.dm @@ -109,8 +109,6 @@ SUBSYSTEM_DEF(timer) if (MC_TICK_CHECK) return - var/static/list/spent = list() - var/static/datum/timedevent/timer if (practical_offset > BUCKET_LEN) head_offset += TICKS2DS(BUCKET_LEN) practical_offset = 1 @@ -121,110 +119,59 @@ SUBSYSTEM_DEF(timer) bucket_list = src.bucket_list resumed = FALSE - - if (!resumed) - timer = null - while (practical_offset <= BUCKET_LEN && head_offset + (practical_offset*world.tick_lag) <= world.time) - var/datum/timedevent/head = bucket_list[practical_offset] - if (!timer || !head || timer == head) - head = bucket_list[practical_offset] - timer = head - while (timer) + var/datum/timedevent/timer + while ((timer = bucket_list[practical_offset])) var/datum/callback/callBack = timer.callBack if (!callBack) bucket_resolution = null //force bucket recreation CRASH("Invalid timer: [get_timer_debug_string(timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset]") + timer.bucketEject() //pop the stack + if (!timer.spent) - spent += timer timer.spent = world.time callBack.InvokeAsync() last_invoke_tick = world.time + if (timer.flags & TIMER_LOOP) + timer.spent = 0 + timer.timeToRun = world.time + timer.wait + timer.bucketJoin() //push the stack + if (MC_TICK_CHECK) - return - - timer = timer.next - if (timer == head) break + //Empty the bucket, check if anything in the secondary queue should be shifted to this bucket + if (!bucket_list[practical_offset]) + bucket_list[practical_offset++] = null + var/i = 0 + for(i in 1 to length(second_queue)) + timer = second_queue[i] + if(timer.timeToRun >= TIMER_MAX) //Invalid timer + i-- + break - bucket_list[practical_offset++] = null + //Check for timers that were scheduled to run in the past + if (timer.timeToRun < head_offset) + bucket_resolution = null //force bucket recreation + stack_trace("[i] Invalid timer state: Timer in long run queue with a time to run less then head_offset. \ + [get_timer_debug_string(timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset]") + break - //we freed up a bucket, lets see if anything in second_queue needs to be shifted to that bucket. - var/i = 0 - var/L = length(second_queue) - for (i in 1 to L) - timer = second_queue[i] - if (timer.timeToRun >= TIMER_MAX) - i-- - break + //Check for timers that are not capable of being scheduled to run without rebuilding buckets + if (timer.timeToRun < head_offset + TICKS2DS(practical_offset - 1)) + bucket_resolution = null // force bucket recreation + stack_trace("[i] Invalid timer state: Timer in long run queue that would require a backtrack to transfer to short run queue. \ + [get_timer_debug_string(timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset]") + break - if (timer.timeToRun < head_offset) - bucket_resolution = null //force bucket recreation - CRASH("[i] Invalid timer state: Timer in long run queue with a time to run less then head_offset. [get_timer_debug_string(timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset]") + timer.bucketJoin() + if (i) + second_queue.Cut(1, i+1) - if (timer.callBack && !timer.spent) - timer.callBack.InvokeAsync() - spent += timer - bucket_count++ - else if(!QDELETED(timer)) - qdel(timer) - continue - - if (timer.timeToRun < head_offset + TICKS2DS(practical_offset)) - bucket_resolution = null //force bucket recreation - CRASH("[i] Invalid timer state: Timer in long run queue that would require a backtrack to transfer to short run queue. [get_timer_debug_string(timer)] world.time: [world.time], head_offset: [head_offset], practical_offset: [practical_offset]") - if (timer.callBack && !timer.spent) - timer.callBack.InvokeAsync() - spent += timer - bucket_count++ - else if(!QDELETED(timer)) - qdel(timer) - continue - - bucket_count++ - var/bucket_pos = max(1, BUCKET_POS(timer)) - - var/datum/timedevent/bucket_head = bucket_list[bucket_pos] - if (!bucket_head) - bucket_list[bucket_pos] = timer - timer.next = null - timer.prev = null - continue - - if (!bucket_head.prev) - bucket_head.prev = bucket_head - timer.next = bucket_head - timer.prev = bucket_head.prev - timer.next.prev = timer - timer.prev.next = timer - if (i) - second_queue.Cut(1, i+1) - - timer = null - - bucket_count -= length(spent) - - for (var/i in spent) - var/datum/timedevent/qtimer = i - if(QDELETED(qtimer)) - bucket_count++ - continue - if(!(qtimer.flags & TIMER_LOOP)) - qdel(qtimer) - else - bucket_count++ - qtimer.spent = 0 - qtimer.bucketEject() - if(qtimer.flags & TIMER_CLIENT_TIME) - qtimer.timeToRun = REALTIMEOFDAY + qtimer.wait - else - qtimer.timeToRun = world.time + qtimer.wait - qtimer.bucketJoin() - - spent.len = 0 + if (MC_TICK_CHECK) + break //formated this way to be runtime resistant /datum/controller/subsystem/timer/proc/get_timer_debug_string(datum/timedevent/TE) From 52043dea7eae568dd0534cda097699dcf870427e Mon Sep 17 00:00:00 2001 From: DragonTrance Date: Fri, 11 Nov 2022 10:04:01 -0500 Subject: [PATCH 5/5] fix endlessly-looping timers --- code/controllers/subsystem/timer.dm | 3 --- 1 file changed, 3 deletions(-) diff --git a/code/controllers/subsystem/timer.dm b/code/controllers/subsystem/timer.dm index e88f42a02..6bdb86257 100644 --- a/code/controllers/subsystem/timer.dm +++ b/code/controllers/subsystem/timer.dm @@ -106,9 +106,6 @@ SUBSYSTEM_DEF(timer) clienttime_timers.Cut(1, next_clienttime_timer_index+1) next_clienttime_timer_index = 0 - if (MC_TICK_CHECK) - return - if (practical_offset > BUCKET_LEN) head_offset += TICKS2DS(BUCKET_LEN) practical_offset = 1