Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Profiler logs now sort by overtime and have a proper timestamp in the filename #3588

Merged
merged 1 commit into from
Sep 28, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions code/__HELPERS/~monkestation-helpers/cmp.dm
Original file line number Diff line number Diff line change
Expand Up @@ -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"]
2 changes: 2 additions & 0 deletions code/controllers/subsystem/init_profiler.dm
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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 */
5 changes: 4 additions & 1 deletion code/controllers/subsystem/profiler.dm
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down Expand Up @@ -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")
Expand All @@ -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 */
2 changes: 1 addition & 1 deletion monkestation/code/__HELPERS/files.dm
Original file line number Diff line number Diff line change
Expand Up @@ -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/"
Expand Down
28 changes: 28 additions & 0 deletions monkestation/code/controllers/subsystem/init_profiler.dm
Original file line number Diff line number Diff line change
@@ -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
42 changes: 42 additions & 0 deletions monkestation/code/controllers/subsystem/profiler.dm
Original file line number Diff line number Diff line change
@@ -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,
)
2 changes: 2 additions & 0 deletions tgstation.dme
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
Loading