예제 #1
0
        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();
            }
        }
예제 #2
0
        private static void MultiNodeGetsInternal(string redisConnection, bool useMultipleRedisConnections, ITestOutputHelper _output, string writeTraceFile = null)
        {
            var testRunKeyspace = $"testKs{DateTime.Now:mmssfffffff}s{Interlocked.Increment(ref _seq)}";

            if (redisConnection.ToLowerInvariant() == "mock")
            {
                redisConnection = $"mock-{Guid.NewGuid():N}";
            }

            var tw = new DualTraceWriter();

            try
            {
                using (var node1Ext = new RedisInterceptOrMock(redisConnection, useMultipleRedisConnections))
                    using (var node1Cache = new RegenerativeCacheManager(testRunKeyspace, node1Ext.Cache, node1Ext.Lock, node1Ext.Bus, tw.T1)
                    {
                        CacheExpiryToleranceSeconds = 1.5,
                        MinimumForwardSchedulingSeconds = 1,
                        TriggerDelaySeconds = 1,
                        FarmClockToleranceSeconds = 0.1,
                    })
                        using (var node2Ext = new RedisInterceptOrMock(redisConnection, useMultipleRedisConnections))
                            using (var node2Cache = new RegenerativeCacheManager(testRunKeyspace, node2Ext.Cache, node2Ext.Lock, node2Ext.Bus, tw.T2)
                            {
                                CacheExpiryToleranceSeconds = 1.5,
                                MinimumForwardSchedulingSeconds = 1,
                                TriggerDelaySeconds = 1,
                                FarmClockToleranceSeconds = 0.1,
                            })
                            {
                                var inactiveRetention    = TimeSpan.FromSeconds(6);
                                var regenerationInterval = TimeSpan.FromSeconds(2);

                                var node1Result1 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t1n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node1Result2 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t1n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);

                                Assert.StartsWith("t1n1_", node1Result1);
                                Assert.Equal(node1Result1, node1Result2);

                                Assert.Single(node1Ext.CacheGets);
                                Assert.Single(node1Ext.CacheGetStringStarts);
                                Assert.Single(node1Ext.CacheSets);
                                Assert.Single(node1Ext.Subscribes);
                                Assert.Single(node1Ext.Publishes);
                                Assert.Single(node1Ext.LockAttempts);
                                Assert.Single(node1Ext.LockAttempts.Where(l => l.Value));

                                Assert.Empty(node2Ext.CacheGets);
                                Assert.Empty(node2Ext.CacheGetStringStarts);
                                Assert.Empty(node2Ext.CacheSets);
                                Assert.Single(node2Ext.Subscribes);
                                Assert.Empty(node2Ext.Publishes);
                                Assert.Empty(node2Ext.LockAttempts);

                                Thread.Sleep(250);

                                Assert.Single(node1Ext.ReceivedMessages);
                                Assert.Single(node2Ext.ReceivedMessages);

                                var node2Result1 = node2Cache.GetOrAdd("test1", () => MockGenDelay($"t1n2_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node2Result2 = node2Cache.GetOrAdd("test1", () => MockGenDelay($"t1n2_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);

                                Assert.Single(node1Ext.CacheSets);
                                Assert.Single(node1Ext.Subscribes);
                                Assert.Single(node1Ext.Publishes);
                                Assert.Single(node1Ext.ReceivedMessages);
                                Assert.Single(node1Ext.LockAttempts);
                                Assert.Single(node1Ext.LockAttempts.Where(l => l.Value));

                                Assert.Single(node2Ext.CacheGets);
                                Assert.Empty(node2Ext.CacheSets);
                                Assert.Single(node2Ext.Subscribes);
                                Assert.Empty(node2Ext.Publishes);
                                Assert.Single(node2Ext.ReceivedMessages);
                                Assert.Empty(node2Ext.LockAttempts);

                                // confirm node2 gets result generated on node1 from external cache
                                Assert.StartsWith("t1n1_", node2Result1);
                                Assert.Equal(node2Result1, node2Result2);

                                Thread.Sleep(4000);

                                // confirm cache has been regenerated in the background (on both nodes)

                                // one set from initial and one from regeneration (across farm)
                                Assert.InRange(node1Ext.CacheSets.Count + node2Ext.CacheSets.Count, 2, 4);

                                Assert.Single(node1Ext.Subscribes);

                                var totalPublished = node1Ext.Publishes.Count + node2Ext.Publishes.Count;
                                Assert.InRange(totalPublished, 2, 4);
                                Assert.Equal(totalPublished, node1Ext.ReceivedMessages.Count);
                                Assert.Equal(totalPublished, node2Ext.ReceivedMessages.Count);

                                // two to four total lock attempt (depending on thread race conditions)
                                Assert.InRange(node1Ext.LockAttempts.Count + node2Ext.LockAttempts.Count, 2, 6);

                                // two successful locks across the farm (initial generation + 1 regeneration)
                                Assert.InRange(node1Ext.LockAttempts.Count(l => l.Value) + node2Ext.LockAttempts.Count(l => l.Value),
                                               2, 4);

                                var locksAcquired = node1Ext.LockAttempts.Count(l => l.Value) +
                                                    node2Ext.LockAttempts.Count(l => l.Value);

                                // confirm first hit to node2 returns val from node1
                                Assert.Single(node2Ext.Subscribes);

                                // initial generation + 1 re-generation per node
                                Assert.InRange(node1Ext.ReceivedMessages.Count, locksAcquired - 1, locksAcquired);
                                Assert.InRange(node2Ext.ReceivedMessages.Count, locksAcquired - 1, locksAcquired);

                                var node1Result3 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t2n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node1Result4 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t2n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);

                                // result still starts with t1n1_ or t1n2
                                Assert.NotEqual(node1Result1, node1Result3);
                                Assert.StartsWith("t1", node1Result3);
                                Assert.Equal(node1Result3, node1Result4);

                                Thread.Sleep(10000);

                                var node1Result5 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t3n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node1Result6 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t3n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);

                                // result still start with t3n1
                                Assert.StartsWith("t3n1_", node1Result5);
                                Assert.Equal(node1Result5, node1Result6);

                                Thread.Sleep(10000);

                                var node2Result3 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t4n2_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node2Result4 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t4n2_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node1Result7 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t4n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);
                                var node1Result8 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t4n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval);

                                // check results flow from node2 back to node1 as well
                                Assert.StartsWith("t4n2_", node2Result3);
                                Assert.Equal(node2Result3, node2Result4);
                                Assert.Equal(node2Result3, node1Result7);
                                Assert.Equal(node2Result3, node1Result8);

                                tw.Stop();
                                tw.Clear();
                            }
            }
            finally
            {
                foreach (var l in tw.GetOutput())
                {
                    _output.WriteLine(l);
                }
            }
        }
예제 #3
0
        private static void NodesCompeteInternal(string redisConnection, bool useMultipleRedisConnections, ITestOutputHelper _output, string writeTraceFile = null)
        {
            var testRunKeyspace = $"testKs{DateTime.Now:mmssfffffff}s{Interlocked.Increment(ref _seq)}";

            if (redisConnection.ToLowerInvariant() == "mock")
            {
                redisConnection = $"mock-{Guid.NewGuid():N}";
            }

            var tw = new DualTraceWriter();

            try
            {
                using (var node1Ext = new RedisInterceptOrMock(redisConnection, useMultipleRedisConnections))
                    using (var node1Cache = new RegenerativeCacheManager(testRunKeyspace, node1Ext.Cache, node1Ext.Lock, node1Ext.Bus, tw.T1)
                    {
                        CacheExpiryToleranceSeconds = 1.5,
                        MinimumForwardSchedulingSeconds = 1,
                        TriggerDelaySeconds = 1,
                        FarmClockToleranceSeconds = 0.1,
                    })
                        using (var node2Ext = new RedisInterceptOrMock(redisConnection, useMultipleRedisConnections))
                            using (var node2Cache = new RegenerativeCacheManager(testRunKeyspace, node2Ext.Cache, node2Ext.Lock, node2Ext.Bus, tw.T2)
                            {
                                CacheExpiryToleranceSeconds = 1.5,
                                MinimumForwardSchedulingSeconds = 1,
                                TriggerDelaySeconds = 1,
                                FarmClockToleranceSeconds = 0.1,
                            })
                            {
                                var inactiveRetention    = TimeSpan.FromSeconds(9);
                                var regenerationInterval = TimeSpan.FromSeconds(3);

                                bool seenN1 = false, seenN2 = false;
                                var  start     = DateTime.Now;
                                var  end       = start.AddSeconds(120);
                                var  rnd       = new Random();
                                bool nodeOrder = false;

                                string node1Result1 = "", node2Result1 = "";

                                var getFrom1 = new Action(() => node1Result1 = node1Cache.GetOrAdd("test1", () => MockGenDelay($"t1n1_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval));
                                var getFrom2 = new Action(() => node2Result1 = node2Cache.GetOrAdd("test1", () => MockGenDelay($"t1n2_{Guid.NewGuid():N}"), inactiveRetention, regenerationInterval));

                                var results = new List <Tuple <string, string> >();
                                do
                                {
                                    // ReSharper disable once AssignmentInConditionalExpression
                                    if (nodeOrder = !nodeOrder)
                                    {
                                        getFrom1(); getFrom2();
                                    }
                                    else
                                    {
                                        getFrom2(); getFrom1();
                                    }

                                    results.Add(new Tuple <string, string>(node2Result1, node2Result1));

                                    if (node2Result1.StartsWith("t1n1") || node1Result1.StartsWith("t1n1"))
                                    {
                                        seenN1 = true;
                                    }
                                    if (node2Result1.StartsWith("t1n2") || node1Result1.StartsWith("t1n2"))
                                    {
                                        seenN2 = true;
                                    }

                                    // randomise the delay to randomise the node order switches
                                    Task.Delay(rnd.Next(50, 100)).Wait();
                                } while (DateTime.Now < end && (!seenN1 || !seenN2));

                                var countOfEqual = results.Count(r => r.Item1 == r.Item2) * 1.0;

                                var probabilityMsg = $"{end.Subtract(start).TotalSeconds:0} seconds means " +
                                                     $"{(int)(end.Subtract(start).TotalSeconds / regenerationInterval.TotalSeconds)} chances to compete, " +
                                                     $"chances of not seeing results from both nodes is approximately " +
                                                     $"2 in (2^{(int)(end.Subtract(start).TotalSeconds / regenerationInterval.TotalSeconds)}), " +
                                                     $"i.e. 1 in {Math.Pow(2, (int)(end.Subtract(start).TotalSeconds / regenerationInterval.TotalSeconds)) / 2:#,##0}.";


                                // _output.WriteLine($"90% of results should be identical, {(countOfEqual / results.Count) * 100:0}% were ({countOfEqual} / {results.Count}). {probabilityMsg}");

                                Assert.True(results.Count > 19,
                                            $"Shouldn't see any cache regeneration / node competition for 2 to 3 seconds. Saw different results in only {DateTime.Now.Subtract(start).TotalMilliseconds*1000:#,##0.0}us.");

                                Assert.True(countOfEqual / results.Count > 0.9,
                                            $"90% of results should be identical, only {(countOfEqual / results.Count)*100:0}% were ({countOfEqual} / {results.Count}).");

                                var errmsg = $"Did not see generation on {{0}} - {probabilityMsg}";
                                Assert.True(seenN1, string.Format(errmsg, "node1"));
                                Assert.True(seenN2, string.Format(errmsg, "node2"));
                            }

                tw.Stop();
                tw.Clear();
            }
            finally
            {
                foreach (var l in tw.GetOutput())
                {
                    _output.WriteLine(l);
                }
            }
        }
예제 #4
0
        private static void SingleNodeGetsInternal(string redisConnection, bool useMultipleRedisConnections, ITestOutputHelper _output, string writeTraceFile = null)
        {
            var testRunKeyspace = $"testKs{DateTime.Now:mmssfffffff}s{Interlocked.Increment(ref _seq)}";

            if (redisConnection.ToLowerInvariant() == "mock")
            {
                redisConnection = $"mock-{Guid.NewGuid():N}";
            }

            var tw = new DualTraceWriter();

            try
            {
                using (var ext = new RedisInterceptOrMock(redisConnection, useMultipleRedisConnections))
                    using (var cache = new RegenerativeCacheManager(testRunKeyspace, ext.Cache, ext.Lock, ext.Bus, tw.T1)
                    {
                        CacheExpiryToleranceSeconds = 1.5,
                        MinimumForwardSchedulingSeconds = 1,
                        TriggerDelaySeconds = 1,
                        FarmClockToleranceSeconds = 0.1,
                    })
                    {
                        var inactiveRetention    = TimeSpan.FromSeconds(6);
                        var regenerationInterval = TimeSpan.FromSeconds(2);

                        var result1 = cache.GetOrAdd("test1", () => $"t1_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);
                        var result2 = cache.GetOrAdd("test1", () => $"t1_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);

                        Assert.StartsWith("t1_", result1);
                        Assert.Equal(result1, result2);

                        Assert.Single(ext.CacheGets);
                        Assert.Single(ext.CacheGetStringStarts);
                        Assert.Single(ext.CacheSets);
                        Assert.Single(ext.Subscribes);
                        Assert.Single(ext.Publishes);
                        Assert.Single(ext.LockAttempts);
                        Assert.Single(ext.LockAttempts.Where(l => l.Value));

                        Thread.Sleep(350);
                        Assert.Single(ext.ReceivedMessages);

                        // Confirm external cache keys are as expected
                        Assert.NotNull(ext.StringGetWithExpiry($"{nameof(MemoryFrontedExternalCache)}:{testRunKeyspace}:Item:test1", out TimeSpan exp));
                        var first10  = ext.GetStringStart($"{nameof(MemoryFrontedExternalCache)}:{testRunKeyspace}:Item:test1", 10);
                        var first100 = ext.GetStringStart($"{nameof(MemoryFrontedExternalCache)}:{testRunKeyspace}:Item:test1", 100);
                        Assert.NotNull(first10);
                        Assert.NotNull(first100);
                        Assert.StartsWith(first10, first100);

                        Thread.Sleep(5000);

                        // confirm cache has been regenerated in the background
                        Assert.InRange(ext.CacheSets.Count, 2, 4);

                        Assert.Single(ext.Subscribes);
                        Assert.InRange(ext.Publishes.Count, 2, 4);
                        Assert.InRange(ext.ReceivedMessages.Count, 2, 4);
                        Assert.InRange(ext.LockAttempts.Count, 2, 4);
                        Assert.InRange(ext.LockAttempts.Count(l => l.Value), 2, 4);

                        var result3 = cache.GetOrAdd("test1", () => $"t2_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);
                        var result4 = cache.GetOrAdd("test1", () => $"t2_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);

                        // result still starts with t1_ as we have not passed the 6s mark
                        // but has been regenerated so is not equal to previous value
                        Assert.NotEqual(result1, result3);
                        Assert.StartsWith("t1_", result3);
                        Assert.Equal(result3, result4);

                        Thread.Sleep(10000); // 6s (regens) + 2 (validity) + 1.5 (tolerance)

                        var result5 = cache.GetOrAdd("test1", () => $"t3_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);
                        var result6 = cache.GetOrAdd("test1", () => $"t3_{Guid.NewGuid():N}", inactiveRetention, regenerationInterval);

                        // result still starts with t1_ as we have not passed the 3s mark
                        Assert.StartsWith("t3_", result5);
                        Assert.Equal(result5, result6);

                        tw.Stop();
                        tw.Clear();
                    }
            }
            finally
            {
                foreach (var l in tw.GetOutput())
                {
                    _output.WriteLine(l);
                }
            }
        }