From d8708cbada0b77ee6880618921386e84fde06349 Mon Sep 17 00:00:00 2001
From: Lucy <lucy@absolucy.moe>
Date: Fri, 27 Sep 2024 17:30:02 -0400
Subject: [PATCH] Profiler logs now sort by overtime and have a proper
 timestamp in the filename

---
 code/__HELPERS/~monkestation-helpers/cmp.dm   |  4 ++
 code/controllers/subsystem/init_profiler.dm   |  2 +
 code/controllers/subsystem/profiler.dm        |  5 ++-
 monkestation/code/__HELPERS/files.dm          |  2 +-
 .../controllers/subsystem/init_profiler.dm    | 28 +++++++++++++
 .../code/controllers/subsystem/profiler.dm    | 42 +++++++++++++++++++
 tgstation.dme                                 |  2 +
 7 files changed, 83 insertions(+), 2 deletions(-)
 create mode 100644 monkestation/code/controllers/subsystem/init_profiler.dm
 create mode 100644 monkestation/code/controllers/subsystem/profiler.dm

diff --git a/code/__HELPERS/~monkestation-helpers/cmp.dm b/code/__HELPERS/~monkestation-helpers/cmp.dm
index c87af6cd5202..d7f322409e96 100644
--- a/code/__HELPERS/~monkestation-helpers/cmp.dm
+++ b/code/__HELPERS/~monkestation-helpers/cmp.dm
@@ -8,3 +8,7 @@
 /// Use when you want a list of most to least severe wounds.
 /proc/cmp_wound_severity_dsc(datum/wound/a, datum/wound/b)
 	return cmp_numeric_dsc(a.severity, b.severity)
+
+/// Used to sort overtime in profiling data.
+/proc/sort_overtime_dsc(list/a, list/b)
+	return b["over"] - a["over"]
diff --git a/code/controllers/subsystem/init_profiler.dm b/code/controllers/subsystem/init_profiler.dm
index 063898b6a098..1d1eed74cb46 100644
--- a/code/controllers/subsystem/init_profiler.dm
+++ b/code/controllers/subsystem/init_profiler.dm
@@ -1,3 +1,4 @@
+/* monkestation edit: reimplemented in [monkestation\code\controllers\subsystem\init_profiler.dm]
 #define INIT_PROFILE_NAME "init_profiler.json"
 
 ///Subsystem exists so we can separately log init time costs from the costs of general operation
@@ -26,3 +27,4 @@ SUBSYSTEM_DEF(init_profiler)
 	world.Profile(PROFILE_CLEAR) //Now that we're written this data out, dump it. We don't want it getting mixed up with our current round data
 
 #undef INIT_PROFILE_NAME
+monkestation end */
diff --git a/code/controllers/subsystem/profiler.dm b/code/controllers/subsystem/profiler.dm
index 629590d75ebb..c936cdc3993c 100644
--- a/code/controllers/subsystem/profiler.dm
+++ b/code/controllers/subsystem/profiler.dm
@@ -6,10 +6,12 @@ SUBSYSTEM_DEF(profiler)
 	var/fetch_cost = 0
 	var/write_cost = 0
 
+/* monkestation edit: reimplemented in [monkestation\code\controllers\subsystem\profiler.dm]
 /datum/controller/subsystem/profiler/stat_entry(msg)
 	msg += "F:[round(fetch_cost,1)]ms"
 	msg += "|W:[round(write_cost,1)]ms"
 	return msg
+monkestation end */
 
 /datum/controller/subsystem/profiler/Initialize()
 	if(CONFIG_GET(flag/auto_profile))
@@ -37,6 +39,7 @@ SUBSYSTEM_DEF(profiler)
 	world.Profile(PROFILE_STOP, type = "sendmaps")
 
 
+/* monkestation edit: reimplemented in [monkestation\code\controllers\subsystem\profiler.dm]
 /datum/controller/subsystem/profiler/proc/DumpFile()
 	var/timer = TICK_USAGE_REAL
 	var/current_profile_data = world.Profile(PROFILE_REFRESH, format = "json")
@@ -59,4 +62,4 @@ SUBSYSTEM_DEF(profiler)
 	WRITE_FILE(prof_file, current_profile_data)
 	WRITE_FILE(sendmaps_file, current_sendmaps_data)
 	write_cost = MC_AVERAGE(write_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
-
+monkestation end */
diff --git a/monkestation/code/__HELPERS/files.dm b/monkestation/code/__HELPERS/files.dm
index ead24af1cd4e..998c4391c8eb 100644
--- a/monkestation/code/__HELPERS/files.dm
+++ b/monkestation/code/__HELPERS/files.dm
@@ -3,7 +3,7 @@
 	var/regex/whitelist_regex
 	if(whitelist)
 		// try not to look at it too hard. yes i wrote this by hand.
-		whitelist_regex = new("(?:\[\\/\\\\\]$|(?:^|\\\\|\\/)(?:[regex_quote_list(whitelist)]|(?:profiler|sendmaps)-\[0-9\]+)\\.(?:[regex_quote_list(valid_extensions)])$)", "i")
+		whitelist_regex = new("(?:\[\\/\\\\\]$|(?:^|\\\\|\\/)(?:[regex_quote_list(whitelist)]|(?:profiler|sendmaps)-\[0-9_\\-\]+)\\.(?:[regex_quote_list(valid_extensions)])$)", "i")
 
 	// wow why was this ever a parameter
 	var/root = "data/logs/"
diff --git a/monkestation/code/controllers/subsystem/init_profiler.dm b/monkestation/code/controllers/subsystem/init_profiler.dm
new file mode 100644
index 000000000000..a17025be41a2
--- /dev/null
+++ b/monkestation/code/controllers/subsystem/init_profiler.dm
@@ -0,0 +1,28 @@
+#define INIT_PROFILE_NAME "init_profiler.json"
+
+///Subsystem exists so we can separately log init time costs from the costs of general operation
+///Hopefully this makes sorting out what causes problems when easier
+SUBSYSTEM_DEF(init_profiler)
+	name = "Init Profiler"
+	init_order = INIT_ORDER_INIT_PROFILER
+	init_stage = INITSTAGE_MAX
+	flags = SS_NO_FIRE
+
+/datum/controller/subsystem/init_profiler/Initialize()
+	if(CONFIG_GET(flag/auto_profile))
+		write_init_profile()
+		return SS_INIT_SUCCESS
+	return SS_INIT_NO_NEED
+
+/datum/controller/subsystem/init_profiler/proc/write_init_profile()
+	var/list/current_profile_data = world.Profile(PROFILE_REFRESH, format = "json")
+	current_profile_data = json_decode(current_profile_data) // yes this is stupid but this gets us a list in a non-awful format
+	CHECK_TICK
+	sortTim(current_profile_data, GLOBAL_PROC_REF(sort_overtime_dsc))
+
+	if(!length(current_profile_data)) //Would be nice to have explicit proc to check this
+		stack_trace("Warning, profiling stopped manually before dump.")
+	rustg_file_write(json_encode(current_profile_data), "[GLOB.log_directory]/[INIT_PROFILE_NAME]")
+	world.Profile(PROFILE_CLEAR) //Now that we're written this data out, dump it. We don't want it getting mixed up with our current round data
+
+#undef INIT_PROFILE_NAME
diff --git a/monkestation/code/controllers/subsystem/profiler.dm b/monkestation/code/controllers/subsystem/profiler.dm
new file mode 100644
index 000000000000..f3445536588d
--- /dev/null
+++ b/monkestation/code/controllers/subsystem/profiler.dm
@@ -0,0 +1,42 @@
+/datum/controller/subsystem/profiler
+	var/sort_cost = 0
+
+/datum/controller/subsystem/profiler/stat_entry(msg)
+	msg += "F:[round(fetch_cost, 1)]ms"
+	msg += "|S:[round(sort_cost, 1)]ms"
+	msg += "|W:[round(write_cost, 1)]ms"
+	return msg
+
+/datum/controller/subsystem/profiler/proc/DumpFile()
+	var/timer = TICK_USAGE_REAL
+	var/list/current_profile_data = world.Profile(PROFILE_REFRESH, format = "json")
+	current_profile_data = json_decode(current_profile_data) // yes this is stupid but this gets us a list in a non-awful format
+	var/current_sendmaps_data = world.Profile(PROFILE_REFRESH, type = "sendmaps", format = "json")
+	fetch_cost = MC_AVERAGE(fetch_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
+	CHECK_TICK
+
+	if(!length(current_profile_data)) //Would be nice to have explicit proc to check this
+		stack_trace("Warning, profiling stopped manually before dump.")
+
+	timer = TICK_USAGE_REAL
+	sortTim(current_profile_data, GLOBAL_PROC_REF(sort_overtime_dsc))
+	sort_cost = MC_AVERAGE(sort_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
+
+	var/timestamp = time2text(world.timeofday, "YYYY-MM-DD_hh-mm-ss")
+	var/prof_file = "[GLOB.log_directory]/profiler/profiler-[timestamp].json"
+	if(!length(current_sendmaps_data)) //Would be nice to have explicit proc to check this
+		stack_trace("Warning, sendmaps profiling stopped manually before dump.")
+	var/sendmaps_file = "[GLOB.log_directory]/profiler/sendmaps-[timestamp].json"
+
+	timer = TICK_USAGE_REAL
+	rustg_file_write(json_encode(current_profile_data), prof_file)
+	rustg_file_write(current_sendmaps_data, sendmaps_file)
+	write_cost = MC_AVERAGE(write_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer))
+
+/datum/controller/subsystem/profiler/get_metrics()
+	. = ..()
+	.["custom"] = list(
+		"fetch_cost" = fetch_cost,
+		"sort_cost" = sort_cost,
+		"write_cost" = write_cost,
+	)
diff --git a/tgstation.dme b/tgstation.dme
index 78cad90c04f4..e8ad085af035 100644
--- a/tgstation.dme
+++ b/tgstation.dme
@@ -5810,7 +5810,9 @@
 #include "monkestation\code\controllers\subsystem\autotransfer.dm"
 #include "monkestation\code\controllers\subsystem\economy.dm"
 #include "monkestation\code\controllers\subsystem\glowshroom.dm"
+#include "monkestation\code\controllers\subsystem\init_profiler.dm"
 #include "monkestation\code\controllers\subsystem\job.dm"
+#include "monkestation\code\controllers\subsystem\profiler.dm"
 #include "monkestation\code\datums\action.dm"
 #include "monkestation\code\datums\dna.dm"
 #include "monkestation\code\datums\emotes.dm"