From a2756af51420fe62e52cf5b9c8bc9fbfe9532eff Mon Sep 17 00:00:00 2001 From: mischa <16416509+vis2k@users.noreply.github.com> Date: Mon, 31 Oct 2022 10:43:10 +0100 Subject: [PATCH] feature: RemoteStatistics tool (#3254) --- Assets/Mirror/Components/RemoteStatistics.cs | 440 ++++++++++++++++++ .../Components/RemoteStatistics.cs.meta | 3 + Assets/Mirror/Core/NetworkServer.cs | 56 ++- Assets/Mirror/Core/TimeSample.cs | 61 +++ Assets/Mirror/Core/TimeSample.cs.meta | 11 + Assets/Mirror/Examples/CCU/Player.prefab | 20 + Assets/Mirror/Tests/Editor/TimeSampleTests.cs | 36 ++ .../Tests/Editor/TimeSampleTests.cs.meta | 3 + remote_statistics.txt | 1 + 9 files changed, 630 insertions(+), 1 deletion(-) create mode 100644 Assets/Mirror/Components/RemoteStatistics.cs create mode 100644 Assets/Mirror/Components/RemoteStatistics.cs.meta create mode 100644 Assets/Mirror/Core/TimeSample.cs create mode 100644 Assets/Mirror/Core/TimeSample.cs.meta create mode 100644 Assets/Mirror/Tests/Editor/TimeSampleTests.cs create mode 100644 Assets/Mirror/Tests/Editor/TimeSampleTests.cs.meta create mode 100644 remote_statistics.txt diff --git a/Assets/Mirror/Components/RemoteStatistics.cs b/Assets/Mirror/Components/RemoteStatistics.cs new file mode 100644 index 000000000..4624fbd55 --- /dev/null +++ b/Assets/Mirror/Components/RemoteStatistics.cs @@ -0,0 +1,440 @@ +// remote statistics panel from Mirror II to show connections, load, etc. +// server syncs statistics to clients if authenticated. +// +// attach this to a player. +// requires NetworkStatistics component on the Network object. +// +// Unity's OnGUI is the easiest to use solution at the moment. +// * playfab is super complex to set up +// * http servers would be nice, but still need to open ports, live refresh, etc +// +// for safety reasons, let's keep this read-only. +// at least until there's safe authentication. +using System; +using System.IO; +using UnityEngine; + +namespace Mirror +{ + // server -> client + struct Stats + { + // general + public int connections; + public double uptime; + public int configuredTickRate; + public int actualTickRate; + + // traffic + public long sentBytesPerSecond; + public long receiveBytesPerSecond; + + // cpu + public float serverTickInterval; + public double fullUpdateAvg; + public double serverEarlyAvg; + public double serverLateAvg; + public double transportEarlyAvg; + public double transportLateAvg; + + // C# boilerplate + public Stats( + // general + int connections, + double uptime, + int configuredTickRate, + int actualTickRate, + // traffic + long sentBytesPerSecond, + long receiveBytesPerSecond, + // cpu + float serverTickInterval, + double fullUpdateAvg, + double serverEarlyAvg, + double serverLateAvg, + double transportEarlyAvg, + double transportLateAvg + ) + { + // general + this.connections = connections; + this.uptime = uptime; + this.configuredTickRate = configuredTickRate; + this.actualTickRate = actualTickRate; + + // traffic + this.sentBytesPerSecond = sentBytesPerSecond; + this.receiveBytesPerSecond = receiveBytesPerSecond; + + // cpu + this.serverTickInterval = serverTickInterval; + this.fullUpdateAvg = fullUpdateAvg; + this.serverEarlyAvg = serverEarlyAvg; + this.serverLateAvg = serverLateAvg; + this.transportEarlyAvg = transportEarlyAvg; + this.transportLateAvg = transportLateAvg; + } + } + + // [RequireComponent(typeof(NetworkStatistics))] <- needs to be on Network GO, not on NI + public class RemoteStatistics : NetworkBehaviour + { + // components ("fake statics" for similar API) + protected NetworkStatistics NetworkStatistics; + + // broadcast to client. + // stats are quite huge, let's only send every few seconds via TargetRpc. + // instead of sending multiple times per second via NB.OnSerialize. + [Tooltip("Send stats every 'interval' seconds to client.")] + public float sendInterval = 1; + double lastSendTime; + + [Header("GUI")] + public bool showGui; + public KeyCode hotKey = KeyCode.F11; + Rect windowRect = new Rect(0, 0, 400, 400); + + // password can't be stored in code or in Unity project. + // it would be available in clients otherwise. + // this is not perfectly secure. that's why RemoteStatistics is read-only. + [Header("Authentication")] + public string passwordFile = "remote_statistics.txt"; + protected bool serverAuthenticated; // client needs to authenticate + protected bool clientAuthenticated; // show GUI until authenticated + protected string serverPassword = null; // null means not found, auth impossible + protected string clientPassword = ""; // for GUI + + // statistics synced to client + Stats stats; + + void LoadPassword() + { + // TODO only load once, not for all players? + // let's avoid static state for now. + + // load the password + string path = Path.GetFullPath(passwordFile); + if (File.Exists(path)) + { + // don't spam the server logs for every player's loaded file + // Debug.Log($"RemoteStatistics: loading password file: {path}"); + try + { + serverPassword = File.ReadAllText(path); + } + catch (Exception exception) + { + Debug.LogWarning($"RemoteStatistics: failed to read password file: {exception}"); + } + } + else + { + Debug.LogWarning($"RemoteStatistics: password file has not been created. Authentication will be impossible. Please save the password in: {path}"); + } + } + + void OnValidate() + { + syncMode = SyncMode.Owner; + } + + // make sure to call base function when overwriting! + // public so it can also be called from tests (and be overwritten by users) + public override void OnStartServer() + { + NetworkStatistics = NetworkManager.singleton.GetComponent(); + if (NetworkStatistics == null) throw new Exception($"RemoteStatistics requires a NetworkStatistics component on {NetworkManager.singleton.name}!"); + + // server needs to load the password + LoadPassword(); + } + + public override void OnStartLocalPlayer() + { + // center the window initially + windowRect.x = Screen.width / 2 - windowRect.width / 2; + windowRect.y = Screen.height / 2 - windowRect.height / 2; + } + + [TargetRpc] + void TargetRpcSync(Stats v) + { + // store stats and flag as authenticated + clientAuthenticated = true; + stats = v; + } + + [Command] + public void CmdAuthenticate(string v) + { + // was a valid password loaded on the server, + // and did the client send the correct one? + if (!string.IsNullOrWhiteSpace(serverPassword) && + serverPassword.Equals(v)) + { + serverAuthenticated = true; + Debug.Log($"RemoteStatistics: connectionId {connectionToClient.connectionId} authenticated with player {name}"); + } + } + + void UpdateServer() + { + // only sync if client has authenticated on the server + if (!serverAuthenticated) return; + + // double for long running servers + if (Time.timeAsDouble >= lastSendTime + sendInterval) + { + lastSendTime = Time.timeAsDouble; + + // target rpc to owner client + TargetRpcSync(new Stats( + // general + NetworkServer.connections.Count, + Time.realtimeSinceStartupAsDouble, + NetworkServer.tickRate, + NetworkServer.actualTickRate, + + // traffic + NetworkStatistics.serverSentBytesPerSecond, + NetworkStatistics.serverReceivedBytesPerSecond, + + // cpu + NetworkServer.tickInterval, + NetworkServer.fullUpdateDuration.average, + NetworkServer.earlyUpdateDuration.average, + NetworkServer.lateUpdateDuration.average, + 0, // TODO ServerTransport.earlyUpdateDuration.average, + 0 // TODO ServerTransport.lateUpdateDuration.average + )); + } + } + + void UpdateClient() + { + if (Input.GetKeyDown(hotKey)) + showGui = !showGui; + } + + void Update() + { + if (isServer) UpdateServer(); + if (isLocalPlayer) UpdateClient(); + } + + void OnGUI() + { + if (!isLocalPlayer) return; + if (!showGui) return; + + windowRect = GUILayout.Window(0, windowRect, OnWindow, "Remote Statistics"); + windowRect = Utils.KeepInScreen(windowRect); + } + + // Text: value + void GUILayout_TextAndValue(string text, string value) + { + GUILayout.BeginHorizontal(); + GUILayout.Label(text); + GUILayout.FlexibleSpace(); + GUILayout.Label(value); + GUILayout.EndHorizontal(); + } + + // fake a progress bar via horizontal scroll bar with ratio as width + void GUILayout_ProgressBar(double ratio, int width) + { + // clamp ratio, otherwise >1 would make it extremely large + ratio = Mathd.Clamp01(ratio); + GUILayout.HorizontalScrollbar(0, (float)ratio, 0, 1, GUILayout.Width(width)); + } + + // need to specify progress bar & caption width, + // otherwise differently sized captions would always misalign the + // progress bars. + void GUILayout_TextAndProgressBar(string text, double ratio, int progressbarWidth, string caption, int captionWidth, Color captionColor) + { + GUILayout.BeginHorizontal(); + GUILayout.Label(text); + GUILayout.FlexibleSpace(); + GUILayout_ProgressBar(ratio, progressbarWidth); + + // coloring the caption is enough. otherwise it's too much. + GUI.color = captionColor; + GUILayout.Label(caption, GUILayout.Width(captionWidth)); + GUI.color = Color.white; + + GUILayout.EndHorizontal(); + } + + void GUI_Authenticate() + { + GUILayout.BeginVertical("Box"); // start general + GUILayout.Label("Authentication"); + + // warning if insecure connection + // if (ClientTransport.IsEncrypted()) + // { + // GUILayout.Label("Connection is encrypted!"); + // } + // else + // { + GUILayout.Label("Connection is not encrypted. Use with care!"); + // } + + // input + clientPassword = GUILayout.PasswordField(clientPassword, '*'); + + // button + GUI.enabled = !string.IsNullOrWhiteSpace(clientPassword); + if (GUILayout.Button("Authenticate")) + { + CmdAuthenticate(clientPassword); + } + GUI.enabled = true; + + GUILayout.EndVertical(); // end general + } + + void GUI_General( + int connections, + double uptime, + int configuredTickRate, + int actualTickRate) + { + GUILayout.BeginVertical("Box"); // start general + GUILayout.Label("General"); + + // connections + GUILayout_TextAndValue("Connections:", $"{connections}"); + + // uptime + GUILayout_TextAndValue("Uptime:", $"{Utils.PrettySeconds(uptime)}"); // TODO + + // tick rate + // might be lower under heavy load. + // might be higher in editor if targetFrameRate can't be set. + GUI.color = actualTickRate < configuredTickRate ? Color.red : Color.green; + GUILayout_TextAndValue("Tick Rate:", $"{actualTickRate} Hz / {configuredTickRate} Hz"); + GUI.color = Color.white; + + GUILayout.EndVertical(); // end general + } + + void GUI_Traffic( + long serverSentBytesPerSecond, + long serverReceivedBytesPerSecond) + { + GUILayout.BeginVertical("Box"); + GUILayout.Label("Network"); + + GUILayout_TextAndValue("Outgoing:", $"{Utils.PrettyBytes(serverSentBytesPerSecond) }/s"); + GUILayout_TextAndValue("Incoming:", $"{Utils.PrettyBytes(serverReceivedBytesPerSecond)}/s"); + + GUILayout.EndVertical(); + } + + void GUI_Cpu( + float serverTickInterval, + double fullUpdateAvg, + double serverEarlyAvg, + double serverLateAvg, + double transportEarlyAvg, + double transportLateAvg) + { + const int barWidth = 120; + const int captionWidth = 90; + + GUILayout.BeginVertical("Box"); + GUILayout.Label("CPU"); + + // unity update + // happens every 'tickInterval'. progress bar shows it in relation. + // <= 90% load is green, otherwise red + double fullRatio = fullUpdateAvg / serverTickInterval; + GUILayout_TextAndProgressBar( + "World Update Avg:", + fullRatio, + barWidth, $"{fullUpdateAvg * 1000:F1} ms", + captionWidth, + fullRatio <= 0.9 ? Color.green : Color.red); + + // server update + // happens every 'tickInterval'. progress bar shows it in relation. + // <= 90% load is green, otherwise red + double serverRatio = (serverEarlyAvg + serverLateAvg) / serverTickInterval; + GUILayout_TextAndProgressBar( + "Server Update Avg:", + serverRatio, + barWidth, $"{serverEarlyAvg * 1000:F1} + {serverLateAvg * 1000:F1} ms", + captionWidth, + serverRatio <= 0.9 ? Color.green : Color.red); + + // transport: early + late update milliseconds. + // for threaded transport, this is the thread's update time. + // happens every 'tickInterval'. progress bar shows it in relation. + // <= 90% load is green, otherwise red + // double transportRatio = (transportEarlyAvg + transportLateAvg) / serverTickInterval; + // GUILayout_TextAndProgressBar( + // "Transport Avg:", + // transportRatio, + // barWidth, + // $"{transportEarlyAvg * 1000:F1} + {transportLateAvg * 1000:F1} ms", + // captionWidth, + // transportRatio <= 0.9 ? Color.green : Color.red); + + GUILayout.EndVertical(); + } + + void GUI_Notice() + { + // for security reasons, let's keep this read-only for now. + + // single line keeps input & visuals simple + // GUILayout.BeginVertical("Box"); + // GUILayout.Label("Global Notice"); + // notice = GUILayout.TextField(notice); + // if (GUILayout.Button("Send")) + // { + // // TODO + // } + // GUILayout.EndVertical(); + } + + void OnWindow(int windowID) + { + if (!clientAuthenticated) + { + GUI_Authenticate(); + } + else + { + GUI_General( + stats.connections, + stats.uptime, + stats.configuredTickRate, + stats.actualTickRate + ); + + GUI_Traffic( + stats.sentBytesPerSecond, + stats.receiveBytesPerSecond + ); + + GUI_Cpu( + stats.serverTickInterval, + stats.fullUpdateAvg, + stats.serverEarlyAvg, + stats.serverLateAvg, + stats.transportEarlyAvg, + stats.transportLateAvg + ); + + GUI_Notice(); + } + + // dragable window in any case + GUI.DragWindow(new Rect(0, 0, 10000, 10000)); + } + } +} diff --git a/Assets/Mirror/Components/RemoteStatistics.cs.meta b/Assets/Mirror/Components/RemoteStatistics.cs.meta new file mode 100644 index 000000000..8de45d59b --- /dev/null +++ b/Assets/Mirror/Components/RemoteStatistics.cs.meta @@ -0,0 +1,3 @@ +fileFormatVersion: 2 +guid: ba360e4ff6b44fc6898f56322b90c6c8 +timeCreated: 1663219738 \ No newline at end of file diff --git a/Assets/Mirror/Core/NetworkServer.cs b/Assets/Mirror/Core/NetworkServer.cs index fcb683e52..7ab19730e 100644 --- a/Assets/Mirror/Core/NetworkServer.cs +++ b/Assets/Mirror/Core/NetworkServer.cs @@ -74,6 +74,23 @@ public static partial class NetworkServer public static Action OnDisconnectedEvent; public static Action OnErrorEvent; + // keep track of actual achieved tick rate. + // might become lower under heavy load. + // very useful for profiling etc. + // measured over 1s each, same as frame rate. no EMA here. + public static int actualTickRate; + static double actualTickRateStart; // start time when counting + static int actualTickRateCounter; // current counter since start + + // profiling + // includes transport update time, because transport calls handlers etc. + // averaged over 1s by passing 'tickRate' to constructor. + public static TimeSample earlyUpdateDuration; + public static TimeSample lateUpdateDuration; + + // capture full Unity update time from before Early- to after LateUpdate + public static TimeSample fullUpdateDuration; + // initialization / shutdown /////////////////////////////////////////// static void Initialize() { @@ -96,6 +113,11 @@ static void Initialize() AddTransportHandlers(); initialized = true; + + // profiling + earlyUpdateDuration = new TimeSample(sendRate); + lateUpdateDuration = new TimeSample(sendRate); + fullUpdateDuration = new TimeSample(sendRate); } static void AddTransportHandlers() @@ -1786,6 +1808,13 @@ static void Broadcast() // (we add this to the UnityEngine in NetworkLoop) internal static void NetworkEarlyUpdate() { + // measure update time for profiling. + if (active) + { + earlyUpdateDuration.Begin(); + fullUpdateDuration.Begin(); + } + // process all incoming messages first before updating the world if (Transport.active != null) Transport.active.ServerEarlyUpdate(); @@ -1793,13 +1822,18 @@ internal static void NetworkEarlyUpdate() // step each connection's local time interpolation in early update. foreach (NetworkConnectionToClient connection in connections.Values) connection.UpdateTimeInterpolation(); + + if (active) earlyUpdateDuration.End(); } internal static void NetworkLateUpdate() { - // only broadcast world if active if (active) { + // measure update time for profiling. + lateUpdateDuration.Begin(); + + // only broadcast world if active // broadcast every sendInterval. // AccurateInterval to avoid update frequency inaccuracy issues: // https://github.com/vis2k/Mirror/pull/3153 @@ -1829,6 +1863,26 @@ internal static void NetworkLateUpdate() // (even if not active. still want to process disconnects etc.) if (Transport.active != null) Transport.active.ServerLateUpdate(); + + // measure actual tick rate every second. + if (active) + { + ++actualTickRateCounter; + if (Time.timeAsDouble >= actualTickRateStart + 1) + { + // calculate avg by exact elapsed time. + // assuming 1s wouldn't be accurate, usually a few more ms passed. + float elapsed = (float)(Time.timeAsDouble - actualTickRateStart); + actualTickRate = Mathf.RoundToInt(actualTickRateCounter / elapsed); + actualTickRateStart = Time.timeAsDouble; + actualTickRateCounter = 0; + } + + // measure total update time. including transport. + // because in early update, transport update calls handlers. + lateUpdateDuration.End(); + fullUpdateDuration.End(); + } } } } diff --git a/Assets/Mirror/Core/TimeSample.cs b/Assets/Mirror/Core/TimeSample.cs new file mode 100644 index 000000000..111e9719f --- /dev/null +++ b/Assets/Mirror/Core/TimeSample.cs @@ -0,0 +1,61 @@ +// TimeSample from Mirror II. +// simple profiling sample, averaged for display in statistics. +// usable in builds without unitiy profiler overhead etc. +// +// .average may safely be called from main thread while Begin/End is in another. +// i.e. worker threads, transport, etc. +using System.Diagnostics; +using System.Threading; + +namespace Mirror +{ + public struct TimeSample + { + // UnityEngine.Time isn't thread safe. use stopwatch instead. + readonly Stopwatch watch; + + // remember when Begin was called + double beginTime; + + // keep accumulating times over the given interval. + // (not readonly. we modify its contents.) + ExponentialMovingAverage ema; + + // average in seconds. + // code often runs in sub-millisecond time. float is more precise. + // + // set with Interlocked for thread safety. + // can be read from main thread while sampling happens in other thread. + public double average; // THREAD SAFE + + // average over N begin/end captures + public TimeSample(int n) + { + watch = new Stopwatch(); + watch.Start(); + ema = new ExponentialMovingAverage(n); + beginTime = 0; + average = 0; + } + + // begin is called before the code to be sampled + public void Begin() + { + // remember when Begin was called. + // keep StopWatch running so we can average over the given interval. + beginTime = watch.Elapsed.TotalSeconds; + // Debug.Log($"Begin @ {beginTime:F4}"); + } + + // end is called after the code to be sampled + public void End() + { + // add duration in seconds to accumulated durations + double elapsed = watch.Elapsed.TotalSeconds - beginTime; + ema.Add(elapsed); + + // expose new average thread safely + Interlocked.Exchange(ref average, ema.Value); + } + } +} diff --git a/Assets/Mirror/Core/TimeSample.cs.meta b/Assets/Mirror/Core/TimeSample.cs.meta new file mode 100644 index 000000000..83e5ede04 --- /dev/null +++ b/Assets/Mirror/Core/TimeSample.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: 26c32f6429554546a88d800c846c74ed +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {fileID: 2800000, guid: 7453abfe9e8b2c04a8a47eb536fe21eb, type: 3} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Assets/Mirror/Examples/CCU/Player.prefab b/Assets/Mirror/Examples/CCU/Player.prefab index 2ff696acc..9de0f731e 100644 --- a/Assets/Mirror/Examples/CCU/Player.prefab +++ b/Assets/Mirror/Examples/CCU/Player.prefab @@ -14,6 +14,7 @@ GameObject: - component: {fileID: 1078519278818213949} - component: {fileID: 3679374677650722848} - component: {fileID: 8691745481282286165} + - component: {fileID: 8079286830074380037} m_Layer: 0 m_Name: Player m_TagString: Untagged @@ -152,3 +153,22 @@ MonoBehaviour: movementProbability: 0.5 movementDistance: 20 manualSpeed: 10 +--- !u!114 &8079286830074380037 +MonoBehaviour: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 449802645721213856} + m_Enabled: 1 + m_EditorHideFlags: 0 + m_Script: {fileID: 11500000, guid: ba360e4ff6b44fc6898f56322b90c6c8, type: 3} + m_Name: + m_EditorClassIdentifier: + syncDirection: 0 + syncMode: 1 + syncInterval: 0.1 + sendInterval: 1 + showGui: 0 + hotKey: 292 + passwordFile: remote_statistics.txt diff --git a/Assets/Mirror/Tests/Editor/TimeSampleTests.cs b/Assets/Mirror/Tests/Editor/TimeSampleTests.cs new file mode 100644 index 000000000..ae98a1a32 --- /dev/null +++ b/Assets/Mirror/Tests/Editor/TimeSampleTests.cs @@ -0,0 +1,36 @@ +using NUnit.Framework; +using System.Threading; + +namespace Mirror.Tests.Editor +{ + public class TimeSampleTests + { + [Test] + public void Sample3() + { + // sample over 3 measurements + TimeSample sample = new TimeSample(3); + + // initial without any values + Assert.That(sample.average, Is.EqualTo(0)); + + // measure 10ms. average should be 10ms. + sample.Begin(); + Thread.Sleep(10); + sample.End(); + Assert.That(sample.average, Is.EqualTo(0.010).Within(0.002)); + + // measure 5ms. average should be 7.5ms + sample.Begin(); + Thread.Sleep(5); + sample.End(); + Assert.That(sample.average, Is.EqualTo(0.0075).Within(0.002)); + + // measure 0ms. average should be 5ms. + sample.Begin(); + Thread.Sleep(0); + sample.End(); + Assert.That(sample.average, Is.EqualTo(0.005).Within(0.002)); + } + } +} diff --git a/Assets/Mirror/Tests/Editor/TimeSampleTests.cs.meta b/Assets/Mirror/Tests/Editor/TimeSampleTests.cs.meta new file mode 100644 index 000000000..b8f6e3bf8 --- /dev/null +++ b/Assets/Mirror/Tests/Editor/TimeSampleTests.cs.meta @@ -0,0 +1,3 @@ +fileFormatVersion: 2 +guid: f52163f56d8e48d49fa9c7164d055019 +timeCreated: 1663221162 \ No newline at end of file diff --git a/remote_statistics.txt b/remote_statistics.txt new file mode 100644 index 000000000..594812f17 --- /dev/null +++ b/remote_statistics.txt @@ -0,0 +1 @@ +Mirror! \ No newline at end of file