From cd7e358f52b78a7edf45c00823cc71c0a7cf2468 Mon Sep 17 00:00:00 2001 From: SkyratBot <59378654+SkyratBot@users.noreply.github.com> Date: Fri, 11 Jun 2021 01:02:39 +0200 Subject: [PATCH] Deep sendmaps profiling (#6237) Co-authored-by: LemonInTheDark <58055496+LemonInTheDark@users.noreply.github.com> Co-authored-by: Gandalf --- code/__DEFINES/_profile.dm | 2 +- code/_compile_options.dm | 4 ++ code/controllers/subsystem/profiler.dm | 40 ++++++++++++-- code/controllers/subsystem/time_track.dm | 70 ++++++++++++++++++++++++ code/modules/admin/admin_verbs.dm | 11 ++++ 5 files changed, 121 insertions(+), 6 deletions(-) diff --git a/code/__DEFINES/_profile.dm b/code/__DEFINES/_profile.dm index 41047b8b7ba..1a6a65cacb3 100644 --- a/code/__DEFINES/_profile.dm +++ b/code/__DEFINES/_profile.dm @@ -1,4 +1,4 @@ #if DM_BUILD >= 1506 // We don't actually care about storing the output here, this is just an easy way to ensure the profile runs first. -GLOBAL_REAL_VAR(world_init_profiler) = world.Profile(PROFILE_START) +GLOBAL_REAL_VAR(world_init_profiler) = world.Profile(PROFILE_RESTART) #endif diff --git a/code/_compile_options.dm b/code/_compile_options.dm index dc5221d1a78..e55746ee014 100644 --- a/code/_compile_options.dm +++ b/code/_compile_options.dm @@ -61,6 +61,10 @@ #if DM_VERSION < 514 && DM_BUILD < 1540 #define USE_EXTOOLS #endif +//Log the full sendmaps profile on 514.1556+, any earlier and we get bugs or it not existing +#if DM_VERSION >= 514 && DM_BUILD >= 1556 +#define SENDMAPS_PROFILE +#endif //Additional code for the above flags. #ifdef TESTING diff --git a/code/controllers/subsystem/profiler.dm b/code/controllers/subsystem/profiler.dm index d115c81b78c..337d606ed4e 100644 --- a/code/controllers/subsystem/profiler.dm +++ b/code/controllers/subsystem/profiler.dm @@ -1,5 +1,10 @@ #define PROFILER_FILENAME "profiler.json" +#ifdef SENDMAPS_PROFILE +#define SENDMAPS_FILENAME "sendmaps.json" +GLOBAL_REAL_VAR(world_init_maptick_profiler) = world.Profile(PROFILE_RESTART, type = "sendmaps") +#endif + SUBSYSTEM_DEF(profiler) name = "Profiler" init_order = INIT_ORDER_PROFILER @@ -27,6 +32,9 @@ SUBSYSTEM_DEF(profiler) /datum/controller/subsystem/profiler/Shutdown() if(CONFIG_GET(flag/auto_profile)) DumpFile() +#ifdef SENDMAPS_PROFILE + world.Profile(PROFILE_CLEAR, type = "sendmaps") +#endif return ..() /datum/controller/subsystem/profiler/proc/StartProfiling() @@ -35,11 +43,18 @@ SUBSYSTEM_DEF(profiler) CONFIG_SET(flag/auto_profile, FALSE) #else world.Profile(PROFILE_START) +#ifdef SENDMAPS_PROFILE + world.Profile(PROFILE_START, type = "sendmaps") +#endif + #endif /datum/controller/subsystem/profiler/proc/StopProfiling() #if DM_BUILD >= 1506 world.Profile(PROFILE_STOP) +#ifdef SENDMAPS_PROFILE + world.Profile(PROFILE_STOP, type = "sendmaps") +#endif #endif /datum/controller/subsystem/profiler/proc/DumpFile() @@ -48,15 +63,30 @@ SUBSYSTEM_DEF(profiler) CONFIG_SET(flag/auto_profile, FALSE) #else var/timer = TICK_USAGE_REAL - var/current_profile_data = world.Profile(PROFILE_REFRESH,format="json") + var/current_profile_data = world.Profile(PROFILE_REFRESH, format = "json") +#ifdef SENDMAPS_PROFILE + var/current_sendmaps_data = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json") +#endif 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.") - var/json_file = file("[GLOB.log_directory]/[PROFILER_FILENAME]") - if(fexists(json_file)) - fdel(json_file) + var/prof_file = file("[GLOB.log_directory]/[PROFILER_FILENAME]") + if(fexists(prof_file)) + fdel(prof_file) +#ifdef SENDMAPS_PROFILE + 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 = file("[GLOB.log_directory]/[SENDMAPS_FILENAME]") + if(fexists(sendmaps_file)) + fdel(sendmaps_file) +#endif + timer = TICK_USAGE_REAL - WRITE_FILE(json_file, current_profile_data) + WRITE_FILE(prof_file, current_profile_data) +#ifdef SENDMAPS_PROFILE + WRITE_FILE(sendmaps_file, current_sendmaps_data) +#endif write_cost = MC_AVERAGE(write_cost, TICK_DELTA_TO_MS(TICK_USAGE_REAL - timer)) #endif diff --git a/code/controllers/subsystem/time_track.dm b/code/controllers/subsystem/time_track.dm index a0c7ef7867a..12814be757e 100644 --- a/code/controllers/subsystem/time_track.dm +++ b/code/controllers/subsystem/time_track.dm @@ -15,10 +15,45 @@ SUBSYSTEM_DEF(time_track) var/last_tick_realtime = 0 var/last_tick_byond_time = 0 var/last_tick_tickcount = 0 +#ifdef SENDMAPS_PROFILE + var/list/sendmaps_names_map = list( + "SendMaps" = "send_maps", + "SendMaps: Initial housekeeping" = "initial_house", + "SendMaps: Cleanup" = "cleanup", + "SendMaps: Client loop" = "client_loop", + "SendMaps: Per client" = "per_client", + "SendMaps: Per client: Deleted images" = "deleted_images", + "SendMaps: Per client: HUD update" = "hud_update", + "SendMaps: Per client: Statpanel update" = "statpanel_update", + "SendMaps: Per client: Map data" = "map_data", + "SendMaps: Per client: Map data: Check eye position" = "check_eye_pos", + "SendMaps: Per client: Map data: Update chunks" = "update_chunks", + "SendMaps: Per client: Map data: Send turfmap updates" = "turfmap_updates", + "SendMaps: Per client: Map data: Send changed turfs" = "changed_turfs", + "SendMaps: Per client: Map data: Send turf chunk info" = "turf_chunk_info", + "SendMaps: Per client: Map data: Send obj changes" = "obj_changes", + "SendMaps: Per client: Map data: Send mob changes" = "mob_changes", + "SendMaps: Per client: Map data: Send notable turf visual contents" = "send_turf_vis_conts", + "SendMaps: Per client: Map data: Send pending animations" = "pending_animations", + "SendMaps: Per client: Map data: Look for movable changes" = "look_for_movable_changes", + "SendMaps: Per client: Map data: Look for movable changes: Check notable turf visual contents" = "check_turf_vis_conts", + "SendMaps: Per client: Map data: Look for movable changes: Check HUD/image visual contents" = "check_hud/image_vis_contents", + "SendMaps: Per client: Map data: Look for movable changes: Loop through turfs in range" = "turfs_in_range", + "SendMaps: Per client: Map data: Look for movable changes: Movables examined" = "movables_examined", + ) +#endif /datum/controller/subsystem/time_track/Initialize(start_timeofday) . = ..() GLOB.perf_log = "[GLOB.log_directory]/perf-[GLOB.round_id ? GLOB.round_id : "NULL"]-[SSmapping.config?.map_name].csv" +#ifdef SENDMAPS_PROFILE + world.Profile(PROFILE_RESTART, type = "sendmaps") + //Need to do the sendmaps stuff in its own file, since it works different then everything else + var/list/sendmaps_shorthands = list() + for(var/proper_name in sendmaps_names_map) + sendmaps_shorthands += sendmaps_names_map[proper_name] + sendmaps_shorthands += "[sendmaps_names_map[proper_name]]_count" +#endif log_perf( list( "time", @@ -42,7 +77,11 @@ SUBSYSTEM_DEF(time_track) "air_network_count", "air_delta_count", "air_superconductive_count" +#ifdef SENDMAPS_PROFILE + ) + sendmaps_shorthands +#else ) +#endif ) /datum/controller/subsystem/time_track/fire() @@ -65,6 +104,21 @@ SUBSYSTEM_DEF(time_track) last_tick_realtime = current_realtime last_tick_byond_time = current_byondtime last_tick_tickcount = current_tickcount + +#ifdef SENDMAPS_PROFILE + var/sendmaps_json = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json") + var/list/send_maps_data = json_decode(sendmaps_json) + var/send_maps_sort = send_maps_data.Copy() //Doing it like this guarentees us a properly sorted list + + for(var/list/packet in send_maps_data) + send_maps_sort[packet["name"]] = packet + + var/list/send_maps_values = list() + for(var/list/packet in send_maps_sort) + send_maps_values += packet["value"] + send_maps_values += packet["calls"] +#endif + SSblackbox.record_feedback("associative", "time_dilation_current", 1, list("[SQLtime()]" = list("current" = "[time_dilation_current]", "avg_fast" = "[time_dilation_avg_fast]", "avg" = "[time_dilation_avg]", "avg_slow" = "[time_dilation_avg_slow]"))) log_perf( list( @@ -89,5 +143,21 @@ SUBSYSTEM_DEF(time_track) length(SSair.networks), length(SSair.high_pressure_delta), length(SSair.active_super_conductivity) +#ifdef SENDMAPS_PROFILE + ) + send_maps_values +#else ) +#endif ) + +#ifdef SENDMAPS_PROFILE +/datum/controller/subsystem/time_track/proc/scream_maptick_data() + var/current_profile_data = world.Profile(PROFILE_REFRESH, type = "sendmaps", format="json") + log_world(current_profile_data) + current_profile_data = json_decode(current_profile_data) + var/output = "" + for(var/list/entry in current_profile_data) + output += "[entry["name"]],[entry["value"]],[entry["calls"]]\n" + log_world(output) + return output +#endif diff --git a/code/modules/admin/admin_verbs.dm b/code/modules/admin/admin_verbs.dm index cff1152dd8e..cb320e0faf0 100644 --- a/code/modules/admin/admin_verbs.dm +++ b/code/modules/admin/admin_verbs.dm @@ -197,6 +197,9 @@ GLOBAL_PROTECT(admin_verbs_debug) /client/proc/export_dynamic_json, /client/proc/run_dynamic_simulations, #endif + #ifdef SENDMAPS_PROFILE + /client/proc/display_sendmaps, + #endif /datum/admins/proc/create_or_modify_area, /client/proc/check_timer_sources, /client/proc/toggle_cdn, @@ -825,3 +828,11 @@ GLOBAL_PROTECT(admin_verbs_hideable) var/datum/admins/admin = GLOB.admin_datums[ckey] admin?.associate(src) + +#ifdef SENDMAPS_PROFILE +/client/proc/display_sendmaps() + set name = "Send Maps Profile" + set category = "Debug" + + src << link("?debug=profile&type=sendmaps&window=test") +#endif