Strage performance issue

[ianselmi]

Hello guys, from our production environment we noticed time spikes when we use CompositeCache object and I built a simple benchmark test to compare CompositeCache with MemCache and RedisCache to RedisCache.

This is the result with CompositeCache:

and this is the result using RedisCache only:

The metrics are: Test count - numbers of iteration Diff - Number of calls per sec Avg time - avg time per call Error: total number of errors DiffErr : error per sec Maxms: Max call time per sec

The test code is:

using System;
using System.Diagnostics;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using hack = IntelligentHack.IntelligentCache;

namespace IntelligentCacheBenchmark
{
    internal class Program
    {
        private static void Main(string[] args)
        {
            var redisConnection = _createConnection(args);
            var memCache = new hack.MemoryCache("t");
            var redisCache = new hack.RedisCache(redisConnection, "r");
            var composite = redisCache;//new hack.CompositeCache(memCache, redisCache);

            var a = Enumerable.Range(0, 100);
            var data = RandomString(2048);
            var p = new BenchmarkTest();
            while (true)
            {
                Parallel.ForEach(a, new ParallelOptions { MaxDegreeOfParallelism = 100 }, (s) =>
                {
                    var ret = p.DoStuff((i) => composite.GetSet((i).ToString(), () => data, TimeSpan.FromSeconds(60)));                    
                });
            }
        }

        private static IConnectionMultiplexer _createConnection(string[] cmdArgs)
        {   
            var cnss = ConnectionMultiplexer.Connect(ConfigurationOptions.Parse(cmdArgs[0]));
            cnss.GetDatabase().Execute("flushall");
            return cnss;
        }

        private static Random random = new Random();

        public static string RandomString(int length)
        {
            const string chars = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789";
            return new string(Enumerable.Repeat(chars, length)
              .Select(s => s[random.Next(s.Length)]).ToArray());
        }
    }

    public class BenchmarkTest
    {
        private long _i = 0;
        private long _oldI = 0;
        private long _elapsedms = 0;
        private long _totalErrors = 0;
        private long _oldErrors = 0;
        private long _max;

        public BenchmarkTest()
        {
            Task.Factory.StartNew(async () =>
            {
                while (true)
                {
                    if (_i > 0) Console.WriteLine($"Test count:{_i} Diff:{_i - _oldI} - Avg time:{_elapsedms / _i}ms - Errors:{_totalErrors} - DiffErr:{_totalErrors - _oldErrors} - Maxms:{_max}");
                    _oldI = _i;
                    _oldErrors = _totalErrors; _max = 0;
                    await Task.Delay(1000);
                }
            });
        }

        public string DoStuff(Func<long, string> a)
        {
            var sw = Stopwatch.StartNew();
            string ret = "";
            try
            {
                ret = a(Interlocked.Increment(ref _i));
            }
            catch
            {
                _totalErrors++;
            }

            sw.Stop();
            Interlocked.Add(ref _elapsedms, sw.ElapsedMilliseconds);
            if (_max < sw.ElapsedMilliseconds) _max = sw.ElapsedMilliseconds;
            return ret;
        }

    }
}

Can you check we miss some configurations or there is some kind of issue?

[sklivvz]

What is the performance issue in your opinion? I don't see any time spikes in your data beyond the obvious initial misses.

[ianselmi]

in my opinion the strange behavior was bad performance using composecache instead to use rediscache. On my pc with composecache I have 400/500 request per sec, with redis cache (same configuration used with compose) I have 3000/4000 request per sec in a multithread env. The spikes are related to our prod env where with compose (memcache +redis)and with 10/15k request per minutes sometimes the cache time increase to 5/10sec to manage that requests instead of 50ms. Using RedisCache the spikes was disappear. In brief, for me is strange have 500 requests per sec with composecache and 3000/4000 with only redis

[sklivvz]

It's impossible to reach any clear conclusion given your test:

• The test compares CompositeCache of MemoryCache and RedisCache versus RedisCache. The impact of MemoryCache is not considered
• Having 100 threads on a normal machine is a bit weird given you don't probably have 100 hardware threads available. This introduces a number of unknowns.
• There's no network latency involved which surely impacts the test significantly -- the test assumes Redis perf is realistic.

In my opinion, a better test would probably involve a CompositeCache of two pass-through caches versus a single pass-through cache without insane levels of parallelism and with a realistic load (e.g. 100ms wait). This should give us an idea of the time spent in composing the caches (which can be calculated with "composite time - 2x passthrough time = composing time". If you then vary the degree of parallelism you will probably see the impact of any locks in the composite cache.

The second test I suggest is to run the same test against MemoiryCache and compare it to a single pass-through cache to spot any locking issue in that.

Finally, I would run the test against a realistic load, set up, and network.

By the way, I suggest you always use BenchmarkDotNet for any benchmarking as it's a standard, issue-free tool that gives consistent/reliable results.

[ianselmi]

Thank for suggestions and I tried to reproduce it with Benchmarkdotnet but is not so easy because Benchmarkdotnet is not developed to test multithread environment. I wrote a simple test as below

using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;
using IntelligentHack.IntelligentCache;
using StackExchange.Redis;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;

using hack = IntelligentHack.IntelligentCache;

namespace IntelligentCacheBenchmark
{
    internal class Program
    {
        private static void Main(string[] args)
        {
            BenchmarkRunner.Run<MultithreadBenchmark>();
        }
    }

    [MemoryDiagnoser]
    public class MultithreadBenchmark
    {
        private readonly string _seed;
        private readonly IConnectionMultiplexer _redisConnection;
        private readonly ICache _composite;
        private readonly ICache _redisCache;
        private readonly ICache _memCache;
        private int _cicle = 0;
        private readonly IEnumerable<int> _worker;
        private readonly int _workerCount = 4;
        private readonly int _iterationsCount = 100;

        public MultithreadBenchmark()
        {
            _seed = RandomString(2048);
            _redisConnection = ConnectionMultiplexer.Connect(ConfigurationOptions.Parse("192.168.0.106:7006"));
            _redisConnection.GetDatabase().Execute("flushall");
            _memCache = new hack.MemoryCache("t");
            _redisCache = new hack.RedisCache(_redisConnection, "r");
            _composite = new hack.CompositeCache(_memCache, _redisCache);
            _worker = Enumerable.Range(0, _iterationsCount);

        }

        [Benchmark]
        public void CompositeMultiThread()
        {
            Parallel.ForEach(_worker, new ParallelOptions { MaxDegreeOfParallelism = _workerCount }, (s) =>
            {
                Interlocked.Increment(ref _cicle);
                _composite.GetSet((_cicle).ToString(), () => _seed, TimeSpan.FromSeconds(60));
            });
        }

        [Benchmark]
        public void CompositeSingleThread()
        {
            foreach (var s in _worker)
            {
                _composite.GetSet((_cicle++).ToString(), () => _seed, TimeSpan.FromSeconds(60));
            }
        }

        [Benchmark]
        public void RedisMultiThread()
        {
            Parallel.ForEach(_worker, new ParallelOptions { MaxDegreeOfParallelism = _workerCount }, (s) =>
            {
                Interlocked.Increment(ref _cicle);
                _redisCache.GetSet((_cicle).ToString(), () => _seed, TimeSpan.FromSeconds(60));
            });
        }

        [Benchmark]
        public void RedisSingleThread()
        {
            foreach (var s in _worker)
            {
                _redisCache.GetSet((_cicle++).ToString(), () => _seed, TimeSpan.FromSeconds(60));
            }
        }

        public string RandomString(int length)
        {
            Random _random = new Random((int)DateTime.Now.Ticks);
            const string chars = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789";
            return new string(Enumerable.Repeat(chars, length)
              .Select(s => s[_random.Next(s.Length)]).ToArray());
        }
    }
}

and the results is this

In my mind, CompositeMultiThread and RedisMultiThread should be similar, isn't it? Probably the lock inside MemCache can't speed up the cache, have you any ideas?

[sklivvz]

I've rewritten the benchmark to run in LinqPad and I've added memory tests.

Results

Optimistic case

In this benchmark, the caches are always hit.

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
CompositeMultiThread	153.9 μs	1.45 μs	1.28 μs	51.2695	5.8594	-	281 KB
CompositeSingleThread	282.3 μs	1.23 μs	1.03 μs	42.9688	0.9766	-	243 KB
MemoryMultiThread	141.3 μs	1.15 μs	1.07 μs	31.9824	3.1738	-	171 KB
MemorySingleThread	248.3 μs	1.59 μs	1.41 μs	23.4375	0.4883	-	133 KB
RedisMultiThread	68,087.1 μs	1,174.50 μs	1,098.63 μs	625.0000	-	-	3,141 KB
RedisSingleThread	790,697.3 μs	12,142.78 μs	11,358.36 μs	-	-	-	3,103 KB

Pessimistic case

In this benchmark, the caches are always missed.	Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
CompositeMultiThread	4,179.6 ms	80.30 ms	95.59 ms	-	-	-	745 KB
CompositeSingleThread	4,171.1 ms	82.78 ms	73.39 ms	-	-	-	774 KB
MemoryMultiThread	4,259.5 ms	84.84 ms	83.33 ms	-	-	-	260 KB
MemorySingleThread	4,232.1 ms	83.80 ms	89.67 ms	-	-	-	187 KB
RedisMultiThread	292.3 ms	5.70 ms	6.34 ms	-	-	-	554 KB
RedisSingleThread	4,203.8 ms	84.02 ms	78.59 ms	-	-	-	510 KB

As you can see:

• CompositeCache doesn't really have any major impact in any scenario
• MemoryCache is always single-threaded because it's protected by a lock. This can be improved, but at the moment it behaves as designed.

The code to repro is here