Line by line profiling system

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

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

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

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]}"

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("<ol><li>[lines.Join("</li><li>")]</li></ol>", "window=[url_encode(GUID())]")

code/modules/admin/verbs/debug.dm

@@ -871,3 +871,42 @@ GLOBAL_PROTECT(LastAdminCalledProc)
 	message_admins("<span class='adminnotice'>[key_name_admin(src)] pumped a random event.</span>")
 	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("<span class='adminnotice'>[key_name_admin(src)] started line by line profiling.</span>")
+	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("<span class='adminnotice'>[key_name_admin(src)] stopped line by line profiling.</span>")
+	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)
+

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

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"