extends Node
## HITCH LOGGER (hyper-games #93 §2). ashatron (GTX 1060) shows 210-613 ms frames
## only while terrain chunks mesh or upload -- but not in every such window, and
## the [MountainStats] line cannot say where the time went: its numbers are one
## sample per 2 s, and its "worst" is the CLAMPED process step (135 ms printed for
## a 4117 ms frame). This times EVERY frame by phase and writes the long ones down
## with what else happened in them.
##
## A frame is split, in Main::iteration's own order, into:
## physics -- SceneTree physics_frame signal -> the last _physics_process
## (the end bracket runs at the highest physics priority), per
## physics step: scripts and coroutines awaiting physics_frame
## physics_engine -- from there to the next step / process_frame: the physics
## server step (Jolt), its sync, timers, tweens, deletes
## process -- SceneTree process_frame signal -> RenderingServer
## frame_pre_draw: ALL of SceneTree::process -- coroutines on
## process_frame, deferred calls, every _process, timers,
## tweens. DCTerrain's uploads, re-trims and seams run here.
## scripts_ms is the _process part alone (bracketed by the
## lowest and highest process priority).
## draw -- frame_pre_draw -> frame_post_draw: culling, command
## recording, and any wait for the GPU / swapchain
## other -- the rest of the wall time (input, navigation, the frame
## pacing sleep)
## For each frame it also keeps: DCTerrain's own phase split (get_frame_stats),
## main-thread CPU time vs wall (descheduled = wall >> cpu), page faults
## (/proc/self/stat; a major fault is a disk read, e.g. a .pck the update deleted),
## nodes added, video memory and draw calls.
##
## A HITCH is a frame longer than HITCH_MIN_MS AND MEDIAN_FACTOR x the median of
## the last RING frames. Each one is a JSON line in log_path (with the three
## frames before it) and a one-line "[HITCH]" on stdout. Every SUMMARY_S seconds a
## "[HITCH] summary" line gives the frame-time distribution. HTPS_HITCHLOG=0 turns
## it off.
const HITCH_MIN_MS := 100.0
const MEDIAN_FACTOR := 3.0
const RING := 120
const KEEP := 50 # hitch records kept in memory (get_hitches)
const SUMMARY_S := 10.0
const BEFORE := 3 # frames recorded before each hitch
const PRIO := 1 << 30 # lowest / highest process priority
var log_path := "user://hitches.log"
var _file: FileAccess = null
var _end: Node = null
var _hitches: Array[Dictionary] = []
var _walls := PackedFloat32Array()
var _ring_i := 0
var _recent: Array[Dictionary] = [] # the last BEFORE frames, compact
var _summary_walls := PackedFloat32Array()
var _summary_t0 := 0
var _summary_hitches := 0
# Per-frame accumulators (usec).
var _frame_t0 := 0
var _phys_us := 0
var _phys_start := 0
var _phys_end := 0 # end of the latest step's scripts; the engine step follows
var _phys_engine_us := 0
var _proc_frame_t := 0 # process_frame signal
var _scripts_start := 0
var _scripts_us := 0
var _draw_start := 0
var _nodes_added := 0
var _cpu0 := -1
var _stat0 := PackedInt64Array()
var _terrain: Node = null
var _terrain_scan_t := 0
# dc-terrain GPU-thread submits (get_frame_stats gpu_submit_*): the slowest one
# over the last GPU_RECENT frames, for the [HITCH] line -- a job that stalls the
# frame can finish, and be counted, a frame either side of it -- and over the
# summary window.
const GPU_RECENT := 4
var _gpu_recent: Array[Dictionary] = []
var _summary_gpu_max := 0.0
var _summary_gpu_worst := ""
var _summary_gpu_submits := 0
var _saw_draw := false
func _init() -> void:
name = "HitchLog"
process_priority = -PRIO
process_physics_priority = -PRIO
func _ready() -> void:
_end = Node.new()
_end.name = "HitchLogEnd"
_end.process_priority = PRIO
_end.process_physics_priority = PRIO
_end.set_script(_EndScript)
add_child(_end)
_file = FileAccess.open(log_path, FileAccess.WRITE)
get_tree().node_added.connect(_on_node_added)
# Connected now, i.e. before anything a script connects later: process_frame
# and physics_frame resume coroutines in connection order.
get_tree().physics_frame.connect(_on_physics_frame)
get_tree().process_frame.connect(_on_process_frame)
RenderingServer.frame_pre_draw.connect(_on_pre_draw)
RenderingServer.frame_post_draw.connect(_on_post_draw)
var vp := get_viewport()
if vp != null:
RenderingServer.viewport_set_measure_render_time(vp.get_viewport_rid(), true)
_walls.resize(RING)
_walls.fill(0.0)
_summary_t0 = Time.get_ticks_usec()
_frame_t0 = _summary_t0
_stat0 = _read_stat()
_write({"type": "session", "time": Time.get_datetime_string_from_system(),
"os": OS.get_name(), "cpu": OS.get_processor_name(), "cpus": OS.get_processor_count(),
"gpu": RenderingServer.get_video_adapter_name(),
"driver": RenderingServer.get_video_adapter_api_version(),
"settings": _settings(), "hitch_min_ms": HITCH_MIN_MS, "median_factor": MEDIAN_FACTOR})
## The last KEEP hitch records, oldest first.
func get_hitches() -> Array[Dictionary]:
return _hitches
## The engine's physics step runs between one step's scripts and the next marker.
func _close_physics_engine(now: int) -> void:
if _phys_end != 0:
_phys_engine_us += now - _phys_end
_phys_end = 0
func _on_physics_frame() -> void:
var now := Time.get_ticks_usec()
_close_physics_engine(now)
_phys_start = now
func _end_physics() -> void:
if _phys_start != 0:
var now := Time.get_ticks_usec()
_phys_us += now - _phys_start
_phys_start = 0
_phys_end = now
func _on_process_frame() -> void:
var now := Time.get_ticks_usec()
# Without draw signals (headless) the frame ends here instead.
if not _saw_draw and _proc_frame_t != 0:
_finish_frame(now)
_close_physics_engine(now)
_proc_frame_t = now
func _process(_delta: float) -> void:
_scripts_start = Time.get_ticks_usec()
func _end_process() -> void:
if _scripts_start != 0:
_scripts_us = Time.get_ticks_usec() - _scripts_start
_scripts_start = 0
func _on_pre_draw() -> void:
_draw_start = Time.get_ticks_usec()
func _on_post_draw() -> void:
_saw_draw = true
var now := Time.get_ticks_usec()
var draw_us := now - _draw_start if _draw_start != 0 else 0
_finish_frame(now, draw_us)
func _on_node_added(_n: Node) -> void:
_nodes_added += 1
func _finish_frame(now: int, draw_us: int = 0) -> void:
var wall := (now - _frame_t0) / 1000.0
_frame_t0 = now
# process = process_frame -> pre_draw; headless has no pre_draw, so the
# _process scripts are all we can attribute.
var proc_us := (_draw_start - _proc_frame_t) if (_saw_draw and _draw_start != 0 and _proc_frame_t != 0) else _scripts_us
var rec := {"wall_ms": wall, "physics_ms": _phys_us / 1000.0,
"physics_engine_ms": _phys_engine_us / 1000.0, "process_ms": proc_us / 1000.0,
"scripts_ms": _scripts_us / 1000.0, "draw_ms": draw_us / 1000.0,
"nodes_added": _nodes_added}
rec["other_ms"] = maxf(0.0, wall - rec["physics_ms"] - rec["physics_engine_ms"]
- rec["process_ms"] - rec["draw_ms"])
_phys_us = 0
_phys_engine_us = 0
_scripts_us = 0
_proc_frame_t = 0 if _saw_draw else _proc_frame_t
_draw_start = 0
_nodes_added = 0
_add_terrain_and_cpu(rec)
var st := _read_stat()
if st.size() == 4 and _stat0.size() == 4:
rec["minflt"] = st[0] - _stat0[0]
rec["majflt"] = st[1] - _stat0[1]
_stat0 = st
_walls[_ring_i] = wall
_ring_i = (_ring_i + 1) % RING
_summary_walls.append(wall)
if wall > HITCH_MIN_MS:
var med := _median()
if wall > MEDIAN_FACTOR * med:
_hitch(rec, med)
_recent.append(rec)
if _recent.size() > BEFORE:
_recent.pop_front()
if (now - _summary_t0) / 1e6 >= SUMMARY_S:
_summary(now)
func _hitch(rec: Dictionary, median: float) -> void:
var full := rec.duplicate()
full["type"] = "hitch"
full["t"] = Time.get_ticks_msec() / 1000.0
full["median_ms"] = median
full["map"] = _map_name()
full["video_mem_mb"] = RenderingServer.get_rendering_info(RenderingServer.RENDERING_INFO_VIDEO_MEM_USED) / 1048576.0
full["draw_calls"] = RenderingServer.get_rendering_info(RenderingServer.RENDERING_INFO_TOTAL_DRAW_CALLS_IN_FRAME)
var vp := get_viewport()
if vp != null:
full["vp_cpu_ms"] = RenderingServer.viewport_get_measured_render_time_cpu(vp.get_viewport_rid())
full["vp_gpu_ms"] = RenderingServer.viewport_get_measured_render_time_gpu(vp.get_viewport_rid())
full["before"] = _recent.duplicate(true)
_hitches.append(full)
if _hitches.size() > KEEP:
_hitches.pop_front()
_summary_hitches += 1
_write(full)
var dc := ""
if full.has("dc"):
var d: Dictionary = full["dc"]
dc = " | dc %.0fms: upload %dx %.0fms, retrim %dx %.0fms, seam %.0fms, coll %.0fms, gpu jobs +%d" % [
d.get("total_ms", 0.0), d.get("uploaded", 0), d.get("upload_ms", 0.0),
d.get("retrims", 0), d.get("retrim_ms", 0.0), d.get("seam_ms", 0.0),
d.get("collision_ms", 0.0), d.get("gpu_jobs", 0)]
var gpu := _gpu_recent_worst()
if not gpu.is_empty():
full["gpu_worst"] = gpu
dc += " | gpu worst %.0fms: %s" % [gpu["ms"], gpu["worst"]]
print("[HITCH] %.0f ms (median %.0f) | phys %.0f+%.0f engine, proc %.0f (scripts %.0f), draw %.0f, other %.0f%s%s | majflt +%d | nodes +%d | vram %.0f MB" % [
full["wall_ms"], median, full["physics_ms"], full["physics_engine_ms"], full["process_ms"],
full["scripts_ms"], full["draw_ms"], full["other_ms"], (" | cpu %.0f" % full["cpu_ms"]) if full.has("cpu_ms") else "", dc,
full.get("majflt", -1), full["nodes_added"], full["video_mem_mb"]])
func _summary(now: int) -> void:
var s := _summary_walls.duplicate()
s.sort()
var n := s.size()
var rec := {"type": "summary", "t": Time.get_ticks_msec() / 1000.0, "frames": n,
"secs": (now - _summary_t0) / 1e6, "hitches": _summary_hitches, "map": _map_name()}
if n > 0:
rec["p50_ms"] = s[n / 2]
rec["p95_ms"] = s[mini(n - 1, int(n * 0.95))]
rec["p99_ms"] = s[mini(n - 1, int(n * 0.99))]
rec["max_ms"] = s[n - 1]
rec["exe_deleted"] = _exe_deleted()
rec["gpu_submits"] = _summary_gpu_submits
rec["gpu_max_ms"] = _summary_gpu_max
rec["gpu_worst"] = _summary_gpu_worst
_write(rec)
print("[HITCH] summary %.0fs: %d frames, p50 %.1f p95 %.1f p99 %.1f max %.1f ms, %d hitches%s" % [
rec["secs"], n, rec.get("p50_ms", 0.0), rec.get("p95_ms", 0.0), rec.get("p99_ms", 0.0),
rec.get("max_ms", 0.0), _summary_hitches,
" | INSTALL SWAPPED UNDER THE RUNNING GAME (exe deleted)" if rec["exe_deleted"] else ""])
if _summary_gpu_submits > 0:
print("[HITCH] summary gpu: %d submits, worst %.1f ms: %s" % [
_summary_gpu_submits, _summary_gpu_max, _summary_gpu_worst])
_summary_gpu_submits = 0
_summary_gpu_max = 0.0
_summary_gpu_worst = ""
_summary_walls.clear()
_summary_hitches = 0
_summary_t0 = now
func _median() -> float:
var s := _walls.duplicate()
s.sort()
# Zeros are unfilled slots at startup; take the median of what we have.
var first := 0
while first < s.size() and s[first] == 0.0:
first += 1
if first >= s.size():
return 0.0
return s[first + (s.size() - first) / 2]
## The slowest GPU submit of the last GPU_RECENT frames, or {} if none ran.
func _gpu_recent_worst() -> Dictionary:
var best := {}
for g: Dictionary in _gpu_recent:
if float(g["ms"]) > 0.0 and (best.is_empty() or float(g["ms"]) > float(best["ms"])):
best = g
return best
func _add_terrain_and_cpu(rec: Dictionary) -> void:
var now_ms := Time.get_ticks_msec()
if (_terrain == null or not is_instance_valid(_terrain)) and now_ms - _terrain_scan_t > 2000:
_terrain_scan_t = now_ms
var found := get_tree().root.find_children("*", "DCTerrain", true, false)
_terrain = found[0] if not found.is_empty() else null
if _terrain == null or not is_instance_valid(_terrain):
return
if _terrain.has_method("get_frame_stats"):
var d: Dictionary = _terrain.call("get_frame_stats")
rec["dc"] = d
if d.has("gpu_submit_max_ms"):
var m := float(d["gpu_submit_max_ms"])
_gpu_recent.append({"ms": m, "worst": str(d.get("gpu_submit_worst", ""))})
if _gpu_recent.size() > GPU_RECENT:
_gpu_recent.pop_front()
_summary_gpu_submits += int(d.get("gpu_submits", 0))
if m > _summary_gpu_max:
_summary_gpu_max = m
_summary_gpu_worst = str(d.get("gpu_submit_worst", ""))
if _terrain.has_method("thread_cpu_usec"):
var c := int(_terrain.call("thread_cpu_usec"))
if c >= 0 and _cpu0 >= 0:
rec["cpu_ms"] = (c - _cpu0) / 1000.0
_cpu0 = c
## [minflt, majflt, utime, stime] from /proc/self/stat; empty off Linux.
func _read_stat() -> PackedInt64Array:
var out := PackedInt64Array()
if OS.get_name() != "Linux":
return out
var f := FileAccess.open("/proc/self/stat", FileAccess.READ)
if f == null:
return out
var line := f.get_line()
# Fields after the ")" that closes comm: state is field 3, minflt 10, majflt 12,
# utime 14, stime 15 -- so indices 7, 9, 11, 12 of what follows ") ".
var parts := line.substr(line.rfind(")") + 2).split(" ")
if parts.size() > 12:
out.append_array([int(parts[7]), int(parts[9]), int(parts[11]), int(parts[12])])
return out
## The install swap renames the running game's directory and deletes it; the
## binary's mapping then reads "(deleted)".
func _exe_deleted() -> bool:
if OS.get_name() != "Linux":
return false
var f := FileAccess.open("/proc/self/maps", FileAccess.READ)
if f == null:
return false
var exe := OS.get_executable_path().get_file()
while not f.eof_reached():
var l := f.get_line()
if l.ends_with("(deleted)") and exe in l:
return true
return false
func _map_name() -> String:
var maps := get_tree().root.get_node_or_null(^"Game/Maps")
if maps != null and maps.get_child_count() > 0:
return String(maps.get_child(maps.get_child_count() - 1).name)
return ""
func _settings() -> Dictionary:
var out := {}
var s := get_tree().root.get_node_or_null(^"Settings")
if s == null or not ("SCHEMA" in s):
return out
for row: Dictionary in s.SCHEMA:
out[row["key"]] = s.call("get_value", row["key"])
return out
func _write(rec: Dictionary) -> void:
if _file != null:
_file.store_line(JSON.stringify(rec))
_file.flush()
# The END bracket: runs after every other node in both phases.
const _EndScript := preload("res://scenes/game/hitch_log_end.gd")