more cleanup

Author: dooly123

Basis Server/BasisNetworkServer/BasisNetworkingReductionSystem/BasisServerReductionSystemEvents.cs

@@ -571,28 +571,28 @@ private static void RebalanceCpuBudget(long nowTick)
             // one machine; on hardware with a different core count or per-core speed this line is
             // what tells an operator whether the shipped default is wrong for them, and which of
             // BSRMaxDegreeOfParallelism / PeerUpdateParallelism to reach for.
+            //
+            // The delivery side rides the same line rather than a second one: undeliverable packets
+            // used to be visible only on the health endpoint, so a server shedding a third of its
+            // output looked identical in the log to one running clean. Drop pressure is per player
+            // per control window; sustained values above the escalate figure are what drive the
+            // shedding shown alongside. Worker counts are what is actually running, not just what
+            // each pool is allowed — the gap between those two is what hid a server using a quarter
+            // of a large host.
             if (WriteLoadLog && nowTick - _lastPoolLoadLogTick >= PoolLoadLogIntervalTicks)
             {
                 _lastPoolLoadLogTick = nowTick;
                 int peerWorkers = lnl?.PeerUpdateWorkers ?? 0;
-                // Workers actually running, not just what each pool is allowed — the gap between
-                // those two is what hid a server using a quarter of a large host.
-                BNL.Log(
-                    $"[CPU] send {parallelOptions.MaxDegreeOfParallelism}/{BasisCpuBudget.ReductionSendCap} workers, " +
-                    $"peer-update {peerWorkers}/{BasisCpuBudget.PeerUpdateCap} workers " +
-                    $"(pass {lnl?.PeerUpdatePassMs ?? 0:F1} ms, target {LiteNetLib.NetManager.PeerPassTargetMs:F0} ms), machine {BasisCpuBudget.Utilization * 100:F0}% of {BasisCpuBudget.TotalCores} cores.");
-
-                // The delivery side of the same question. Undeliverable packets used to be visible
-                // only on the health endpoint, so a server shedding a third of its output looked
-                // identical in the log to one running clean — this is the line that would have made
-                // that obvious. Drop pressure is per player per control window; sustained values
-                // above 1 are what drive the shedding shown alongside.
                 int pop = NetworkServer.Server?.ConnectedPeersCount ?? 0;
                 BNL.Log(
-                    $"[POP] {pop} peers: drop pressure {_dropsPerPlayerWindow:F2}/player " +
-                    $"(escalate above {DropEscalatePerPlayer:F2}), slicing {_sliceCount}/{MaxSliceCount()}, " +
-                    $"shed tier {_loadShedTier} ({LoadShedTierName(_loadShedTier)}), " +
-                    $"unreliable queue {(lnl != null ? lnl.EffectiveUnreliableQueuePerPeer : 0)}/peer.");
+                    $"[CPU/POP] {pop} peers | send {parallelOptions.MaxDegreeOfParallelism}/{BasisCpuBudget.ReductionSendCap} wkr, " +
+                    $"peer-upd {peerWorkers}/{BasisCpuBudget.PeerUpdateCap} wkr " +
+                    $"(pass {lnl?.PeerUpdatePassMs ?? 0:F1}/{LiteNetLib.NetManager.PeerPassTargetMs:F0} ms), " +
+                    $"machine {BasisCpuBudget.Utilization * 100:F0}% of {BasisCpuBudget.TotalCores} cores | " +
+                    $"drops {_dropsPerPlayerWindow:F2}/player (esc {DropEscalatePerPlayer:F2}), " +
+                    $"slice {_sliceCount}/{MaxSliceCount()}, " +
+                    $"tier {_loadShedTier} {LoadShedTierName(_loadShedTier)}, " +
+                    $"unrel q {(lnl != null ? lnl.EffectiveUnreliableQueuePerPeer : 0)}/peer");
             }
         }
 
@@ -781,6 +781,7 @@ private static void MaybeGrowSendSockets(LiteNetLib.NetManager lnl, long nowTick
         // Smoothed tick duration driving the load controller, and a rate limit for its log line.
         private static double _tickMsEma;
         private static long _lastSliceLogTick;
+        private static bool _loadLegendWritten;
 
         // Overrun-ratio control signal. Evaluated once per window rather than per tick so the
         // controller cannot chatter, and so a single slow tick cannot move it.
@@ -1398,12 +1399,19 @@ private static void RunTick(long startTick)
                 if (nowLog - _lastSliceLogTick > Stopwatch.Frequency * 5)
                 {
                     _lastSliceLogTick = nowLog;
-                    BNL.Log($"[BSR] Load: {_tickOverrunRatio:P0} of ticks over budget " +
+                    // How to read the line is worth saying once per run, not on every change: it was
+                    // 118 characters of unchanging prose repeated all through a busy session, more
+                    // than the numbers it was explaining.
+                    if (!_loadLegendWritten)
+                    {
+                        _loadLegendWritten = true;
+                        BNL.Log("[BSR] Load legend: period alone is harmless; tier > 0 means distant " +
+                                "players stop updating; slicing > 1 means everyone's rate is reduced.");
+                    }
+                    BNL.Log($"[BSR] Load: {_tickOverrunRatio:P0} ticks over budget " +
                             $"(mean {_tickMsEma:F2} ms), period {intervalMs} ms " +
-                            $"({1000 / Math.Max(1, intervalMs)} Hz), shed tier {_loadShedTier} " +
-                            $"({LoadShedTierName(_loadShedTier)}), slicing {_sliceCount}. " +
-                            $"Period alone is harmless; tier > 0 means distant players stop updating; " +
-                            $"slicing > 1 means everyone's rate is reduced.");
+                            $"({1000 / Math.Max(1, intervalMs)} Hz), " +
+                            $"tier {_loadShedTier} {LoadShedTierName(_loadShedTier)}, slicing {_sliceCount}");
                 }
             }
         }

Basis Server/BasisNetworkServer/BasisNetworkingReductionSystem/Profiling.cs

@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using System.Diagnostics;
+using System.Text;
 using System.Threading;
 
 namespace BasisNetworkServer.BasisNetworkingReductionSystem
@@ -308,30 +309,45 @@ public static void TryPrint()
 
             if (!WriteToLog) return;
 
-            BNL.Log($"\n[BSR Profile] {ticks} ticks, {msgs} msgs, {sends} sends, preSer {preSer}/{preSer + preSkip}");
-            BNL.Log($"  drain:    {drain / ticks:F3} ms/tick ({drain / total * 100:F1}%)");
-            BNL.Log($"  process:  {process / ticks:F3} ms/tick ({process / total * 100:F1}%)");
-            BNL.Log($"  distance: {distance / ticks:F3} ms/tick ({distance / total * 100:F1}%)");
-            BNL.Log($"  update:   {update / ticks:F3} ms/tick ({update / total * 100:F1}%)");
-            BNL.Log($"  trigger:  {trigger / ticks:F3} ms/tick ({trigger / total * 100:F1}%)");
-            BNL.Log($"  total:    {total / ticks:F3} ms/tick");
+            // One line, not eleven. A window carries the same 26 figures it always did, but every
+            // BNL.Log costs a console lock, a DateTime.Now, an open/write/close on the log file and
+            // a fistful of console attribute syscalls — the cost of reporting a window was set by
+            // the number of calls, not by anything being measured. Percentages are dropped to whole
+            // numbers where the ms/tick figure they derive from sits beside them.
+            double pctOfTotal = total > 0 ? 100.0 / total : 0;
+
+            StringBuilder line = new StringBuilder(288);
+            AppendInv(line, $"[BSR] {ticks}t {total / ticks:F3}ms/t");
+            AppendPhase(line, "drain", drain, ticks, pctOfTotal);
+            AppendPhase(line, "proc", process, ticks, pctOfTotal);
+            AppendPhase(line, "dist", distance, ticks, pctOfTotal);
+            AppendPhase(line, "upd", update, ticks, pctOfTotal);
+            AppendPhase(line, "trig", trigger, ticks, pctOfTotal);
+            AppendInv(line, $" | {msgs}msg {sends}send preser {preSer}/{preSer + preSkip}");
 
             if (bEmit > 0 || bTail > 0 || bFallback > 0)
             {
                 double ratio = bRaw > 0 ? (double)bComp / bRaw : 0;
-                double avgMsgsPerBundle = bEmit > 0 ? (double)bMsg / bEmit : 0;
-                double avgRawPerBundle = bEmit > 0 ? (double)bRaw / bEmit : 0;
-                double avgCompPerBundle = bEmit > 0 ? (double)bComp / bEmit : 0;
+                double savedPct = bRaw > 0 ? (ratio - 1) * 100.0 : 0; // negative: bundled bytes shrank
                 double deflateMs = bDeflate / MsToTick;
-                double avgDeflateUs = bEmit > 0 ? (deflateMs * 1000.0) / bEmit : 0;
-                double bundlesPerTick = (double)bEmit / ticks;
-                double retryRate = bEmit > 0 ? (double)bRetry / bEmit * 100.0 : 0;
-                long savedBytes = bRaw - bComp; // raw input vs compressed output
-                BNL.Log($"  bundles:  {bEmit} emitted ({bundlesPerTick:F2}/tick), {bMsg} msgs in bundles, {bTail} msgs tail-uncompressed, {bFallback} fallbacks");
-                BNL.Log($"            ratio {ratio:F3} ({(1 - ratio) * 100:F1}% saved on bundled bytes), avg {avgMsgsPerBundle:F1} msgs/bundle ({avgRawPerBundle:F0} B raw → {avgCompPerBundle:F0} B compressed)");
-                BNL.Log($"            deflate {deflateMs / ticks:F3} ms/tick ({deflateMs / total * 100:F1}% of tick), {avgDeflateUs:F1} µs/bundle, retries {bRetry} ({retryRate:F1}%)");
-                BNL.Log($"            saved ~{savedBytes / 1024.0:F1} KB this window before per-message wire overhead");
+                double perBundle = bEmit > 0 ? 1.0 / bEmit : 0;       // 0 collapses every per-bundle average to 0
+
+                AppendInv(line, $" | bundles {bEmit} {bEmit / (double)ticks:F2}/t {bMsg}msg {bTail}tail {bFallback}fb");
+                AppendInv(line, $" {bMsg * perBundle:F1}msg/b {bRaw * perBundle:F0}→{bComp * perBundle:F0}B {ratio:F3} {savedPct:F1}% {(bRaw - bComp) / 1024.0:F1}KB");
+                AppendInv(line, $" deflate {deflateMs / ticks:F3}ms/t {deflateMs * pctOfTotal:F1}% {deflateMs * 1000.0 * perBundle:F1}µs/b retry {bRetry} {bRetry * perBundle * 100.0:F1}%");
             }
+
+            BNL.Log(line.ToString());
         }
+
+        /// <summary>
+        /// Invariant culture so a comma-decimal host still emits numbers a log scraper can read —
+        /// the same reason the health endpoint pins it.
+        /// </summary>
+        private static void AppendInv(StringBuilder sb, FormattableString text) =>
+            sb.Append(FormattableString.Invariant(text));
+
+        private static void AppendPhase(StringBuilder sb, string name, double ms, long ticks, double pctOfTotal) =>
+            AppendInv(sb, $" {name} {ms / ticks:F3} {ms * pctOfTotal:F0}%");
     }
 }