OverviewFilesCommitsIssuesDocsReleasesPeers

hyper-tps / autoloads / perf_metrics.gd

421 lines · gd ref:
extends CanvasLayer

## Performance metrics overlay. Toggle with F3.
## Shows FPS, frame time, render stats, network stats, and memory.

var panel: PanelContainer
var label: RichTextLabel
var visible_overlay: bool = false

# Network stats sampling
var _net_timer: float = 0.0
const NET_SAMPLE_INTERVAL: float = 1.0


func _ready() -> void:
	_register_admin()
	layer = 100

	panel = PanelContainer.new()
	panel.anchors_preset = Control.PRESET_TOP_RIGHT
	panel.anchor_left = 1.0
	panel.anchor_right = 1.0
	panel.offset_left = -280
	panel.offset_right = 0
	panel.offset_top = 10
	panel.offset_bottom = 400

	var style := StyleBoxFlat.new()
	style.bg_color = Color(0, 0, 0, 0.7)
	style.set_corner_radius_all(4)
	style.set_content_margin_all(8)
	panel.add_theme_stylebox_override("panel", style)

	label = RichTextLabel.new()
	label.bbcode_enabled = true
	label.fit_content = true
	label.scroll_active = false
	label.custom_minimum_size = Vector2(260, 0)
	label.add_theme_font_size_override("normal_font_size", 13)
	panel.add_child(label)

	add_child(panel)
	panel.visible = visible_overlay


func _unhandled_input(event: InputEvent) -> void:
	if Keymap.tapped(event, "toggle_metrics"):
		visible_overlay = not visible_overlay
		panel.visible = visible_overlay


## FRAME-TIME LOG — opt-in, off unless HYPER_TPS_FRAMELOG names a file.
##
## Exists to answer the one hard constraint on background tile generation: does
## a throttled CPU generator affect frame time? Nothing else about generation
## matters if the answer is yes, and it has never been measured.
##
## ⚠ LOGGED BEFORE THE visible_overlay GUARD. Everything below returns early
## when the overlay is hidden (F3), so logging further down would only record
## frames while the overlay happened to be on screen — and the overlay itself
## costs frame time, which is exactly what we are trying to measure.
##
## One line per frame: unix_ms,frame_ms. Flushed every FLUSH_EVERY frames rather
## than per frame, because a per-frame fsync would itself be a stutter source.
const FLUSH_EVERY := 120
var _flog: FileAccess = null
var _flog_n: int = 0
var _flog_checked: bool = false


func _frame_log(frame_ms: float) -> void:
	if not _flog_checked:
		_flog_checked = true
		var path := OS.get_environment("HYPER_TPS_FRAMELOG")
		if not path.is_empty():
			_flog = FileAccess.open(path, FileAccess.WRITE)
			if _flog != null:
				_flog.store_line("unix_ms,frame_ms")
				print("[perf] frame log -> ", path)
			else:
				push_warning("[perf] cannot open HYPER_TPS_FRAMELOG: " + path)
	if _flog == null:
		return
	_flog.store_line("%d,%.4f" % [Time.get_ticks_msec(), frame_ms])
	_flog_n += 1
	if _flog_n % FLUSH_EVERY == 0:
		_flog.flush()


func _process(delta: float) -> void:
	_frame_log(delta * 1000.0)
	# SAMPLED REGARDLESS OF THE OVERLAY. Everything below this used to run only
	# while F11 was open, which is exactly backwards for a soak: the run you most
	# want numbers from is the one nobody is watching.
	_net_sample()

	if not visible_overlay:
		return

	_net_timer += delta
	var text := ""

	# --- Frame Performance ---
	var fps := Engine.get_frames_per_second()
	var frame_ms := delta * 1000.0
	var fps_color := "green" if fps >= 55 else ("yellow" if fps >= 30 else "red")
	text += "[b]--- FRAME ---[/b]\n"
	text += "FPS: [color=%s]%d[/color]  (%.1f ms)\n" % [fps_color, fps, frame_ms]
	text += "Physics: %.1f ms\n" % (1000.0 / Engine.physics_ticks_per_second)

	# --- Render Stats ---
	text += "\n[b]--- RENDER ---[/b]\n"
	var vp := get_viewport()
	if vp:
		var ri := vp.get_render_info(Viewport.RENDER_INFO_TYPE_VISIBLE, Viewport.RENDER_INFO_OBJECTS_IN_FRAME)
		var prims := vp.get_render_info(Viewport.RENDER_INFO_TYPE_VISIBLE, Viewport.RENDER_INFO_PRIMITIVES_IN_FRAME)
		var draws := vp.get_render_info(Viewport.RENDER_INFO_TYPE_VISIBLE, Viewport.RENDER_INFO_DRAW_CALLS_IN_FRAME)
		text += "Objects: %d\n" % ri
		text += "Primitives: %s\n" % _format_number(prims)
		text += "Draw Calls: %d\n" % draws

	# --- Network Stats ---
	text += "\n[b]--- NETWORK ---[/b]\n"
	var mp := multiplayer
	if mp and mp.multiplayer_peer and mp.multiplayer_peer.get_connection_status() == MultiplayerPeer.CONNECTION_CONNECTED:
		text += "Peer ID: %d\n" % mp.get_unique_id()
		text += "Peers: %d\n" % mp.get_peers().size()
		text += "Mode: mesh  Server: %s\n" % ("Yes" if mp.is_server() else "No")

		# Per-peer RTT — the signal the overlay never showed.
		var snap: Dictionary = snapshot()
		text += "Uptime: %.1f min   joins/leaves: %d/%d\n" % [
			float(snap["uptime_ms"]) / 60000.0, snap["joined_total"], snap["left_total"]]
		if int(snap["first_peer_ms"]) >= 0:
			text += "First peer after: %.1f s\n" % (float(snap["first_peer_ms"]) / 1000.0)
		# ⚠ BOUNDED ON PURPOSE. The panel is a fixed-height box (offset_bottom=400)
		# with scroll_active=false, so unbounded rows would overflow it and spill
		# over whatever is beneath. Four peers is more than this overlay needs to
		# be useful; the rest are counted, and the LOG has every peer regardless.
		var rtt_map: Dictionary = snap["rtt"]
		var shown := 0
		for pid_s in rtt_map:
			if shown >= 4:
				text += "  (+%d more — see net log)\n" % (rtt_map.size() - shown)
				break
			var e: Dictionary = rtt_map[pid_s]
			text += "  peer %s  p50 %d  p95 %d  jit %d  (n=%d)\n" % [
				pid_s, e["p50"], e["p95"], e["jitter"], e["samples"]]
			shown += 1

		# HyperswarmMultiplayerPeer stats
		if mp.multiplayer_peer.has_method("get_stats"):
			var stats: Dictionary = mp.multiplayer_peer.get_stats()
			if stats.size() > 0:
				text += "\n[b]--- UDX TRANSPORT ---[/b]\n"
				for key in stats:
					var val = stats[key]
					if val is float:
						text += "%s: %.2f\n" % [key, val]
					else:
						text += "%s: %s\n" % [key, str(val)]
	else:
		text += "[color=gray]Not connected[/color]\n"

	# --- Memory ---
	text += "\n[b]--- MEMORY ---[/b]\n"
	var static_mem := Performance.get_monitor(Performance.MEMORY_STATIC)
	var obj_count := Performance.get_monitor(Performance.OBJECT_COUNT)
	var node_count := Performance.get_monitor(Performance.OBJECT_NODE_COUNT)
	var orphan_count := Performance.get_monitor(Performance.OBJECT_ORPHAN_NODE_COUNT)
	text += "Static: %s\n" % _format_bytes(static_mem)
	text += "Objects: %d  Nodes: %d\n" % [obj_count, node_count]
	if orphan_count > 0:
		text += "[color=yellow]Orphans: %d[/color]\n" % orphan_count

	# --- Players ---
	var players := get_tree().get_nodes_in_group("spawn_points")
	var _player_nodes := get_tree().get_nodes_in_group("") # Count CharacterBody3D
	text += "\n[b]--- GAME ---[/b]\n"
	text += "Spawn Points: %d\n" % players.size()

	label.text = text


# =============================================================================
# NETWORK SAMPLING — for a multi-hour two-machine soak (spec/bot-testbed.md (b))
# =============================================================================
#
## WHY SAMPLING LIVES HERE and not in a new autoload: this file is already "FPS,
## network, memory", already owns the F11 overlay, and already has a flushed file
## log. A second stats autoload would duplicate all three.
##
## WHAT WAS MISSING. The overlay dumped get_stats() raw and never called
## get_peer_rtt() at all -- the single most useful signal the transport exposes
## (hyperswarm_peer.cpp:227 gives srtt/rttvar/rto/min_rtt PER PEER). There was no
## history, so no percentile or jitter; no churn counters; and no record of when
## the first peer arrived.
##
## ⚠ get_stats() IS NOT A COUNTER SET. It returns unique_id, is_server,
## connection_status, incoming_packets and bound_port -- and incoming_packets is
## a QUEUE DEPTH, not a cumulative total. Bytes/packets/retransmits do not exist
## on the C++ side yet, so they are absent here rather than faked. Adding them is
## a GDExtension change, deliberately not bundled with this.
##
## EVENT-DRIVEN, NO INDEPENDENT CLOCK. Records are written when something
## CHANGES: a peer joins, a peer leaves, or a peer's rounded p50 RTT moves by at
## least RTT_RECORD_DELTA_MS. Sampling itself rides _process (the frame loop),
## not a Timer. A stable link therefore writes nothing for hours, and a flapping
## one writes densely -- which is the shape you want from a soak log.

## Ring size per peer. 256 frames is a few seconds of history at 60fps: enough
## for a stable percentile, small enough that a 4-peer mesh costs ~4KB.
const RTT_WINDOW := 256
## Only record when the displayed number would actually change.
const RTT_RECORD_DELTA_MS := 1

var _rtt: Dictionary = {}            # peer_id -> Array[int] of srtt samples
var _rtt_last_recorded: Dictionary = {}  # peer_id -> int p50 at last record
var _peers_joined_total: int = 0
var _peers_left_total: int = 0
var _session_start_ms: int = 0
var _first_peer_ms: int = -1
var _net_log: FileAccess = null
var _net_log_n: int = 0
var _net_hooked: bool = false


func _net_sample() -> void:
	if _session_start_ms == 0:
		_session_start_ms = Time.get_ticks_msec()
	var mp := multiplayer
	if mp == null or mp.multiplayer_peer == null:
		return
	if mp.multiplayer_peer is OfflineMultiplayerPeer:
		return
	if not _net_hooked:
		_net_hooked = true
		if not mp.peer_connected.is_connected(_on_net_peer_connected):
			mp.peer_connected.connect(_on_net_peer_connected)
		if not mp.peer_disconnected.is_connected(_on_net_peer_disconnected):
			mp.peer_disconnected.connect(_on_net_peer_disconnected)
	if not mp.multiplayer_peer.has_method("get_peer_rtt"):
		return
	for pid: int in mp.get_peers():
		var r: Dictionary = mp.multiplayer_peer.get_peer_rtt(pid)
		if r.is_empty():
			continue
		var srtt: int = int(r.get("srtt", 0))
		if srtt <= 0:
			continue
		var ring: Array = _rtt.get(pid, [])
		ring.append(srtt)
		if ring.size() > RTT_WINDOW:
			ring.remove_at(0)
		_rtt[pid] = ring
		var p50: int = _percentile(ring, 0.50)
		var last: int = int(_rtt_last_recorded.get(pid, -9999))
		if absi(p50 - last) >= RTT_RECORD_DELTA_MS:
			_rtt_last_recorded[pid] = p50
			_net_record("rtt", {"peer": pid, "p50": p50, "p95": _percentile(ring, 0.95),
				"jitter": _jitter(ring), "min": int(r.get("min_rtt", 0)),
				"rto": int(r.get("rto", 0)), "n": ring.size()})


func _peer_count() -> int:
	if multiplayer == null or multiplayer.multiplayer_peer == null:
		return 0
	if multiplayer.multiplayer_peer is OfflineMultiplayerPeer:
		return 0
	return multiplayer.get_peers().size()


func _on_net_peer_connected(pid: int) -> void:
	_peers_joined_total += 1
	if _first_peer_ms < 0:
		_first_peer_ms = Time.get_ticks_msec() - _session_start_ms
		_net_record("first_peer", {"peer": pid, "after_ms": _first_peer_ms})
	_net_record("peer_up", {"peer": pid, "peers": _peer_count(),
		"joined_total": _peers_joined_total})


func _on_net_peer_disconnected(pid: int) -> void:
	_peers_left_total += 1
	_rtt.erase(pid)
	_rtt_last_recorded.erase(pid)
	_net_record("peer_down", {"peer": pid, "peers": _peer_count(),
		"left_total": _peers_left_total})


## NDJSON, appended: tailable during a run, and a torn last line from a kill
## costs one record instead of the file. Default on -- a soak you have to
## remember to enable is a soak you lose. HYPER_TPS_NETLOG overrides the path;
## set it to "off" to disable.
func _net_record(kind: String, data: Dictionary) -> void:
	if _net_log == null:
		var path := OS.get_environment("HYPER_TPS_NETLOG")
		if path == "off":
			return
		if path.is_empty():
			path = "user://netstats-%d.ndjson" % Time.get_unix_time_from_system()
		_net_log = FileAccess.open(path, FileAccess.WRITE)
		if _net_log == null:
			push_warning("[perf] cannot open net log: " + path)
			return
		print("[perf] net log -> ", ProjectSettings.globalize_path(path))
	data["t"] = Time.get_ticks_msec() - _session_start_ms
	data["kind"] = kind
	_net_log.store_line(JSON.stringify(data))
	_net_log_n += 1
	# FLUSH EVERY RECORD. These are change-driven and deliberately sparse -- a
	# stable link writes nothing for hours -- so a flush-every-N buffer (copied
	# from _frame_log, where it is right because that writes at 60Hz) means the
	# first N-1 records of a soak never reach disk and a killed process loses
	# them. Measured: two meshed peers ran for minutes and both logs were 0 bytes.
	_net_log.flush()


func _percentile(ring: Array, q: float) -> int:
	if ring.is_empty():
		return 0
	var sorted := ring.duplicate()
	sorted.sort()
	# round(), NOT floor(): with floor, p95 of 1..5 is index floor(3.8)=3 -> 4,
	# i.e. the 95th percentile of five samples silently excludes the worst one.
	# Caught by gate_net_stats asserting a known input.
	var i: int = clampi(int(round(q * (sorted.size() - 1))), 0, sorted.size() - 1)
	return int(sorted[i])


## Mean absolute deviation from the mean — same definition game.gd's benchmark
## summary uses, so the two agree.
func _jitter(ring: Array) -> int:
	if ring.size() < 2:
		return 0
	var sum: float = 0.0
	for v in ring:
		sum += float(v)
	var avg: float = sum / ring.size()
	var dev: float = 0.0
	for v in ring:
		dev += absf(float(v) - avg)
	return int(round(dev / ring.size()))


## Everything the soak harness needs, in one call. Also what the overlay renders
## and what AdminFacade exposes, so the screen and the log cannot disagree.
## ---- SIMULATION COST (hyper-games #114 §7: the bot / creature benchmark) ----------
##
## The counters live in the STATIC SimStats (autoloads/sim_stats.gd): creatures and bot
## brains compile in `--script` gates before any autoload exists. These are its /global/perf
## face — the same numbers, readable over /world.
func sim_reset() -> void:
	SimStats.reset()


func sim_snapshot() -> Dictionary:
	return SimStats.snapshot()


func snapshot() -> Dictionary:
	var peers: Dictionary = {}
	for pid in _rtt:
		var ring: Array = _rtt[pid]
		peers[str(pid)] = {"p50": _percentile(ring, 0.50), "p95": _percentile(ring, 0.95),
			"jitter": _jitter(ring), "samples": ring.size()}
	return {
		"uptime_ms": Time.get_ticks_msec() - _session_start_ms,
		"peers": _peer_count(),
		"joined_total": _peers_joined_total,
		"left_total": _peers_left_total,
		"first_peer_ms": _first_peer_ms,
		"rtt": peers,
	}


func _format_bytes(bytes: float) -> String:
	if bytes < 1024:
		return "%d B" % bytes
	elif bytes < 1048576:
		return "%.1f KB" % (bytes / 1024.0)
	else:
		return "%.1f MB" % (bytes / 1048576.0)


func _format_number(n: int) -> String:
	if n < 1000:
		return str(n)
	elif n < 1000000:
		return "%.1fK" % (n / 1000.0)
	else:
		return "%.2fM" % (n / 1000000.0)


## Expose snapshot() on the AdminFacade so a peer's network stats are queryable
## from the TUI and admin-cli instead of only by tailing its NDJSON on disk.
## The facade was nearly empty -- only ScriptHost and the sky were registered --
## so this costs a group plus four metas and serves bot, TUI and CLI at once.
##
## ⚠ CALL SCOPE IS "authority", AND THAT IS A LIMITATION, NOT A PREFERENCE.
## An admin:cmd reaches every peer, and results are published to
## admin:result:<seq> with NO responder segment (admin_facade.gd:240) under
## LWW-by-ts. So a value-returning method run "local" would have every peer
## overwrite the same key and the caller would read an arbitrary peer's numbers
## -- the defect admin_facade.gd:222 and :586 already warn about. "authority"
## means exactly one peer answers, which is correct but reads only the
## AUTHORITY's stats. Reading every peer's needs either a responder-keyed result
## or each peer publishing its own snapshot to a realtime per-peer key; that is a
## facade change, deliberately not made here.
##
## Role "peer": reading your own mesh's health is not an admin action. Methods are
## opt-in and default to admin (admin_facade.gd:516), so this has to be said.
func _register_admin() -> void:
	add_to_group("admin_controllable")
	set_meta("admin_scope", "global")        # an autoload: survives map changes
	set_meta("admin_name", "perf")           # -> /global/perf
	set_meta("admin_exposed_methods", ["snapshot", "sim_snapshot", "sim_reset"])
	# sim_*: LOCAL — the simulating peer's own cost, read where it is spent.
	set_meta("admin_call_scopes", {"snapshot": "authority", "sim_snapshot": "local", "sim_reset": "local"})
	set_meta("admin_roles", {"snapshot": {"call": "peer"}, "sim_snapshot": {"call": "peer"},
		"sim_reset": {"call": "peer"}})