From 7ace8da9e0e4f3ccd0663f2cd2f1625ae5149ed4 Mon Sep 17 00:00:00 2001 From: Kyle Spier-Swenson Date: Sun, 27 Jun 2021 15:31:03 -0700 Subject: [PATCH] Adds configs to disable laggy hard deletes (#59750) cl server: Added configs to disable laggy hard deletes once they lag the server too much. admin: laggy hard deletes only output once per type path. /cl closes #58379 --- code/__DEFINES/qdel.dm | 5 +- code/__DEFINES/time.dm | 6 ++ .../configuration/entries/general.dm | 9 +++ code/controllers/subsystem/garbage.dm | 74 ++++++++++++------- code/modules/admin/verbs/debug.dm | 5 ++ config/config.txt | 6 ++ 6 files changed, 76 insertions(+), 29 deletions(-) diff --git a/code/__DEFINES/qdel.dm b/code/__DEFINES/qdel.dm index ef770532bd4..643774c83a0 100644 --- a/code/__DEFINES/qdel.dm +++ b/code/__DEFINES/qdel.dm @@ -13,7 +13,6 @@ // Qdel should assume this object won't gc, and hard delete it posthaste. #define QDEL_HINT_HARDDEL_NOW 4 -//! Defines for the [gc_destroyed][/datum/var/gc_destroyed] var. #ifdef REFERENCE_TRACKING /** If REFERENCE_TRACKING is enabled, qdel will call this object's find_references() verb. @@ -29,6 +28,10 @@ #define GC_QUEUE_HARDDELETE 2 #define GC_QUEUE_COUNT 2 //increase this when adding more steps. +#define QDEL_ITEM_ADMINS_WARNED (1<<0) //! Set when admins are told about lag causing qdels in this type. +#define QDEL_ITEM_SUSPENDED_FOR_LAG (1<<1) //! Set when a type can no longer be hard deleted on failure because of lag it causes while this happens. + +// Defines for the [gc_destroyed][/datum/var/gc_destroyed] var. #define GC_QUEUED_FOR_QUEUING -1 #define GC_CURRENTLY_BEING_QDELETED -2 diff --git a/code/__DEFINES/time.dm b/code/__DEFINES/time.dm index 458a6f1a954..5632333ffab 100644 --- a/code/__DEFINES/time.dm +++ b/code/__DEFINES/time.dm @@ -48,10 +48,16 @@ When using time2text(), please use "DDD" to find the weekday. Refrain from using #define TICKS *world.tick_lag +#define MILLISECONDS * 0.10 + #define DS2TICKS(DS) ((DS)/world.tick_lag) #define TICKS2DS(T) ((T) TICKS) +#define MS2DS(T) ((T) MILLISECONDS) + +#define DS2MS(T) ((T) * 100) + /*Timezones*/ /// Line Islands Time diff --git a/code/controllers/configuration/entries/general.dm b/code/controllers/configuration/entries/general.dm index 3d7144efe05..93bf277bb16 100644 --- a/code/controllers/configuration/entries/general.dm +++ b/code/controllers/configuration/entries/general.dm @@ -514,3 +514,12 @@ /// URL for admins to be redirected to for 2FA /datum/config_entry/string/admin_2fa_url + +/datum/config_entry/number/hard_deletes_overrun_threshold + integer = FALSE + min_val = 0 + config_entry_value = 0.5 + +/datum/config_entry/number/hard_deletes_overrun_limit + config_entry_value = 0 + min_val = 0 diff --git a/code/controllers/subsystem/garbage.dm b/code/controllers/subsystem/garbage.dm index 21bba290d33..3659172fcc7 100644 --- a/code/controllers/subsystem/garbage.dm +++ b/code/controllers/subsystem/garbage.dm @@ -37,8 +37,8 @@ SUBSYSTEM_DEF(garbage) var/totaldels = 0 var/totalgcs = 0 - var/highest_del_time = 0 - var/highest_del_tickusage = 0 + var/highest_del_ms = 0 + var/highest_del_type_string = "" var/list/pass_counts var/list/fail_counts @@ -90,6 +90,8 @@ SUBSYSTEM_DEF(garbage) for(var/path in items) var/datum/qdel_item/I = items[path] dellog += "Path: [path]" + if (I.qdel_flags & QDEL_ITEM_SUSPENDED_FOR_LAG) + dellog += "\tSUSPENDED FOR LAG" if (I.failures) dellog += "\tFailures: [I.failures]" dellog += "\tqdel() Count: [I.qdels]" @@ -97,6 +99,9 @@ SUBSYSTEM_DEF(garbage) if (I.hard_deletes) dellog += "\tTotal Hard Deletes: [I.hard_deletes]" dellog += "\tTime Spent Hard Deleting: [I.hard_delete_time]ms" + dellog += "\tHighest Time Spent Hard Deleting: [I.hard_delete_max]ms" + if (I.hard_deletes_over_threshold) + dellog += "\tHard Deletes Over Threshold: [I.hard_deletes_over_threshold]" if (I.slept_destroy) dellog += "\tSleeps: [I.slept_destroy]" if (I.no_respect_force) @@ -200,6 +205,13 @@ SUBSYSTEM_DEF(garbage) to_chat(admin, "## TESTING: GC: -- [ADMIN_VV(D)] | [type] was unable to be GC'd --") #endif I.failures++ + + if (I.qdel_flags & QDEL_ITEM_SUSPENDED_FOR_LAG) + #ifdef REFERENCE_TRACKING + if(ref_searching) + return //ref searching intentionally cancels all further fires while running so things that hold references don't end up getting deleted, so we want to return here instead of continue + #endif + continue if (GC_QUEUE_HARDDELETE) HardDelete(D) if (MC_TICK_CHECK) @@ -235,52 +247,58 @@ SUBSYSTEM_DEF(garbage) //this is mainly to separate things profile wise. /datum/controller/subsystem/garbage/proc/HardDelete(datum/D) - var/time = world.timeofday - var/tick = TICK_USAGE - var/ticktime = world.time ++delslasttick ++totaldels var/type = D.type var/refID = "\ref[D]" + var/tick_usage = TICK_USAGE del(D) - - tick = (TICK_USAGE-tick+((world.time-ticktime)/world.tick_lag*100)) + tick_usage = TICK_USAGE_TO_MS(tick_usage) var/datum/qdel_item/I = items[type] - I.hard_deletes++ - I.hard_delete_time += TICK_DELTA_TO_MS(tick) + I.hard_delete_time += tick_usage + if (tick_usage > I.hard_delete_max) + I.hard_delete_max = tick_usage + if (tick_usage > highest_del_ms) + highest_del_ms = tick_usage + highest_del_type_string = "[type]" + var/time = MS2DS(tick_usage) - if (tick > highest_del_tickusage) - highest_del_tickusage = tick - time = world.timeofday - time - if (!time && TICK_DELTA_TO_MS(tick) > 1) - time = TICK_DELTA_TO_MS(tick)/100 - if (time > highest_del_time) - highest_del_time = time if (time > 0.1 SECONDS) - log_game("Error: [type]([refID]) took longer than 0.1 seconds to delete (took [time/10] seconds to delete)") - message_admins("Error: [type]([refID]) took longer than 0.1 seconds to delete (took [time/10] seconds to delete).") postpone(time) + var/threshold = CONFIG_GET(number/hard_deletes_overrun_threshold) + if (threshold && (time > threshold SECONDS)) + if (!(I.qdel_flags & QDEL_ITEM_ADMINS_WARNED)) + log_game("Error: [type]([refID]) took longer than [threshold] seconds to delete (took [round(time/10, 0.1)] seconds to delete)") + message_admins("Error: [type]([refID]) took longer than [threshold] seconds to delete (took [round(time/10, 0.1)] seconds to delete).") + I.qdel_flags |= QDEL_ITEM_ADMINS_WARNED + I.hard_deletes_over_threshold++ + var/overrun_limit = CONFIG_GET(number/hard_deletes_overrun_limit) + if (overrun_limit && I.hard_deletes_over_threshold >= overrun_limit) + I.qdel_flags |= QDEL_ITEM_SUSPENDED_FOR_LAG /datum/controller/subsystem/garbage/Recover() if (istype(SSgarbage.queues)) for (var/i in 1 to SSgarbage.queues.len) queues[i] |= SSgarbage.queues[i] - +/// Qdel Item: Holds statistics on each type that passes thru qdel /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 + var/name = "" //!Holds the type as a string for this type + 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/hard_delete_max = 0 //!Highest time spent hard_deleting this in ms. + var/hard_deletes_over_threshold = 0 //!Number of times hard deletes took longer than the configured threshold + 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 + var/qdel_flags = 0 //!Flags related to this type's trip thru qdel. /datum/qdel_item/New(mytype) name = "[mytype]" diff --git a/code/modules/admin/verbs/debug.dm b/code/modules/admin/verbs/debug.dm index 40572117f05..728ce320422 100644 --- a/code/modules/admin/verbs/debug.dm +++ b/code/modules/admin/verbs/debug.dm @@ -578,6 +578,8 @@ But you can call procs that are of type /mob/living/carbon/human/proc/ for that for(var/path in SSgarbage.items) var/datum/qdel_item/I = SSgarbage.items[path] dellog += "
  • [path]