Deep sendmaps profiling (#6237)

Co-authored-by: LemonInTheDark <58055496+LemonInTheDark@users.noreply.github.com>
Co-authored-by: Gandalf <jzo123@hotmail.com>
This commit is contained in:
SkyratBot
2021-06-11 00:02:39 +01:00
committed by GitHub
co-authored by LemonInTheDark Gandalf
parent b8c9d5e79b
commit cd7e358f52
5 changed files with 121 additions and 6 deletions
+35 -5
View File
@@ -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
+70
View File
@@ -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