Skip to content

Commit 6f9530b

Browse files
LisiasLisias
committed
Somewhat more sensible performance logging.
1 parent 6e0d2c2 commit 6f9530b

File tree

12 files changed

+147
-55
lines changed

12 files changed

+147
-55
lines changed

‎Source/ModuleManager/MMPatchLoader.cs‎

Lines changed: 28 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,5 @@
11
using System;
22
using System.Collections.Generic;
3-
using System.Diagnostics;
43
using System.Diagnostics.CodeAnalysis;
54
using System.Globalization;
65
using System.IO;
@@ -15,7 +14,6 @@
1514
using ModuleManager.Threading;
1615
using ModuleManager.Tags;
1716
using ModuleManager.Patches;
18-
using ModuleManager.Progress;
1917
using NodeStack = ModuleManager.Collections.ImmutableStack<ConfigNode>;
2018

2119
using static ModuleManager.FilePathRepository;
@@ -41,22 +39,25 @@ public class MMPatchLoader : LoadingSystem
4139

4240
private readonly IEnumerable<ModListGenerator.ModAddedByAssembly> modsAddedByAssemblies;
4341
private readonly IBasicLogger logger;
42+
private readonly Progress.ProgressCounter counter;
43+
private readonly Progress.Timings timings;
4444

4545
public static void AddPostPatchCallback(ModuleManagerPostPatchCallback callback)
4646
{
4747
PostPatchLoader.AddPostPatchCallback(callback);
4848
}
4949

50-
public MMPatchLoader(IEnumerable<ModListGenerator.ModAddedByAssembly> modsAddedByAssemblies, IBasicLogger logger)
50+
public MMPatchLoader(IEnumerable<ModListGenerator.ModAddedByAssembly> modsAddedByAssemblies, IBasicLogger logger, Progress.ProgressCounter counter, Progress.Timings timings)
5151
{
5252
this.modsAddedByAssemblies = modsAddedByAssemblies ?? throw new ArgumentNullException(nameof(modsAddedByAssemblies));
5353
this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
54+
this.counter = counter;
55+
this.timings = timings;
5456
}
5557

5658
public IEnumerable<IProtoUrlConfig> Run()
5759
{
58-
Stopwatch patchSw = new Stopwatch();
59-
patchSw.Start();
60+
this.timings.Patching.Start();
6061

6162
status = "Checking Cache";
6263
logger.Info(status);
@@ -79,7 +80,7 @@ public IEnumerable<IProtoUrlConfig> Run()
7980
{
8081
IBasicLogger patchLogger = new PatchLogger(FilePathRepository.PATCH_LOG_FILENAME);
8182

82-
IPatchProgress progress = new PatchProgress(patchLogger);
83+
Progress.IPatchProgress progress = new Progress.PatchProgress(patchLogger, this.counter);
8384
status = "Pre patch init";
8485
patchLogger.Info(status);
8586
IEnumerable<string> mods = ModListGenerator.GenerateModList(modsAddedByAssemblies, progress, patchLogger);
@@ -148,14 +149,14 @@ public IEnumerable<IProtoUrlConfig> Run()
148149

149150
#region Saving Cache
150151

151-
foreach (KeyValuePair<string, int> item in progress.Counter.warningFiles)
152+
foreach (KeyValuePair<string, int> item in this.counter.warningFiles)
152153
{
153154
patchLogger.Warning(item.Value + " warning" + (item.Value > 1 ? "s" : "") + " related to GameData/" + item.Key);
154155
}
155156

156-
if (progress.Counter.errors > 0 || progress.Counter.exceptions > 0)
157+
if (this.counter.errors > 0 || this.counter.exceptions > 0)
157158
{
158-
foreach (KeyValuePair<string, int> item in progress.Counter.errorFiles)
159+
foreach (KeyValuePair<string, int> item in this.counter.errorFiles)
159160
{
160161
errors += item.Value + " error" + (item.Value > 1 ? "s" : "") + " related to GameData/" + item.Key
161162
+ "\n";
@@ -175,8 +176,8 @@ public IEnumerable<IProtoUrlConfig> Run()
175176
else
176177
{
177178
status = "Saving Cache";
178-
patchLogger.Info(status);
179-
CreateCache(databaseConfigs, progress.Counter.patchedNodes);
179+
CreateCache(databaseConfigs, this.counter.patchedNodes);
180+
patchLogger.Info("Cache saved.");
180181
}
181182

182183
patchLogger.Finish();
@@ -220,8 +221,8 @@ public IEnumerable<IProtoUrlConfig> Run()
220221

221222
logger.Info(status);
222223

223-
patchSw.Stop();
224-
logger.Info("Ran in " + ((float)patchSw.ElapsedMilliseconds / 1000).ToString("F3") + "s");
224+
this.timings.Patching.Stop();
225+
logger.Info("Ran in " + this.timings.Patching);
225226

226227
return databaseConfigs;
227228
}
@@ -262,8 +263,7 @@ private void SaveModdedPhysics(IEnumerable<IProtoUrlConfig> databaseConfigs)
262263

263264
private bool IsCacheUpToDate()
264265
{
265-
Stopwatch sw = new Stopwatch();
266-
sw.Start();
266+
this.timings.ShaCalc.Start();
267267

268268
System.Security.Cryptography.SHA256 sha = System.Security.Cryptography.SHA256.Create();
269269
System.Security.Cryptography.SHA256 filesha = System.Security.Cryptography.SHA256.Create();
@@ -314,9 +314,9 @@ private bool IsCacheUpToDate()
314314
sha.Clear();
315315
filesha.Clear();
316316

317-
sw.Stop();
317+
this.timings.ShaCalc.Stop();
318318

319-
logger.Info("SHA generated in " + ((float)sw.ElapsedMilliseconds / 1000).ToString("F3") + "s");
319+
logger.Info("SHA generated in " + this.timings.ShaCalc);
320320
logger.Info(" SHA = " + configSha);
321321

322322
bool useCache = false;
@@ -494,7 +494,10 @@ private IEnumerable<IProtoUrlConfig> LoadCache()
494494
ConfigNode cache = CACHE_CONFIG.Load().Node;
495495

496496
if (cache.HasValue("patchedNodeCount") && int.TryParse(cache.GetValue("patchedNodeCount"), out int patchedNodeCount))
497+
{
497498
status = "ModuleManager: " + patchedNodeCount + " patch" + (patchedNodeCount != 1 ? "es" : "") + " loaded from cache";
499+
this.counter.patchedNodes.Set(patchedNodeCount);
500+
}
498501

499502
// Create the fake file where we load the physic config cache
500503
UrlDir gameDataDir = GameDatabase.Instance.root.AllDirectories.First(d => d.path.EndsWith("GameData") && d.name == "" && d.url == "");
@@ -524,23 +527,23 @@ private IEnumerable<IProtoUrlConfig> LoadCache()
524527
return databaseConfigs;
525528
}
526529

527-
private void StatusUpdate(IPatchProgress progress, string activity = null)
530+
private void StatusUpdate(Progress.IPatchProgress progress, string activity = null)
528531
{
529-
status = "ModuleManager: " + progress.Counter.patchedNodes + " patch" + (progress.Counter.patchedNodes != 1 ? "es" : "") + " applied";
532+
status = "ModuleManager: " + this.counter.patchedNodes + " patch" + (this.counter.patchedNodes != 1 ? "es" : "") + " applied";
530533
if (progress.ProgressFraction < 1f - float.Epsilon)
531534
status += " (" + progress.ProgressFraction.ToString("P0") + ")";
532535

533536
if (activity != null)
534537
status += "\n" + activity;
535538

536-
if (progress.Counter.warnings > 0)
537-
status += ", found <color=yellow>" + progress.Counter.warnings + " warning" + (progress.Counter.warnings != 1 ? "s" : "") + "</color>";
539+
if (this.counter.warnings > 0)
540+
status += ", found <color=yellow>" + this.counter.warnings + " warning" + (this.counter.warnings != 1 ? "s" : "") + "</color>";
538541

539-
if (progress.Counter.errors > 0)
540-
status += ", found <color=orange>" + progress.Counter.errors + " error" + (progress.Counter.errors != 1 ? "s" : "") + "</color>";
542+
if (this.counter.errors > 0)
543+
status += ", found <color=orange>" + this.counter.errors + " error" + (this.counter.errors != 1 ? "s" : "") + "</color>";
541544

542-
if (progress.Counter.exceptions > 0)
543-
status += ", encountered <color=red>" + progress.Counter.exceptions + " exception" + (progress.Counter.exceptions != 1 ? "s" : "") + "</color>";
545+
if (this.counter.exceptions > 0)
546+
status += ", encountered <color=red>" + this.counter.exceptions + " exception" + (this.counter.exceptions != 1 ? "s" : "") + "</color>";
544547
}
545548

546549
#region Applying Patches

‎Source/ModuleManager/MMPatchRunner.cs‎

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
using System;
22
using System.Collections;
33
using System.Collections.Generic;
4-
using System.IO;
54
using ModuleManager.Extensions;
65
using ModuleManager.Logging;
76
using ModuleManager.Threading;
@@ -13,13 +12,19 @@ namespace ModuleManager
1312
public class MMPatchRunner
1413
{
1514
private readonly IBasicLogger kspLogger;
15+
private readonly Progress.ProgressCounter counter;
16+
private readonly Progress.Timings timings;
1617

1718
public string Status { get; private set; } = "";
1819
public string Errors { get; private set; } = "";
1920

20-
public MMPatchRunner(IBasicLogger kspLogger)
21+
internal MMPatchLoader patchLoader;
22+
23+
public MMPatchRunner(IBasicLogger kspLogger, Progress.ProgressCounter counter, Progress.Timings timings)
2124
{
2225
this.kspLogger = kspLogger ?? throw new ArgumentNullException(nameof(kspLogger));
26+
this.counter = counter;
27+
this.timings = timings;
2328
}
2429

2530
public IEnumerator Run()
@@ -33,7 +38,7 @@ public IEnumerator Run()
3338
IEnumerable<ModListGenerator.ModAddedByAssembly> modsAddedByAssemblies = ModListGenerator.GetAdditionalModsFromStaticMethods(ModLogger.Instance);
3439

3540
IEnumerable<IProtoUrlConfig> databaseConfigs = null;
36-
MMPatchLoader patchLoader = new MMPatchLoader(modsAddedByAssemblies, ModLogger.Instance);
41+
this.patchLoader = new MMPatchLoader(modsAddedByAssemblies, ModLogger.Instance, this.counter, this.timings);
3742

3843
ITaskStatus patchingThreadStatus = BackgroundTask.Start(delegate
3944
{

‎Source/ModuleManager/ModuleManager.cs‎

Lines changed: 36 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -52,13 +52,21 @@ public class ModuleManager : MonoBehaviour
5252
private GUI.Menu menu;
5353

5454
internal MMPatchRunner patchRunner;
55+
private readonly Progress.ProgressCounter counter;
56+
private readonly Progress.Timings timings;
5557

5658
private InterceptLogHandler interceptLogHandler;
5759

5860
#endregion state
5961

6062
private static bool loadedInScene;
6163

64+
private ModuleManager()
65+
{
66+
this.counter = new Progress.ProgressCounter();
67+
this.timings = new Progress.Timings();
68+
}
69+
6270
internal void OnRnDCenterSpawn()
6371
{
6472
inRnDCenter = true;
@@ -138,8 +146,9 @@ internal void Awake()
138146

139147
Log("Adding post patch to the loading screen {0}", list.Count);
140148
list.Insert(gameDatabaseIndex + 1, aGameObject.AddComponent<PostPatchLoader>());
149+
PostPatchLoader.Instance.Set(this.timings);
141150

142-
patchRunner = new MMPatchRunner(ModLogger.Instance);
151+
this.patchRunner = new MMPatchRunner(ModLogger.Instance, this.counter, this.timings);
143152
StartCoroutine(patchRunner.Run());
144153

145154
// Workaround for 1.6.0 Editor bug after a PartDatabase rebuild.
@@ -231,7 +240,30 @@ internal void Update()
231240
if (PerformanceMetrics.Instance.IsRunning && HighLogic.LoadedScene == GameScenes.MAINMENU)
232241
{
233242
PerformanceMetrics.Instance.Stop();
234-
Log("Total loading Time = " + PerformanceMetrics.Instance.ElapsedTimeInSecs.ToString("F3") + "s");
243+
if (0 == this.counter.totalPatches.Value)
244+
{
245+
Log("Loaded {0} patch(es) from cache."
246+
, this.counter.patchedNodes.Value
247+
);
248+
Log("Total loading Time = {0:0.000}s."
249+
, PerformanceMetrics.Instance.ElapsedTimeInSecs
250+
);
251+
}
252+
else
253+
{
254+
Log("Found {0} and applied {1} patch(es), with {2} warning(s) and {3} error(s). {4} node(s) patched."
255+
, this.counter.totalPatches.Value
256+
, this.counter.appliedPatches.Value
257+
, this.counter.warnings.Value
258+
, this.counter.errors.Value
259+
, this.counter.patchedNodes.Value
260+
);
261+
Log("Total loading Time = {0:0.000}s, with {1} on patching and {2} on post patching (both parallel to loading)."
262+
, PerformanceMetrics.Instance.ElapsedTimeInSecs
263+
, (string)this.timings.Patching
264+
, (string)this.timings.PostPatching
265+
);
266+
}
235267
PerformanceMetrics.Instance.Destroy();
236268
}
237269

@@ -281,7 +313,7 @@ internal IEnumerator DataBaseReloadWithMM(bool dump = false)
281313
GUI.ReloadingDatabaseDialog reloadingDialog = GUI.ReloadingDatabaseDialog.Show(this);
282314
try
283315
{
284-
patchRunner = new MMPatchRunner(ModLogger.Instance);
316+
patchRunner = new MMPatchRunner(ModLogger.Instance, this.counter, this.timings);
285317

286318
yield return null;
287319

@@ -295,7 +327,7 @@ internal IEnumerator DataBaseReloadWithMM(bool dump = false)
295327
while (!GameDatabase.Instance.IsReady())
296328
yield return null;
297329

298-
PostPatchLoader.Instance.StartLoad();
330+
PostPatchLoader.Instance.Set(this.timings);
299331

300332
while (!PostPatchLoader.Instance.IsReady())
301333
yield return null;

‎Source/ModuleManager/ModuleManager.csproj‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -137,6 +137,8 @@
137137
<Compile Include="Utils\PerformanceMetrics.cs" />
138138
<Compile Include="Logging\PatchLogger.cs" />
139139
<Compile Include="Properties\LegalMamboJambo.cs" />
140+
<Compile Include="Progress\Timings.cs" />
141+
<Compile Include="Utils\Stopwatch.cs" />
140142
</ItemGroup>
141143
<ItemGroup>
142144
<Reference Include="System" />

‎Source/ModuleManager/PostPatchLoader.cs‎

Lines changed: 14 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,6 @@
11
using System;
2-
using System.IO;
32
using System.Collections;
43
using System.Collections.Generic;
5-
using System.Diagnostics;
64
using System.Reflection;
75
using UnityEngine;
86
using ModuleManager.Extensions;
@@ -24,6 +22,7 @@ public class PostPatchLoader : LoadingSystem
2422
private static readonly List<ModuleManagerPostPatchCallback> postPatchCallbacks = new List<ModuleManagerPostPatchCallback>();
2523

2624
private readonly IBasicLogger logger = ModLogger.Instance;
25+
private Progress.Timings timings;
2726

2827
private bool ready = false;
2928

@@ -62,20 +61,25 @@ public override void StartLoad()
6261
StartCoroutine(Run());
6362
}
6463

64+
internal void Set(Progress.Timings timings)
65+
{
66+
this.timings = timings;
67+
}
68+
6569
private IEnumerator Run()
6670
{
67-
Stopwatch waitTimer = new Stopwatch();
68-
waitTimer.Start();
71+
while (null == this.timings) yield return null;
72+
73+
this.timings.Wait.Start();
6974

7075
progressTitle = "ModuleManager: Waiting for patching to finish";
7176

7277
while (databaseConfigs == null) yield return null;
7378

74-
waitTimer.Stop();
75-
logger.Info("Waited " + ((float)waitTimer.ElapsedMilliseconds / 1000).ToString("F3") + "s for patching to finish");
79+
this.timings.Wait.Stop();
80+
logger.Info("Waited " + this.timings.Wait + " for patching to finish");
7681

77-
Stopwatch postPatchTimer = new Stopwatch();
78-
postPatchTimer.Start();
82+
this.timings.PostPatching.Start();
7983

8084
progressTitle = "ModuleManager: Applying patched game database";
8185
logger.Info("Applying patched game database");
@@ -203,8 +207,8 @@ private IEnumerator Run()
203207
if (ModuleManager.dumpPostPatch)
204208
ModuleManager.OutputAllConfigs();
205209

206-
postPatchTimer.Stop();
207-
logger.Info("Post patch ran in " + ((float)postPatchTimer.ElapsedMilliseconds / 1000).ToString("F3") + "s");
210+
this.timings.PostPatching.Stop();
211+
logger.Info("Post patch ran in " + this.timings.PostPatching);
208212

209213
ready = true;
210214
}

‎Source/ModuleManager/Progress/IPatchProgress.cs‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,6 @@ namespace ModuleManager.Progress
44
{
55
public interface IPatchProgress
66
{
7-
ProgressCounter Counter { get; }
8-
97
float ProgressFraction { get; }
108

119
EventVoid OnPatchApplied { get; }

‎Source/ModuleManager/Progress/PatchProgress.cs‎

Lines changed: 2 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -23,16 +23,10 @@ public float ProgressFraction
2323
public EventVoid OnPatchApplied { get; } = new EventVoid("OnPatchApplied");
2424
public EventData<IPass> OnPassStarted { get; } = new EventData<IPass>("OnPassStarted");
2525

26-
public PatchProgress(IBasicLogger logger)
26+
public PatchProgress(IBasicLogger logger, ProgressCounter counter)
2727
{
2828
this.logger = logger;
29-
Counter = new ProgressCounter();
30-
}
31-
32-
public PatchProgress(IPatchProgress progress, IBasicLogger logger)
33-
{
34-
this.logger = logger;
35-
Counter = progress.Counter;
29+
this.Counter = counter;
3630
}
3731

3832
public void PatchAdded()

‎Source/ModuleManager/Progress/ProgressCounter.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ public class ProgressCounter
88
{
99
public readonly Counter totalPatches = new Counter();
1010
public readonly Counter appliedPatches = new Counter();
11-
public readonly Counter patchedNodes = new Counter();
11+
public readonly SetableCounter patchedNodes = new SetableCounter();
1212
public readonly Counter warnings = new Counter();
1313
public readonly Counter errors = new Counter();
1414
public readonly Counter exceptions = new Counter();

‎Source/ModuleManager/Progress/Timings.cs‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
using ModuleManager.Utils;
2+
3+
namespace ModuleManager.Progress
4+
{
5+
public class Timings
6+
{
7+
internal Stopwatch Wait = new Stopwatch();
8+
internal Stopwatch Patching = new Stopwatch();
9+
internal Stopwatch PostPatching = new Stopwatch();
10+
internal Stopwatch ShaCalc = new Stopwatch();
11+
}
12+
}

0 commit comments

Comments
 (0)