From f36d3ff08a148eadbcf4254397c1ea138d3b0575 Mon Sep 17 00:00:00 2001 From: Jordan Brown Date: Fri, 27 Oct 2017 14:09:50 -0400 Subject: [PATCH 1/2] Line by line profiling system --- code/__DEFINES/math.dm | 2 ++ code/__DEFINES/profile.dm | 29 +++++++++++++++++++++ code/__HELPERS/cmp.dm | 12 +++++++++ code/__HELPERS/unsorted.dm | 18 +++++++++++++ code/datums/profiling.dm | 18 +++++++++++++ code/modules/admin/verbs/debug.dm | 39 +++++++++++++++++++++++++++++ code/modules/admin/verbs/mapping.dm | 5 +++- tgstation.dme | 2 ++ 8 files changed, 124 insertions(+), 1 deletion(-) create mode 100644 code/__DEFINES/profile.dm create mode 100644 code/datums/profiling.dm diff --git a/code/__DEFINES/math.dm b/code/__DEFINES/math.dm index 534e0d3608..5b3f51b4e3 100644 --- a/code/__DEFINES/math.dm +++ b/code/__DEFINES/math.dm @@ -10,6 +10,8 @@ #define T20C 293.15 // 20degC #define TCMB 2.7 // -270.3degC +#define SHORT_REAL_LIMIT 16777216 + //"fancy" math for calculating time in ms from tick_usage percentage and the length of ticks //percent_of_tick_used * (ticklag * 100(to convert to ms)) / 100(percent ratio) //collapsed to percent_of_tick_used * tick_lag diff --git a/code/__DEFINES/profile.dm b/code/__DEFINES/profile.dm new file mode 100644 index 0000000000..28fc7782ce --- /dev/null +++ b/code/__DEFINES/profile.dm @@ -0,0 +1,29 @@ +#define PROFILE_START ;PROFILE_STORE = list();PROFILE_SET; +#define PROFILE_STOP ;PROFILE_STORE = null; + +#define PROFILE_SET ;PROFILE_TIME = TICK_USAGE_REAL; PROFILE_LINE = __LINE__; PROFILE_FILE = __FILE__; PROFILE_SLEEPCHECK = world.time; + +#define PROFILE_TICK ;\ + if (PROFILE_STORE) {\ + var/PROFILE_TICK_USAGE_REAL = TICK_USAGE_REAL;\ + if (PROFILE_SLEEPCHECK == world.time) {\ + var/PROFILE_STRING = "[PROFILE_FILE]:[PROFILE_LINE] - [__FILE__]:[__LINE__]";\ + var/list/PROFILE_ITEM = PROFILE_STORE[PROFILE_STRING];\ + if (!PROFILE_ITEM) {\ + PROFILE_ITEM = new(PROFILE_ITEM_LEN);\ + PROFILE_STORE[PROFILE_STRING] = PROFILE_ITEM;\ + PROFILE_ITEM[PROFILE_ITEM_TIME] = 0;\ + PROFILE_ITEM[PROFILE_ITEM_COUNT] = 0;\ + };\ + PROFILE_ITEM[PROFILE_ITEM_TIME] += TICK_DELTA_TO_MS(PROFILE_TICK_USAGE_REAL-PROFILE_TIME);\ + var/PROFILE_INCR_AMOUNT = min(1, 2**round(PROFILE_ITEM[PROFILE_ITEM_COUNT]/SHORT_REAL_LIMIT));\ + if (prob(100/PROFILE_INCR_AMOUNT)) {\ + PROFILE_ITEM[PROFILE_ITEM_COUNT] += PROFILE_INCR_AMOUNT;\ + };\ + };\ + PROFILE_SET;\ + }; + +#define PROFILE_ITEM_LEN 2 +#define PROFILE_ITEM_TIME 1 +#define PROFILE_ITEM_COUNT 2 \ No newline at end of file diff --git a/code/__HELPERS/cmp.dm b/code/__HELPERS/cmp.dm index 1c9c33f21a..d4ec1651a1 100644 --- a/code/__HELPERS/cmp.dm +++ b/code/__HELPERS/cmp.dm @@ -58,3 +58,15 @@ GLOBAL_VAR_INIT(cmp_field, "name") . = B.failures - A.failures if (!.) . = B.qdels - A.qdels +<<<<<<< HEAD +======= + +/proc/cmp_profile_avg_time_dsc(list/A, list/B) + return (B[PROFILE_ITEM_TIME]/(B[PROFILE_ITEM_COUNT] || 1)) - (A[PROFILE_ITEM_TIME]/(A[PROFILE_ITEM_COUNT] || 1)) + +/proc/cmp_profile_time_dsc(list/A, list/B) + return B[PROFILE_ITEM_TIME] - A[PROFILE_ITEM_TIME] + +/proc/cmp_profile_count_dsc(list/A, list/B) + return B[PROFILE_ITEM_COUNT] - A[PROFILE_ITEM_COUNT] +>>>>>>> bf06d69... Merge pull request #32116 from MrStonedOne/line-by-line-profiling diff --git a/code/__HELPERS/unsorted.dm b/code/__HELPERS/unsorted.dm index 4a9588a685..c9b392ed76 100644 --- a/code/__HELPERS/unsorted.dm +++ b/code/__HELPERS/unsorted.dm @@ -1411,3 +1411,21 @@ GLOBAL_DATUM_INIT(dview_mob, /mob/dview, new) //checks if a turf is in the planet z list. /proc/turf_z_is_planet(turf/T) return GLOB.z_is_planet["[T.z]"] + +//returns a GUID like identifier (using a mostly made up record format) +//guids are not on their own suitable for access or security tokens, as most of their bits are predictable. +// (But may make a nice salt to one) +/proc/GUID() + var/const/GUID_VERSION = "b" + var/const/GUID_VARIANT = "d" + var/node_id = copytext(md5("[rand()*rand(1,9999999)][world.name][world.hub][world.hub_password][world.internet_address][world.address][world.contents.len][world.status][world.port][rand()*rand(1,9999999)]"), 1, 13) + + var/time_high = "[num2hex(text2num(time2text(world.realtime,"YYYY")), 2)][num2hex(world.realtime, 6)]" + + var/time_mid = num2hex(world.timeofday, 4) + + var/time_low = num2hex(world.time, 3) + + var/time_clock = num2hex(TICK_DELTA_TO_MS(world.tick_usage), 3) + + return "{[time_high]-[time_mid]-[GUID_VERSION][time_low]-[GUID_VARIANT][time_clock]-[node_id]}" \ No newline at end of file diff --git a/code/datums/profiling.dm b/code/datums/profiling.dm new file mode 100644 index 0000000000..49a80d0ede --- /dev/null +++ b/code/datums/profiling.dm @@ -0,0 +1,18 @@ +//these are real globals so you can use profiling to profile early world init stuff. +GLOBAL_REAL_VAR(list/PROFILE_STORE) +GLOBAL_REAL_VAR(PROFILE_LINE) +GLOBAL_REAL_VAR(PROFILE_FILE) +GLOBAL_REAL_VAR(PROFILE_SLEEPCHECK) +GLOBAL_REAL_VAR(PROFILE_TIME) + + +/proc/profile_show(user, sort = /proc/cmp_profile_avg_time_dsc) + sortTim(PROFILE_STORE, sort, TRUE) + + var/list/lines = list() + + for (var/entry in PROFILE_STORE) + var/list/data = PROFILE_STORE[entry] + lines += "[entry] => [num2text(data[PROFILE_ITEM_TIME], 10)]ms ([data[PROFILE_ITEM_COUNT]]) (avg:[num2text(data[PROFILE_ITEM_TIME]/(data[PROFILE_ITEM_COUNT] || 1), 99)])" + + user << browse("
  1. [lines.Join("
  2. ")]
", "window=[url_encode(GUID())]") diff --git a/code/modules/admin/verbs/debug.dm b/code/modules/admin/verbs/debug.dm index 980dfd0a59..853344cc25 100644 --- a/code/modules/admin/verbs/debug.dm +++ b/code/modules/admin/verbs/debug.dm @@ -871,3 +871,42 @@ GLOBAL_PROTECT(LastAdminCalledProc) message_admins("[key_name_admin(src)] pumped a random event.") SSblackbox.add_details("admin_verb","Pump Random Event") log_admin("[key_name(src)] pumped a random event.") + +/client/proc/start_line_profiling() + set category = "Profile" + set name = "Start Line Profiling" + set desc = "Starts tracking line by line profiling for code lines that support it" + + PROFILE_START + + message_admins("[key_name_admin(src)] started line by line profiling.") + SSblackbox.add_details("admin_verb","Start Line Profiling") + log_admin("[key_name(src)] started line by line profiling.") + +/client/proc/stop_line_profiling() + set category = "Profile" + set name = "Stops Line Profiling" + set desc = "Stops tracking line by line profiling for code lines that support it" + + PROFILE_STOP + + message_admins("[key_name_admin(src)] stopped line by line profiling.") + SSblackbox.add_details("admin_verb","stop Line Profiling") + log_admin("[key_name(src)] stopped line by line profiling.") + +/client/proc/show_line_profiling() + set category = "Profile" + set name = "Show Line Profiling" + set desc = "Shows tracked profiling info from code lines that support it" + + var/sortlist = list( + "Avg time" = /proc/cmp_profile_avg_time_dsc, + "Total Time" = /proc/cmp_profile_time_dsc, + "Call Count" = /proc/cmp_profile_count_dsc + ) + var/sort = input(src, "Sort type?", "Sort Type", "Avg time") as null|anything in sortlist + if (!sort) + return + sort = sortlist[sort] + profile_show(src, sort) + diff --git a/code/modules/admin/verbs/mapping.dm b/code/modules/admin/verbs/mapping.dm index 3ceb1aeb75..d560099563 100644 --- a/code/modules/admin/verbs/mapping.dm +++ b/code/modules/admin/verbs/mapping.dm @@ -42,7 +42,10 @@ GLOBAL_LIST_INIT(admin_verbs_debug_mapping, list( /client/proc/print_pointers, /client/proc/cmd_show_at_list, /client/proc/cmd_show_at_markers, - /client/proc/manipulate_organs + /client/proc/manipulate_organs, + /client/proc/start_line_profiling, + /client/proc/stop_line_profiling, + /client/proc/show_line_profiling )) /obj/effect/debugging/mapfix_marker diff --git a/tgstation.dme b/tgstation.dme index 912f3cc89e..74d470b907 100755 --- a/tgstation.dme +++ b/tgstation.dme @@ -61,6 +61,7 @@ #include "code\__DEFINES\pinpointers.dm" #include "code\__DEFINES\pipe_construction.dm" #include "code\__DEFINES\preferences.dm" +#include "code\__DEFINES\profile.dm" #include "code\__DEFINES\qdel.dm" #include "code\__DEFINES\radiation.dm" #include "code\__DEFINES\radio.dm" @@ -288,6 +289,7 @@ #include "code\datums\mutable_appearance.dm" #include "code\datums\mutations.dm" #include "code\datums\outfit.dm" +#include "code\datums\profiling.dm" #include "code\datums\progressbar.dm" #include "code\datums\radiation_wave.dm" #include "code\datums\recipe.dm" From 7ffe1b4e233860ac662b08f85ff565393d7df0bf Mon Sep 17 00:00:00 2001 From: LetterJay Date: Fri, 27 Oct 2017 23:55:23 -0500 Subject: [PATCH 2/2] Update cmp.dm --- code/__HELPERS/cmp.dm | 3 --- 1 file changed, 3 deletions(-) diff --git a/code/__HELPERS/cmp.dm b/code/__HELPERS/cmp.dm index d4ec1651a1..dbb548a6a5 100644 --- a/code/__HELPERS/cmp.dm +++ b/code/__HELPERS/cmp.dm @@ -58,8 +58,6 @@ GLOBAL_VAR_INIT(cmp_field, "name") . = B.failures - A.failures if (!.) . = B.qdels - A.qdels -<<<<<<< HEAD -======= /proc/cmp_profile_avg_time_dsc(list/A, list/B) return (B[PROFILE_ITEM_TIME]/(B[PROFILE_ITEM_COUNT] || 1)) - (A[PROFILE_ITEM_TIME]/(A[PROFILE_ITEM_COUNT] || 1)) @@ -69,4 +67,3 @@ GLOBAL_VAR_INIT(cmp_field, "name") /proc/cmp_profile_count_dsc(list/A, list/B) return B[PROFILE_ITEM_COUNT] - A[PROFILE_ITEM_COUNT] ->>>>>>> bf06d69... Merge pull request #32116 from MrStonedOne/line-by-line-profiling