From fb395ecf77f098175018bd3ba033fd05d12f70d5 Mon Sep 17 00:00:00 2001 From: SuddyN Date: Mon, 12 May 2025 10:29:15 -0400 Subject: [PATCH 1/5] implement PerfTest.cs --- util/PerfTest/PerfTest.cs | 350 +++++++++++++++++++++++++++++++++++--- 1 file changed, 331 insertions(+), 19 deletions(-) diff --git a/util/PerfTest/PerfTest.cs b/util/PerfTest/PerfTest.cs index 4439973..7fa7452 100644 --- a/util/PerfTest/PerfTest.cs +++ b/util/PerfTest/PerfTest.cs @@ -1,57 +1,337 @@ +using System.Buffers; using System.Collections.Concurrent; +using System.Diagnostics; +using Microsoft.Extensions.Caching.Distributed; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; using NATS.Client.Core; +using NATS.Client.KeyValueStore; +using NATS.Net; namespace CodeCargo.NatsDistributedCache.PerfTest; +/// +/// Performance test for NatsCache that tracks cache operations +/// public class PerfTest { + // Configuration + private const int NumCacheItems = 10_000; + private const int KeyExpirySecs = 5; + private const int MaxTestRuntimeSecs = 60; + private const int FieldWidth = 12; + private const int BatchSize = 100; + + // Dependencies private readonly INatsConnection _nats; + private readonly NatsCache _cache; + + // Stats tracking + private readonly Stopwatch _stopwatch = new(); private readonly ConcurrentDictionary _stats = new(); + private readonly List _activeKeys = []; + private readonly Random _random = new(42); // Fixed seed for reproducibility + + // Operation tracking via kvstore watcher + private readonly SemaphoreSlim _watchLock = new(1, 1); + private NatsKVStore? _kvStore; public PerfTest(INatsConnection nats) { _nats = nats; + var options = Options.Create(new NatsCacheOptions + { + BucketName = "cache" + }); + + _cache = new NatsCache(options, NullLogger.Instance, nats); + // Initialize statistics counters _stats["KeysInserted"] = 0; _stats["KeysRetrieved"] = 0; _stats["KeysExpired"] = 0; + _stats["OperationsPerSec"] = 0; + _stats["CurrentKeys"] = 0; } public async Task Run(CancellationToken cancellationToken) { - var cts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + Console.WriteLine($"Starting CodeCargo NatsDistributedCache Performance Test - {DateTime.Now}"); + Console.WriteLine($"Testing with {NumCacheItems} cache items"); + + using var cts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + cts.CancelAfter(TimeSpan.FromSeconds(MaxTestRuntimeSecs)); - // Create tasks for printing stats and watching metrics + // Create and connect the watcher to track operations + await InitializeWatcher(cts.Token); + + // Start timer + _stopwatch.Start(); + + // Create tasks for the test operations var printTask = StartPrintTask(cts.Token); var watchTask = StartWatchTask(cts.Token); + var insertTask = StartInsertTask(cts.Token); + var retrieveTask = StartRetrieveTask(cts.Token); + var expireTask = StartExpireTask(cts.Token); + + try + { + // Wait for all tasks to complete or cancellation + await Task.WhenAll(watchTask, insertTask, retrieveTask, expireTask); + } + catch (OperationCanceledException) + { + // Expected when test completes + } + finally + { + // Stop stopwatch + _stopwatch.Stop(); + + // Make sure print task completes + await cts.CancelAsync(); + try + { + await printTask; + } + catch (OperationCanceledException) + { + // Ignore + } - // todo: test logic - await Task.Delay(TimeSpan.FromSeconds(5), cts.Token); + // Print final stats + PrintFinalStats(); + } + } + + private static string FormatElapsedTime(TimeSpan elapsed) => + $"{Math.Floor(elapsed.TotalMinutes):00}:{elapsed.Seconds:00}.{elapsed.Milliseconds / 10:00}"; - await cts.CancelAsync(); + private byte[] GenerateRandomData(int size) + { + var data = new byte[size]; + _random.NextBytes(data); + return data; + } - // Wait for all tasks to complete or cancellation - await Task.WhenAll(printTask, watchTask); + private async Task InitializeWatcher(CancellationToken ct) + { + await _watchLock.WaitAsync(ct); + try + { + if (_kvStore == null) + { + var jsContext = _nats.CreateJetStreamContext(); + var kvContext = new NatsKVContext(jsContext); + _kvStore = (NatsKVStore)await kvContext.GetStoreAsync("cache", ct); + } + } + finally + { + _watchLock.Release(); + } } - private static Task StartWatchTask(CancellationToken ct) => + private Task StartInsertTask(CancellationToken ct) => Task.Run( async () => { try { + for (var i = 0; i < NumCacheItems && !ct.IsCancellationRequested; i++) + { + // Create a batch of items + for (var j = 0; j < BatchSize && i + j < NumCacheItems && !ct.IsCancellationRequested; j++) + { + var key = $"BatchNum{i}IndividualNum{j}"; + var data = GenerateRandomData(256); // 256 byte values + + try + { + var options = new DistributedCacheEntryOptions + { + AbsoluteExpirationRelativeToNow = TimeSpan.FromSeconds(KeyExpirySecs + _random.Next(KeyExpirySecs)) + }; + + await _cache.SetAsync(key, data, options, ct); + + lock (_activeKeys) + { + _activeKeys.Add(key); + } + + // Note: actual count is tracked by the watcher + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + Console.WriteLine($"Insert error: {ex.Message}"); + } + } + + // Small delay between batches + await Task.Delay(10, ct); + } + } + catch (OperationCanceledException) + { + // Ignore cancellation + } + }, + ct); + + private Task StartRetrieveTask(CancellationToken ct) => + Task.Run( + async () => + { + try + { + // Wait a bit before starting retrieval operations + await Task.Delay(1000, ct); + while (!ct.IsCancellationRequested) { - // TODO: Implement watching for cache operations and updating stats + string? key = null; + + lock (_activeKeys) + { + if (_activeKeys.Count > 0) + { + var index = _random.Next(_activeKeys.Count); + key = _activeKeys[index]; + } + } - // Wait before checking again - await Task.Delay(100, ct); + if (key != null) + { + try + { + await _cache.GetAsync(key, ct); + + // Note: actual count is tracked by the watcher + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + Console.WriteLine($"Retrieve error: {ex.Message}"); + } + } + + await Task.Delay(5, ct); // Small delay between retrievals } } catch (OperationCanceledException) { - // Ignore cancellation exceptions + // Ignore cancellation + } + }, + ct); + + private Task StartExpireTask(CancellationToken ct) => + Task.Run( + async () => + { + try + { + // Wait a bit before starting expiry operations + await Task.Delay(2000, ct); + + while (!ct.IsCancellationRequested) + { + string? key = null; + + lock (_activeKeys) + { + if (_activeKeys.Count > 0) + { + var index = _random.Next(_activeKeys.Count); + key = _activeKeys[index]; + _activeKeys.RemoveAt(index); + } + } + + if (key != null) + { + try + { + await _cache.RemoveAsync(key, ct); + + // Note: actual count is tracked by the watcher + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + Console.WriteLine($"Expire error: {ex.Message}"); + } + } + + await Task.Delay(50, ct); // Less frequent expiry operations + } + } + catch (OperationCanceledException) + { + // Ignore cancellation + } + }, + ct); + + private Task StartWatchTask(CancellationToken ct) => + Task.Run( + async () => + { + try + { + if (_kvStore == null) + { + Console.WriteLine("KV Store not initialized"); + return; + } + + var opsBuffer = new List(); + var statsUpdateInterval = TimeSpan.FromMilliseconds(500); + var lastStatsUpdate = DateTimeOffset.Now; + + await foreach (var entry in _kvStore.WatchAsync>( + ">", + opts: new NatsKVWatchOpts { MetaOnly = true }, + cancellationToken: ct)) + { + opsBuffer.Add(entry.Operation); + + // Update stats periodically instead of on every operation + if (DateTimeOffset.Now - lastStatsUpdate > statsUpdateInterval) + { + // var gets = opsBuffer.Count(op => op == NatsKVOperation.Get); + var puts = opsBuffer.Count(op => op == NatsKVOperation.Put); + var deletes = opsBuffer.Count(op => op == NatsKVOperation.Del); + + // _stats["KeysRetrieved"] += gets; + _stats["KeysInserted"] += puts; + _stats["KeysExpired"] += deletes; + + // Update current keys count + _stats["CurrentKeys"] = _stats["KeysInserted"] - _stats["KeysExpired"]; + + // Calculate operations per second + var elapsed = _stopwatch.Elapsed.TotalSeconds; + if (elapsed > 0) + { + var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; + _stats["OperationsPerSec"] = (long)(totalOps / elapsed); + } + + opsBuffer.Clear(); + lastStatsUpdate = DateTimeOffset.Now; + } + } + } + catch (OperationCanceledException) + { + // Ignore cancellation + } + catch (Exception ex) + { + Console.WriteLine($"Watch error: {ex.Message}"); } }, ct); @@ -64,15 +344,11 @@ private Task StartPrintTask(CancellationToken ct) => { while (!ct.IsCancellationRequested) { - // Clear + // Clear console Console.Clear(); // Print current statistics - Console.WriteLine("======== Per Stats ========"); - Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"]}"); - Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"]}"); - Console.WriteLine($"Keys Expired: {_stats["KeysExpired"]}"); - Console.WriteLine("==========================="); + PrintProgress(); // Wait before printing again await Task.Delay(TimeSpan.FromSeconds(1), ct); @@ -80,8 +356,44 @@ private Task StartPrintTask(CancellationToken ct) => } catch (OperationCanceledException) { - // Ignore cancellation exceptions + // Ignore cancellation } }, ct); + + private void PrintProgress() + { + Console.WriteLine("========== CodeCargo NatsDistributedCache Performance =========="); + Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); + Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); + Console.WriteLine($"Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); + Console.WriteLine($"Elapsed Time: {FormatElapsedTime(_stopwatch.Elapsed),FieldWidth}"); + Console.WriteLine("=========================================================="); + } + + private void PrintFinalStats() + { + Console.Clear(); + Console.WriteLine("========== CodeCargo NatsDistributedCache Test Summary =========="); + Console.WriteLine($"Test completed at: {DateTime.Now}"); + Console.WriteLine($"Total test duration: {FormatElapsedTime(_stopwatch.Elapsed)}"); + Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Total Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); + Console.WriteLine($"Total Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); + Console.WriteLine($"Total Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Final Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Average Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); + Console.WriteLine("=========================================================="); + + // Also log memory usage + var meg = Math.Pow(2, 20); + var memoryMiB = Process.GetCurrentProcess().PrivateMemorySize64 / meg; + var allocMiB = GC.GetTotalAllocatedBytes() / meg; + Console.WriteLine($"Memory Usage MiB: {memoryMiB,FieldWidth:N0}"); + Console.WriteLine($"Total Alloc MiB: {allocMiB,FieldWidth:N0}"); + } } From 4d9f0e775afc97e793d2652aa8ba142165329a57 Mon Sep 17 00:00:00 2001 From: SuddyN Date: Mon, 12 May 2025 10:52:09 -0400 Subject: [PATCH 2/5] update PerfTest configuration --- util/PerfTest/PerfTest.cs | 41 ++++++++++++++++++++++++--------------- 1 file changed, 25 insertions(+), 16 deletions(-) diff --git a/util/PerfTest/PerfTest.cs b/util/PerfTest/PerfTest.cs index 7fa7452..ad04434 100644 --- a/util/PerfTest/PerfTest.cs +++ b/util/PerfTest/PerfTest.cs @@ -17,11 +17,15 @@ namespace CodeCargo.NatsDistributedCache.PerfTest; public class PerfTest { // Configuration - private const int NumCacheItems = 10_000; - private const int KeyExpirySecs = 5; private const int MaxTestRuntimeSecs = 60; + private const int NumCacheItems = 10_000; private const int FieldWidth = 12; private const int BatchSize = 100; + private const int ValueDataSizeBytes = 256; + private const int KeyExpirySecs = 2; + private const int InsertDelayMs = 10; + private const int RetrieveDelayMs = 5; + private const int RemoveDelayMs = 50; // Dependencies private readonly INatsConnection _nats; @@ -147,7 +151,7 @@ private Task StartInsertTask(CancellationToken ct) => for (var j = 0; j < BatchSize && i + j < NumCacheItems && !ct.IsCancellationRequested; j++) { var key = $"BatchNum{i}IndividualNum{j}"; - var data = GenerateRandomData(256); // 256 byte values + var data = GenerateRandomData(ValueDataSizeBytes); // 256 byte values try { @@ -172,7 +176,7 @@ private Task StartInsertTask(CancellationToken ct) => } // Small delay between batches - await Task.Delay(10, ct); + await Task.Delay(InsertDelayMs, ct); } } catch (OperationCanceledException) @@ -218,7 +222,7 @@ private Task StartRetrieveTask(CancellationToken ct) => } } - await Task.Delay(5, ct); // Small delay between retrievals + await Task.Delay(RetrieveDelayMs, ct); // Small delay between retrievals } } catch (OperationCanceledException) @@ -265,7 +269,7 @@ private Task StartExpireTask(CancellationToken ct) => } } - await Task.Delay(50, ct); // Less frequent expiry operations + await Task.Delay(RemoveDelayMs, ct); // Less frequent expiry operations } } catch (OperationCanceledException) @@ -363,30 +367,35 @@ private Task StartPrintTask(CancellationToken ct) => private void PrintProgress() { + var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; Console.WriteLine("========== CodeCargo NatsDistributedCache Performance =========="); - Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); - Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); - Console.WriteLine($"Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); - Console.WriteLine($"Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine($"Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); + Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); + Console.WriteLine($"Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); - Console.WriteLine($"Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); - Console.WriteLine($"Elapsed Time: {FormatElapsedTime(_stopwatch.Elapsed),FieldWidth}"); + Console.WriteLine($"Elapsed Time: {FormatElapsedTime(_stopwatch.Elapsed),FieldWidth}"); + Console.WriteLine($"Time Remaining: {FormatElapsedTime(TimeSpan.FromSeconds(MaxTestRuntimeSecs) - _stopwatch.Elapsed),FieldWidth}"); + Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); + Console.WriteLine($"Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); Console.WriteLine("=========================================================="); } private void PrintFinalStats() { + var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; Console.Clear(); Console.WriteLine("========== CodeCargo NatsDistributedCache Test Summary =========="); - Console.WriteLine($"Test completed at: {DateTime.Now}"); - Console.WriteLine($"Total test duration: {FormatElapsedTime(_stopwatch.Elapsed)}"); + Console.WriteLine($"Test completed at: {DateTime.Now}"); + Console.WriteLine($"Total test duration: {FormatElapsedTime(_stopwatch.Elapsed)}"); Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Final Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); - Console.WriteLine($"Final Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); - Console.WriteLine($"Average Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); + Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); + Console.WriteLine($"Average Ops/Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); Console.WriteLine("=========================================================="); // Also log memory usage From 92cf83d04acaa51a2046711f02bae5759706ef0c Mon Sep 17 00:00:00 2001 From: SuddyN Date: Mon, 12 May 2025 14:20:05 -0400 Subject: [PATCH 3/5] track retrievals --- util/PerfTest/PerfTest.cs | 84 ++++++++++++++++++++------------------- 1 file changed, 43 insertions(+), 41 deletions(-) diff --git a/util/PerfTest/PerfTest.cs b/util/PerfTest/PerfTest.cs index ad04434..13b8e80 100644 --- a/util/PerfTest/PerfTest.cs +++ b/util/PerfTest/PerfTest.cs @@ -26,6 +26,7 @@ public class PerfTest private const int InsertDelayMs = 10; private const int RetrieveDelayMs = 5; private const int RemoveDelayMs = 50; + private const int StatsUpdateIntervalMs = 500; // Dependencies private readonly INatsConnection _nats; @@ -55,9 +56,7 @@ public PerfTest(INatsConnection nats) // Initialize statistics counters _stats["KeysInserted"] = 0; _stats["KeysRetrieved"] = 0; - _stats["KeysExpired"] = 0; - _stats["OperationsPerSec"] = 0; - _stats["CurrentKeys"] = 0; + _stats["KeysRemoved"] = 0; } public async Task Run(CancellationToken cancellationToken) @@ -79,12 +78,12 @@ public async Task Run(CancellationToken cancellationToken) var watchTask = StartWatchTask(cts.Token); var insertTask = StartInsertTask(cts.Token); var retrieveTask = StartRetrieveTask(cts.Token); - var expireTask = StartExpireTask(cts.Token); + var removeTask = StartRemoveTask(cts.Token); try { // Wait for all tasks to complete or cancellation - await Task.WhenAll(watchTask, insertTask, retrieveTask, expireTask); + await Task.WhenAll(watchTask, insertTask, retrieveTask, removeTask); } catch (OperationCanceledException) { @@ -213,8 +212,7 @@ private Task StartRetrieveTask(CancellationToken ct) => try { await _cache.GetAsync(key, ct); - - // Note: actual count is tracked by the watcher + _stats.AddOrUpdate("KeysRetrieved", 1, (_, count) => count + 1); } catch (Exception ex) when (ex is not OperationCanceledException) { @@ -232,7 +230,7 @@ private Task StartRetrieveTask(CancellationToken ct) => }, ct); - private Task StartExpireTask(CancellationToken ct) => + private Task StartRemoveTask(CancellationToken ct) => Task.Run( async () => { @@ -265,7 +263,7 @@ private Task StartExpireTask(CancellationToken ct) => } catch (Exception ex) when (ex is not OperationCanceledException) { - Console.WriteLine($"Expire error: {ex.Message}"); + Console.WriteLine($"Remove error: {ex.Message}"); } } @@ -292,7 +290,7 @@ private Task StartWatchTask(CancellationToken ct) => } var opsBuffer = new List(); - var statsUpdateInterval = TimeSpan.FromMilliseconds(500); + var statsUpdateInterval = TimeSpan.FromMilliseconds(StatsUpdateIntervalMs); var lastStatsUpdate = DateTimeOffset.Now; await foreach (var entry in _kvStore.WatchAsync>( @@ -301,30 +299,9 @@ private Task StartWatchTask(CancellationToken ct) => cancellationToken: ct)) { opsBuffer.Add(entry.Operation); - - // Update stats periodically instead of on every operation - if (DateTimeOffset.Now - lastStatsUpdate > statsUpdateInterval) + if (DateTimeOffset.Now - lastStatsUpdate <= statsUpdateInterval) { - // var gets = opsBuffer.Count(op => op == NatsKVOperation.Get); - var puts = opsBuffer.Count(op => op == NatsKVOperation.Put); - var deletes = opsBuffer.Count(op => op == NatsKVOperation.Del); - - // _stats["KeysRetrieved"] += gets; - _stats["KeysInserted"] += puts; - _stats["KeysExpired"] += deletes; - - // Update current keys count - _stats["CurrentKeys"] = _stats["KeysInserted"] - _stats["KeysExpired"]; - - // Calculate operations per second - var elapsed = _stopwatch.Elapsed.TotalSeconds; - if (elapsed > 0) - { - var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; - _stats["OperationsPerSec"] = (long)(totalOps / elapsed); - } - - opsBuffer.Clear(); + await UpdateStatsIfNeeded(opsBuffer); lastStatsUpdate = DateTimeOffset.Now; } } @@ -340,6 +317,27 @@ private Task StartWatchTask(CancellationToken ct) => }, ct); + private Task UpdateStatsIfNeeded(List opsBuffer) + { + // Process the buffer and update stats + // Read operations are tracked directly in StartRetrieveTask + var puts = opsBuffer.Count(op => op == NatsKVOperation.Put); + var deletes = opsBuffer.Count(op => op == NatsKVOperation.Del); + + if (puts > 0) + { + _stats.AddOrUpdate("KeysInserted", puts, (_, count) => count + puts); + } + + if (deletes > 0) + { + _stats.AddOrUpdate("KeysRemoved", deletes, (_, count) => count + deletes); + } + + opsBuffer.Clear(); + return Task.CompletedTask; + } + private Task StartPrintTask(CancellationToken ct) => Task.Run( async () => @@ -367,35 +365,39 @@ private Task StartPrintTask(CancellationToken ct) => private void PrintProgress() { - var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; + var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysRemoved"]; + var opsPerSecond = (long)(totalOps / _stopwatch.Elapsed.TotalSeconds); + var currentKeys = _stats["KeysInserted"] - _stats["KeysRemoved"]; Console.WriteLine("========== CodeCargo NatsDistributedCache Performance =========="); - Console.WriteLine($"Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine($"Current Keys: {currentKeys,FieldWidth:N0}"); Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); - Console.WriteLine($"Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Keys Removed: {_stats["KeysRemoved"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); Console.WriteLine($"Elapsed Time: {FormatElapsedTime(_stopwatch.Elapsed),FieldWidth}"); Console.WriteLine($"Time Remaining: {FormatElapsedTime(TimeSpan.FromSeconds(MaxTestRuntimeSecs) - _stopwatch.Elapsed),FieldWidth}"); Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); - Console.WriteLine($"Ops per Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); + Console.WriteLine($"Ops per Second: {opsPerSecond,FieldWidth:N0}"); Console.WriteLine("=========================================================="); } private void PrintFinalStats() { - var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysExpired"]; + var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysRemoved"]; + var opsPerSecond = (long)(totalOps / _stopwatch.Elapsed.TotalSeconds); + var currentKeys = _stats["KeysInserted"] - _stats["KeysRemoved"]; Console.Clear(); Console.WriteLine("========== CodeCargo NatsDistributedCache Test Summary =========="); Console.WriteLine($"Test completed at: {DateTime.Now}"); Console.WriteLine($"Total test duration: {FormatElapsedTime(_stopwatch.Elapsed)}"); Console.WriteLine("----------------------------------------------------------"); - Console.WriteLine($"Final Current Keys: {_stats["CurrentKeys"],FieldWidth:N0}"); + Console.WriteLine($"Final Current Keys: {currentKeys,FieldWidth:N0}"); Console.WriteLine($"Total Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); - Console.WriteLine($"Total Keys Expired: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Total Keys Removed: {_stats["KeysRemoved"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); - Console.WriteLine($"Average Ops/Second: {_stats["OperationsPerSec"],FieldWidth:N0}"); + Console.WriteLine($"Average Ops/Second: {opsPerSecond,FieldWidth:N0}"); Console.WriteLine("=========================================================="); // Also log memory usage From 739a80633e38ddac40e97f17f3f704db96ee5d92 Mon Sep 17 00:00:00 2001 From: SuddyN Date: Mon, 12 May 2025 15:05:18 -0400 Subject: [PATCH 4/5] improve stats tracking --- util/PerfTest/PerfTest.cs | 89 +++++++++++++++++++++++++-------------- 1 file changed, 58 insertions(+), 31 deletions(-) diff --git a/util/PerfTest/PerfTest.cs b/util/PerfTest/PerfTest.cs index 13b8e80..fe28229 100644 --- a/util/PerfTest/PerfTest.cs +++ b/util/PerfTest/PerfTest.cs @@ -2,7 +2,6 @@ using System.Collections.Concurrent; using System.Diagnostics; using Microsoft.Extensions.Caching.Distributed; -using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; using NATS.Client.Core; @@ -22,7 +21,7 @@ public class PerfTest private const int FieldWidth = 12; private const int BatchSize = 100; private const int ValueDataSizeBytes = 256; - private const int KeyExpirySecs = 2; + private const int AbsoluteExpirationSecs = 10; private const int InsertDelayMs = 10; private const int RetrieveDelayMs = 5; private const int RemoveDelayMs = 50; @@ -57,6 +56,7 @@ public PerfTest(INatsConnection nats) _stats["KeysInserted"] = 0; _stats["KeysRetrieved"] = 0; _stats["KeysRemoved"] = 0; + _stats["KeysExpired"] = 0; } public async Task Run(CancellationToken cancellationToken) @@ -156,7 +156,7 @@ private Task StartInsertTask(CancellationToken ct) => { var options = new DistributedCacheEntryOptions { - AbsoluteExpirationRelativeToNow = TimeSpan.FromSeconds(KeyExpirySecs + _random.Next(KeyExpirySecs)) + AbsoluteExpirationRelativeToNow = TimeSpan.FromSeconds(AbsoluteExpirationSecs), }; await _cache.SetAsync(key, data, options, ct); @@ -196,30 +196,7 @@ private Task StartRetrieveTask(CancellationToken ct) => while (!ct.IsCancellationRequested) { - string? key = null; - - lock (_activeKeys) - { - if (_activeKeys.Count > 0) - { - var index = _random.Next(_activeKeys.Count); - key = _activeKeys[index]; - } - } - - if (key != null) - { - try - { - await _cache.GetAsync(key, ct); - _stats.AddOrUpdate("KeysRetrieved", 1, (_, count) => count + 1); - } - catch (Exception ex) when (ex is not OperationCanceledException) - { - Console.WriteLine($"Retrieve error: {ex.Message}"); - } - } - + await ProcessSingleRetrievalAsync(ct); await Task.Delay(RetrieveDelayMs, ct); // Small delay between retrievals } } @@ -230,6 +207,52 @@ private Task StartRetrieveTask(CancellationToken ct) => }, ct); + private async Task ProcessSingleRetrievalAsync(CancellationToken ct) + { + var (key, index) = GetRandomActiveKey(); + if (key == null) + return; + + try + { + var result = await _cache.GetAsync(key, ct); + _stats.AddOrUpdate("KeysRetrieved", 1, (_, count) => count + 1); + + if (result == null) + { + _stats.AddOrUpdate("KeysExpired", 1, (_, count) => count + 1); + RemoveExpiredKeyFromActiveList(index); + } + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + Console.WriteLine($"Retrieve error: {ex.Message}"); + } + } + + private (string? Key, int Index) GetRandomActiveKey() + { + lock (_activeKeys) + { + if (_activeKeys.Count == 0) + return (null, -1); + + var index = _random.Next(_activeKeys.Count); + return (_activeKeys[index], index); + } + } + + private void RemoveExpiredKeyFromActiveList(int index) + { + lock (_activeKeys) + { + if (index >= 0 && index < _activeKeys.Count) + { + _activeKeys.RemoveAt(index); + } + } + } + private Task StartRemoveTask(CancellationToken ct) => Task.Run( async () => @@ -367,13 +390,15 @@ private void PrintProgress() { var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysRemoved"]; var opsPerSecond = (long)(totalOps / _stopwatch.Elapsed.TotalSeconds); - var currentKeys = _stats["KeysInserted"] - _stats["KeysRemoved"]; Console.WriteLine("========== CodeCargo NatsDistributedCache Performance =========="); - Console.WriteLine($"Current Keys: {currentKeys,FieldWidth:N0}"); + Console.WriteLine($"Current Keys: {_activeKeys.Count,FieldWidth:N0}"); Console.WriteLine($"Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); Console.WriteLine($"Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); Console.WriteLine($"Keys Removed: {_stats["KeysRemoved"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Cache Hits: {_stats["KeysRetrieved"] - _stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Cache Misses: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine("----------------------------------------------------------"); Console.WriteLine($"Elapsed Time: {FormatElapsedTime(_stopwatch.Elapsed),FieldWidth}"); Console.WriteLine($"Time Remaining: {FormatElapsedTime(TimeSpan.FromSeconds(MaxTestRuntimeSecs) - _stopwatch.Elapsed),FieldWidth}"); Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); @@ -385,17 +410,19 @@ private void PrintFinalStats() { var totalOps = _stats["KeysInserted"] + _stats["KeysRetrieved"] + _stats["KeysRemoved"]; var opsPerSecond = (long)(totalOps / _stopwatch.Elapsed.TotalSeconds); - var currentKeys = _stats["KeysInserted"] - _stats["KeysRemoved"]; Console.Clear(); Console.WriteLine("========== CodeCargo NatsDistributedCache Test Summary =========="); Console.WriteLine($"Test completed at: {DateTime.Now}"); Console.WriteLine($"Total test duration: {FormatElapsedTime(_stopwatch.Elapsed)}"); Console.WriteLine("----------------------------------------------------------"); - Console.WriteLine($"Final Current Keys: {currentKeys,FieldWidth:N0}"); + Console.WriteLine($"Final Current Keys: {_activeKeys.Count,FieldWidth:N0}"); Console.WriteLine($"Total Keys Inserted: {_stats["KeysInserted"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Removed: {_stats["KeysRemoved"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); + Console.WriteLine($"Cache Hits: {_stats["KeysRetrieved"] - _stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Cache Misses: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine("----------------------------------------------------------"); Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); Console.WriteLine($"Average Ops/Second: {opsPerSecond,FieldWidth:N0}"); Console.WriteLine("=========================================================="); From 3ff25a3f4549f07e6106e014b723ff2f1e25be61 Mon Sep 17 00:00:00 2001 From: SuddyN Date: Mon, 12 May 2025 15:17:22 -0400 Subject: [PATCH 5/5] fix formatting & remove redundant comments --- util/PerfTest/PerfTest.cs | 24 ++++++++---------------- 1 file changed, 8 insertions(+), 16 deletions(-) diff --git a/util/PerfTest/PerfTest.cs b/util/PerfTest/PerfTest.cs index fe28229..c310a92 100644 --- a/util/PerfTest/PerfTest.cs +++ b/util/PerfTest/PerfTest.cs @@ -26,6 +26,7 @@ public class PerfTest private const int RetrieveDelayMs = 5; private const int RemoveDelayMs = 50; private const int StatsUpdateIntervalMs = 500; + private const int StatsPrintIntervalMs = 1000; // Dependencies private readonly INatsConnection _nats; @@ -105,7 +106,6 @@ public async Task Run(CancellationToken cancellationToken) // Ignore } - // Print final stats PrintFinalStats(); } } @@ -150,7 +150,7 @@ private Task StartInsertTask(CancellationToken ct) => for (var j = 0; j < BatchSize && i + j < NumCacheItems && !ct.IsCancellationRequested; j++) { var key = $"BatchNum{i}IndividualNum{j}"; - var data = GenerateRandomData(ValueDataSizeBytes); // 256 byte values + var data = GenerateRandomData(ValueDataSizeBytes); try { @@ -165,8 +165,6 @@ private Task StartInsertTask(CancellationToken ct) => { _activeKeys.Add(key); } - - // Note: actual count is tracked by the watcher } catch (Exception ex) when (ex is not OperationCanceledException) { @@ -174,7 +172,6 @@ private Task StartInsertTask(CancellationToken ct) => } } - // Small delay between batches await Task.Delay(InsertDelayMs, ct); } } @@ -197,7 +194,7 @@ private Task StartRetrieveTask(CancellationToken ct) => while (!ct.IsCancellationRequested) { await ProcessSingleRetrievalAsync(ct); - await Task.Delay(RetrieveDelayMs, ct); // Small delay between retrievals + await Task.Delay(RetrieveDelayMs, ct); } } catch (OperationCanceledException) @@ -259,7 +256,7 @@ private Task StartRemoveTask(CancellationToken ct) => { try { - // Wait a bit before starting expiry operations + // Wait a bit before starting removal operations await Task.Delay(2000, ct); while (!ct.IsCancellationRequested) @@ -281,8 +278,6 @@ private Task StartRemoveTask(CancellationToken ct) => try { await _cache.RemoveAsync(key, ct); - - // Note: actual count is tracked by the watcher } catch (Exception ex) when (ex is not OperationCanceledException) { @@ -290,7 +285,7 @@ private Task StartRemoveTask(CancellationToken ct) => } } - await Task.Delay(RemoveDelayMs, ct); // Less frequent expiry operations + await Task.Delay(RemoveDelayMs, ct); } } catch (OperationCanceledException) @@ -369,14 +364,11 @@ private Task StartPrintTask(CancellationToken ct) => { while (!ct.IsCancellationRequested) { - // Clear console Console.Clear(); - - // Print current statistics PrintProgress(); // Wait before printing again - await Task.Delay(TimeSpan.FromSeconds(1), ct); + await Task.Delay(TimeSpan.FromMilliseconds(StatsPrintIntervalMs), ct); } } catch (OperationCanceledException) @@ -420,8 +412,8 @@ private void PrintFinalStats() Console.WriteLine($"Total Keys Retrieved: {_stats["KeysRetrieved"],FieldWidth:N0}"); Console.WriteLine($"Total Keys Removed: {_stats["KeysRemoved"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); - Console.WriteLine($"Cache Hits: {_stats["KeysRetrieved"] - _stats["KeysExpired"],FieldWidth:N0}"); - Console.WriteLine($"Cache Misses: {_stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Cache Hits: {_stats["KeysRetrieved"] - _stats["KeysExpired"],FieldWidth:N0}"); + Console.WriteLine($"Cache Misses: {_stats["KeysExpired"],FieldWidth:N0}"); Console.WriteLine("----------------------------------------------------------"); Console.WriteLine($"Total operations: {totalOps,FieldWidth:N0}"); Console.WriteLine($"Average Ops/Second: {opsPerSecond,FieldWidth:N0}");