private static void ShowStats(SynchedColouredConsoleTraceWriter synchedConsole) { synchedConsole.WriteLine($@" Following results & performance based on a {100.0 / _perTestMeasureEveryN:#0.0}% sample ({MonitoredWorkBag.Count:#,##0}) + all timeouts & faulted requests. Results & performance of sample... Total: {MonitoredWorkBag.Count:#,##0}, Completed: {MonitoredWorkBag.Count(t => t.Item1.IsCompleted):#,##0}, Faulted: {MonitoredWorkBag.Count(t => t.Item1.IsFaulted):#,##0}, Cancelled: {MonitoredWorkBag.Count(t => t.Item1.IsCanceled):#,##0}, Performance (microseconds [us] - thousandaths of milliseconds / millionths of seconds) Fastest: {MonitoredWorkBag.Min(t => t.Item2.TotalMilliseconds * 1000):#,##0.0} (us), Slowest: {MonitoredWorkBag.Max(t => t.Item2.TotalMilliseconds * 1000):#,##0.0} (us), Average time: {MonitoredWorkBag.Average(t => t.Item2.TotalMilliseconds * 1000):#,##0.0} (us), Median: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.50):#,##0.0} (us), P75: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.75):#,##0.0} (us), P90: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.90):#,##0.0} (us), P95: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.95):#,##0.0} (us), P99: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.99):#,##0.0} (us), P3x9: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.999):#,##0.0} (us), P5x9: {Percentile(MonitoredWorkBag.Select(t => t.Item2.TotalMilliseconds * 1000), 0.99999):#,##0.0} (us), ", overrideShowOutput: true); }
private static string MonitorWork(Func <string> work, SynchedColouredConsoleTraceWriter synchedConsole, int testId = -3) { var sw = new Stopwatch(); Task <string> task = null; try { sw.Start(); var result = work(); sw.Stop(); task = Task.FromResult <string>(result); return(task.Result); } catch (Exception ex) { sw.Stop(); task = Task.FromException <string>(ex); var error = $"ERROR: {(ex as AggregateException)?.InnerExceptions.First().Message ?? ex.Message}"; synchedConsole.WriteLine($"MonitorWork: * *** *** *** {error}", ConsoleColor.White, ConsoleColor.Red); return(error); } finally { synchedConsole.WriteLine($"MonitorWork: testId:{testId}: {sw.Elapsed.TotalMilliseconds * 1000:#,##0.0}(us)", ConsoleColor.White, ConsoleColor.Blue); task = task ?? Task.FromCanceled <string>(CancellationToken.None); var tpl = new Tuple <Task, TimeSpan>(task, sw.Elapsed); synchedConsole.WritePerformanceSample(tpl); if (task.IsCanceled || task.IsFaulted || (Interlocked.Increment(ref _measureSeq) % _perTestMeasureEveryN) == 0) { MonitoredWorkBag.Add(tpl); } } }
static void Main(string[] args) { var rndSrc = new Random(2); var testIdSrc = 0; var uniqueCacheId = 1; var ttl = TimeSpan.FromSeconds(10); // 20 min equiv var regen = TimeSpan.FromSeconds(2.5); // 1 min equiv var regenDuration = TimeSpan.FromSeconds(1.25); // duration of call to generate value to store in cache var regenErrorPercentage = 0; var farmClockTollerance = 0.1; var p1Duration = TimeSpan.FromSeconds(10); var p1Frequency = TimeSpan.FromSeconds(0.5); var launchTwoInstances = false; var doRegTest = true; var doPerfTest = true; var writePerformanceCsv = false; var writeTraceOutputFile = false; var writeHtmlOutputFile = false; var outputFolder = "c:\\temp\\"; var perfTestCount = 1000000; var perfTestMeasure = 100000; var keyspace = $"keyspace{Guid.NewGuid():N}"; if (launchTwoInstances && args.Length == 0 && !Debugger.IsAttached) { Process.Start(Assembly.GetEntryAssembly().Location, $"nospawn 1 {keyspace}"); //Task.Delay(2000).Wait(); Process.Start(Assembly.GetEntryAssembly().Location, $"nospawn 2 {keyspace}"); return; } var id = 0; if (args.Length >= 3) { int.TryParse(args[1], out id); keyspace = args[2]; } var synchedConsole = new SynchedColouredConsoleTraceWriter( traceFileName: writeTraceOutputFile ? $"{outputFolder}RegenerativeCacheManagerDemo_{keyspace}_{id}.txt" : null, htmlFileName: writeHtmlOutputFile ? $"{outputFolder}RegenerativeCacheManagerDemo_{keyspace}_{id}.html" : null, performanceFileName: writePerformanceCsv ? $"{outputFolder}RegenerativeCacheManagerDemo_{keyspace}_{id}.csv" : null ); using (var ct1R = new BasicRedisWrapper("localhost")) using (var cacheTest1 = new RegenerativeCacheManager("keyspace3", ct1R.Cache, ct1R.Lock, ct1R.Bus)) using (var ct2R = new BasicRedisWrapper("localhost")) using (var cacheTest2 = new RegenerativeCacheManager("Keyspace3", ct2R.Cache, ct2R.Lock, ct2R.Bus)) { new List <IDisposable> { cacheTest1, ct1R, cacheTest2, ct2R }.ForEach(d => d.Dispose()); } synchedConsole.WriteLine("RegenerativeCacheManager dispose works.", ConsoleColor.Black, ConsoleColor.Green); var redis = new BasicRedisWrapper("localhost", true); var cache = new RegenerativeCacheManager(keyspace, redis.Cache, redis.Lock, redis.Bus, synchedConsole) { // low tollerences in this test due to extremely low cache item re-generation and expiry times, normally 30s to minutes CacheExpiryToleranceSeconds = 1, TriggerDelaySeconds = 1, MinimumForwardSchedulingSeconds = 1, FarmClockToleranceSeconds = farmClockTollerance, }; var generateFunc = new Func <string>(() => { Task.Delay(regenDuration).Wait(); if (rndSrc.Next(0, 100) < regenErrorPercentage) { throw new ApplicationException("Synthetic Error"); } return($" >>> CacheItemVal_{DateTime.Now:ss.fff}_{Interlocked.Increment(ref uniqueCacheId)} <<< "); }); if (doRegTest) { synchedConsole.WriteLine($"Inactive TTL: {ttl.TotalSeconds}s, Regeneration every: {regen.TotalSeconds}s, Regeneration performance: {regenDuration.TotalSeconds}s"); synchedConsole.WriteLine($"------- running get per second (in background) for {p1Duration.TotalSeconds} seconds"); synchedConsole.WriteLine("================================================="); var start = DateTime.UtcNow; while (DateTime.UtcNow.Subtract(start).TotalSeconds < p1Duration.TotalSeconds) { var testId = Interlocked.Increment(ref testIdSrc); Task.Run(() => synchedConsole.WriteLine($"* PART 1 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testId)}")); Task.Delay(p1Frequency).Wait(); } synchedConsole.WriteLine("================================================="); synchedConsole.DebugWait(6); var testX1 = Interlocked.Increment(ref testIdSrc); synchedConsole.WriteLine($"* PART 2 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testX1)}"); synchedConsole.WriteLine("================================================="); synchedConsole.DebugWait(15); var testX2 = Interlocked.Increment(ref testIdSrc); Task.Run(() => synchedConsole.WriteLine($"* PART 3 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testX2)}")); var testX3 = Interlocked.Increment(ref testIdSrc); Task.Run(() => synchedConsole.WriteLine($"* PART 3 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testX3)}")); var testX4 = Interlocked.Increment(ref testIdSrc); synchedConsole.WriteLine($"* PART 3 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testX4)}"); var testX5 = Interlocked.Increment(ref testIdSrc); synchedConsole.WriteLine($"* PART 3 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testX5)}"); synchedConsole.DebugWait(2); synchedConsole.DebugWait(20); ShowStats(synchedConsole); try { Task.WaitAll(MonitoredWorkBag.Select(t => t.Item1).ToArray()); } catch (Exception ex) { synchedConsole.WriteLine($"First error: {(ex as AggregateException)?.InnerExceptions.First().ToString() ?? ex.ToString()}", ConsoleColor.White, ConsoleColor.Red); } while (MonitoredWorkBag.TryTake(out Tuple <Task, TimeSpan> tr)) { tr.Item1.Dispose(); } } if (doRegTest && doPerfTest) { synchedConsole.OpenNewOutputFile(); } if (doPerfTest) { cache.Dispose(); _perTestMeasureEveryN = Math.Max(1, perfTestCount / perfTestMeasure); cache = new RegenerativeCacheManager(keyspace, redis.Cache, redis.Lock, redis.Bus, synchedConsole) { // low tollerences in this test due to extremely low cache item re-generation and expiry times, normally 30s to minutes TriggerDelaySeconds = 1, MinimumForwardSchedulingSeconds = 1, FarmClockToleranceSeconds = farmClockTollerance, CacheExpiryToleranceSeconds = 5, }; synchedConsole.WriteLine($"Running performance test of {perfTestCount:#,##0} cache calls to GetOrAdd in parallel.", ConsoleColor.White, ConsoleColor.DarkBlue); testIdSrc = 1; while (MonitoredWorkBag.TryTake(out Tuple <Task, TimeSpan> tr)) { ; } synchedConsole.ShowFullOutputToConsole = false; // warm up cache.GetOrAdd("test1", generateFunc, ttl, regen); var swWait = Stopwatch.StartNew(); var dop = 10; Parallel.ForEach(Enumerable.Range(0, dop), new ParallelOptions { MaxDegreeOfParallelism = dop }, (i) => { for (int j = 0; j < perfTestCount / dop; j++) { var testId = Interlocked.Increment(ref testIdSrc); if (j % 10 == 0) { Thread.Sleep(1); } synchedConsole.WriteLine($"* PART 4 * Cache Value: {MonitorWork(() => cache.GetOrAdd("test1", generateFunc, ttl, regen), synchedConsole, testId)}"); } }); swWait.Stop(); synchedConsole.WriteLine($"\r\n\r\n\t\t\t{perfTestCount:#,##0} cache GetOrAdd calls completed with {dop} degrees of parallelism." + $"\r\n\r\n\t\t\t Duration: {swWait.Elapsed.TotalMilliseconds * 1000:#,##0.0}us." + $"\r\n\t\t\t Requests/s: {perfTestCount / swWait.Elapsed.TotalSeconds:#,##0.0} ({perfTestCount / swWait.Elapsed.TotalHours:#,##0}/h)" + $"\r\n\r\n" , ConsoleColor.White, overrideShowOutput: true); ShowStats(synchedConsole); while (MonitoredWorkBag.TryTake(out Tuple <Task, TimeSpan> tr)) { tr.Item1.Dispose(); } GC.Collect(); } synchedConsole.CloseAndStopAllWriting(); if (launchTwoInstances) { synchedConsole.WriteLine("Press enter to exit.", overrideShowOutput: true); Console.ReadLine(); } }