Performance Issue in Loop

[GoogleCodeExporter]

Performing command operations within a loop causes a significant amount of 
time to be spent within the redis operation.

In the following example code takes 40 seconds to execute the loop.
The trans.Commit() command that follows is immediate.

What is the cause of this?

            using (var trans = this.redisClient.CreateTransaction())
            {
                string keyMaster = "key:";
                string valueMaster = "value:";

                for (int i = 0; i < 1000; i++)
                {
                    string key = keyMaster + i.ToString();
                    trans.QueueCommand(r => r.Set(key, valueMaster));
                }

                trans.Commit();

                for (int i = 0; i < 1000; i++)
                {
                    string key = keyMaster + i.ToString();
                    this.redisClient.Get<string>(key);
                }

            }

Original issue reported on code.google.com by christop...@gmail.com on 19 May 2010 at 10:29

[GoogleCodeExporter]

Hi, 

Even though the example works, it's probably a good idea to start using the 
'redisClient' again outside the transaction scope as 
they're both trans/redisClient use the same connection under the covers, the 
difference is that the connection is in a 'MULTI/EXEC' 
state when inside a transaction.

Anyway your code looks fine so I've modified your snippet to include timings 
and ran this inside a unit test (inside R#/VS.NET on my 
3yo iMac)

var before = DateTime.Now;
using (var trans = this.redisClient.CreateTransaction())
{
    string keyMaster = "key:";
    string valueMaster = "value:";

    for (int i = 0; i < 1000; i++)
    {
        string key = keyMaster + i.ToString();
        trans.QueueCommand(r => r.Set(key, valueMaster));
    }

    trans.Commit();

    for (int i = 0; i < 1000; i++)
    {
        string key = keyMaster + i.ToString();
        this.redisClient.Get<string>(key);
    }

    Console.WriteLine("Time Taken: {0}ms", (DateTime.Now - before).TotalMilliseconds);
}

And on my side I get:
>>Time Taken: 715.0409ms

So I'm really not sure where the performance problem is, hopefully if I get 
more information about your environment I might be able 
to track down the issue:

What version of redis-server are you running? Is it a windows or linux version?
Is it on the same network as your machine? What's your connection like? 
Does it make a difference if you specify an IP Address instead of a hostname in 
the connection?

Original comment by demis.be...@gmail.com on 19 May 2010 at 11:00

[GoogleCodeExporter]

Ok. I have run a few more tests to hopefully help, although I am not able to 
narrow 
down where the problem is.

My setup is:
Linux Server, running 1.2.6 redis server. 
I have also used the 1.3.12 redis server and received the same results.

I am running the ServiceStack.Redis.dll dated 5/12/10

I use a hostname to connect, but using an IP address does not make a difference 
in 
timing.

So, using the code as you modified it I get:
>>Time Taken: 81192ms

I modified the code to remove the transaction and just use SET / GET as shown 
and 
received:
                var before = DateTime.Now;

                string keyMaster = "key:";
                string valueMaster = "value:";

                for (int i = 0; i < 1000; i++)
                {
                    string key = keyMaster + i.ToString();
                    this.redisClient.Set(key, valueMaster);
                }

                for (int i = 0; i < 1000; i++)
                {
                    string key = keyMaster + i.ToString();
                    this.redisClient.Get<string>(key);
                }

                Console.WriteLine("Time Taken: {0}ms", (DateTime.Now - 
before).TotalMilliseconds);

>> Time Taken: 81074.1066ms

I have also tested against the migueldeicaza-redis-sharp test code as shown 
below and 
received results that match your times:

        Redis r;
        r = new Redis("or-consus");
        r.FlushAll();

        string keyMaster = "key:";
        string valueMaster = "value";

        var before = DateTime.Now;

        for (int i = 0; i < 1000; i++)
        {
            string key = keyMaster + i.ToString();
            r.Set(key, valueMaster);
        }

        for (int i = 0; i < 1000; i++)
        {
            string key = keyMaster + i.ToString();
            r.Get(key);
        }

        Console.WriteLine("Time Taken: {0}ms", (DateTime.Now - 
before).TotalMilliseconds);

>> Time Taken: 689.0689ms

Original comment by christop...@gmail.com on 20 May 2010 at 1:14

[GoogleCodeExporter]

Hi,

Thanks for this info, it means that there is definitely an issue with my client 
and not with any versions of the redis-server I'm testing against.

Now the biggest difference between my implementation and redis-sharp (where it 
was originally based) was that I've moved everything over to the new multi-
bulk, binary safe protocol which because it requires length of all keys and 
values so should in theory should actually be faster!

The other difference of using the new protocol is that it requires more 
'Socket.Send()' which I naively thought was harmless. It turns out that its not 
and 
makes a big difference. So now I've changed all my writes to use a buffer that 
I'm managing to ensure there is only one Flush (i.e. 'Socket.Send()') for 
every command (still puzzled by the 80x penalty tho). Anyway all 400+ tests 
pass with the fix so it should be safe to use.

It's actually quite embarrassing I didn't catch this perf-issue sooner. 
Unfortunately because all my tests are unit tests, I only have perf tests 
against a 
local instance of redis-server which doesn't exhibit these perf issues. 

Normally I would publish and distribute this fix right away, but because I'm in 
the middle of developing REST services around all operations you can find 
here: 
http://www.servicestack.net/RedisWebServices.Host/Public/Metadata

I've noticed that I've been using some inconsistent nomenclature so I've made 
some breaking changes to the IRedisClient API to be more accurate and 
consistent. So because its a breaking change I want to distribute the new 
client in-tandom with the Redis 2.0RC which should be out later today.

Anyway I've re-factored your sample code above to include 'logged intervals' 
which was helpful in tracking down the bottle-neck.
The new fix is inside the 'ServiceStack.Redis.dll' that is attached to this 
comment.

class Program
{
    const string KeyMaster = "key:";
    const string ValueMaster = "value:";
    private const int Iterations = 1000;
    private const int LogEveryTimes = 100;

    static void Main(string[] args)
    {
        var host = args.Length > 0 ? args[0] : "localhost";
        var port = args.Length > 1 ? int.Parse(args[1]) : 6379;

        var redisClient = new RedisClient(host, port);

        var before = DateTime.Now;
        for (var i = 0; i < Iterations; i++)
        {
            var key = KeyMaster + i;
            redisClient.Set(key, ValueMaster);

            if (i % LogEveryTimes == 0)
                Console.WriteLine("Time taken at {0}: {1}ms", i, (DateTime.Now - before).TotalMilliseconds);
        }

        for (int i = 0; i < Iterations; i++)
        {
            var key = KeyMaster + i;
            redisClient.Get<string>(key);

            if (i % LogEveryTimes == 0)
                Console.WriteLine("Time taken at {0}: {1}ms", i, (DateTime.Now - before).TotalMilliseconds);
        }

        Console.WriteLine("Total Time Taken: {0}ms", (DateTime.Now - before).TotalMilliseconds);
    }
}

Let me know if you find any problems with the attached client.
Thanks for reporting this issue, it looks like it will actually benefit all of 
mflow.com's users since we make significant use of Redis :)

Cheers,
Demis

Original comment by demis.be...@gmail.com on 20 May 2010 at 11:56

Attachments:

• ServiceStack.Redis.dll

[GoogleCodeExporter]

And just for clarity I'll show the massive perf gains that I'm now getting with 
the above program on my end.
Where before it was taking > 81 seconds, it now completes in just 330ms, so I 
think its fixed :)

#SET INTERVALS
Time taken at 0: 33ms
Time taken at 100: 48ms
Time taken at 200: 63ms
Time taken at 300: 78ms
Time taken at 400: 93ms
Time taken at 500: 107ms
Time taken at 600: 122ms
Time taken at 700: 136ms
Time taken at 800: 150ms
Time taken at 900: 165ms

#GET INTERVALS
Time taken at 0: 190ms
Time taken at 100: 205ms
Time taken at 200: 219ms
Time taken at 300: 233ms
Time taken at 400: 247ms
Time taken at 500: 261ms
Time taken at 600: 275ms
Time taken at 700: 289ms
Time taken at 800: 303ms
Time taken at 900: 316ms

#TOTAL
Total Time Taken: 330ms

Original comment by demis.be...@gmail.com on 20 May 2010 at 12:12

[GoogleCodeExporter]

Thank you very much!  The problem is indeed fixed.

It took a little longer to get the code to compile with all the changes you 
have 
made, but once I did my results came in similar to yours:

Time taken at 0: 2.0002ms
Time taken at 100: 25.0025ms
Time taken at 200: 47.0047ms
Time taken at 300: 69.0069ms
Time taken at 400: 88.0088ms
Time taken at 500: 107.0107ms
Time taken at 600: 127.0127ms
Time taken at 700: 148.0148ms
Time taken at 800: 168.0168ms
Time taken at 900: 188.0188ms

Time taken at 0: 214.0214ms
Time taken at 100: 233.0233ms
Time taken at 200: 254.0254ms
Time taken at 300: 274.0274ms
Time taken at 400: 294.0294ms
Time taken at 500: 315.0315ms
Time taken at 600: 335.0335ms
Time taken at 700: 354.0354ms
Time taken at 800: 374.0374ms
Time taken at 900: 395.0395ms
Time Taken: 415.0415ms

Original comment by christop...@gmail.com on 20 May 2010 at 6:21

[GoogleCodeExporter]

Awesome great to hear! 

Maybe it's just randomness in timings, but by the looks of it it looks even 
quicker 
than the raw redis-sharp no?

Original comment by demis.be...@gmail.com on 20 May 2010 at 6:25

[GoogleCodeExporter]

I have run both tests (ServiceStack and redis-sharp) several times now and the 
ServiceStack is consistently faster.  Nice job! 

Original comment by christop...@gmail.com on 20 May 2010 at 6:39

[GoogleCodeExporter]

Since the fix is now included in the new releases available at:
http://code.google.com/p/servicestack/wiki/RedisClientReleaseNotes

I'm now closing this issue. Thanks for reporting!

Original comment by demis.be...@gmail.com on 22 May 2010 at 10:51

• Changed state: Fixed