Commited transaction with task not completed in Redis 2.x

[BenedicteLeo]

I have updated a project from Redis 1.2.6 to Redis 2.0.495 under target framework net462. Since the update, some tasks that are part of a transaction are not completed after executing the transaction. I suspect it is a 2.x bug since it was working consistently before, and I haven't seen a related release note (do tell if I missed it).
Here is a simplified code sample:

ConditionResult keyNotExists = transaction.AddCondition(Condition.KeyNotExists(someKey));
Task hashSetTask = transaction.HashSetAsync(someKey, someValues);
Task<bool> expireTask = transaction.KeyExpireAsync(someKey, ttl);

bool committed = await transaction.ExecuteAsync();
Debug.Assert(hashSetTask.IsCompleted, "This fails sometimes");
Debug.Assert(expireTask.IsCompleted, "This also fails sometimes");

Both Debug.Asserts fail very frequently (as I run tests), but they don't fail all of the time. In addition, the asserts also fail when I put them inside an "if(commited)" conditional. Thank you.
[Edit] I forgot to mention I'm using Redis 3.2.100 (00000000/0) 64 bit

[NickCraver]

Are you deleting (or setting) someKey before the test? Or is it inconsistent? e.g. does the transaction fail or succeed?

[BenedicteLeo]

The key is generated at random. The transaction succeeds.

Here is the script I just ran in LinqPad, and the issue repros.

ConnectionMultiplexer conn = ConnectionMultiplexer.Connect("localhost,abortConnect=false");
var db = conn.GetDatabase();
for (int i = 0; i < 40000; i++)
{
	string key = "key~" + Guid.NewGuid();
	HashEntry[] hashEntries = new HashEntry[]
	{
	       new HashEntry("blah", DateTime.UtcNow.ToString("R"))
	};
        ITransaction transaction = db.CreateTransaction();
	ConditionResult keyNotExists = transaction.AddCondition(Condition.KeyNotExists(key));
	Task hashSetTask = transaction.HashSetAsync(key, hashEntries);
	Task<bool> expireTask = transaction.KeyExpireAsync(key, TimeSpan.FromSeconds(30));
	bool committed = await transaction.ExecuteAsync();	
	if (committed)
	{
		if (!hashSetTask.IsCompleted) "Oh no!".Dump();
		if (!expireTask.IsCompleted) "Oh no2!".Dump();
	}
}

The 40000 key-value pairs get created (I view them using RedisDesktopManager), and they do expire (get deleted) after 30s.

I forgot to mention I'm using Redis 3.2.100 (00000000/0) 64 bit.

[mscrivo]

Seeing the exact same thing here, we have a bunch of tests that now never complete with 2.0.495 (whereas 1.2.6 worked perfectly fine), with code very similiar to @BenedicteLeo's. The interesting thing is that, on my dev machine (which is a 4C/8T machine), I can't reproduce the issue. But it reproduces 100% of the time on our slow 1C/1T build agents. We are using Redis 4.0.11.

[BenedicteLeo]

Interesting; I'm running my tests on an average 4C/8T machine.

[mgravell]

This is very high on my priority list to investigate, thanks.

…

On Fri, 7 Sep 2018, 19:05 Benedicte, ***@***.***> wrote: Interesting; I'm running my tests on an average 4C/8T machine. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#943 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AABDsHltSN6QJ9dn6UikYPBUwQzHu5zyks5uYrVagaJpZM4Wd9bo> .

[mgravell]

Right; I've been looking at this, and I think this is a minor expectation failure rather than a "OMG the lib is on fire" problem.

There is a slight behaviour difference between 1.* and 2.* here - you aren't imagining things; the difference is:

• in 1.* it attempted to set the task result eagerly, but there were scenarios where this could cause thread-stealing (very very bad; and no, the "don't allow sync continuations" flag doesn't help)
• in 2.* it sets the task results via a worker

the difference, then, is that when under load, the result can be "seriously, I'm just about to be completed, but right now I'm not". The current solution then (without any lib changes), is to either await the result (which will often be already complete), or if you're in sync code... meh you can probably just use .Result if you know that the transaction has completed - the inner tasks will be literally about to complete.

For example, if I do this to the test provided above, and add counters, then I get:

09:03:29.865: hash hit: 39991, miss: 9; expire hit: 39993, miss: 7

(edit: where "hit" means "was already completed", and "miss" means "wasn't")

with the main code change being:

if (committed)
{
    if (hashSetTask.IsCompleted) hashHit++; else hashMiss++;
    if (expireTask.IsCompleted) expireHit++; else expireMiss++;
    await hashSetTask;
    await expireTask;
}

so... it is pretty rare, and await (or .Result) works; I'll take a look to see if we can perhaps reverse the orders, so that the transaction is the last thing added to the worker - however, there is inherently a race scenario here, and in theory it is possible that even if we queue them in the "right" order, very occasionally they might get completed in the other order. Because: threads.

Unfortunately, it is painfully hard to avoid this kind of problem because of the design of Task<T> and the risk of thread-stealing.

[mgravell]

Upon further reading, it looks like we're already processing them in the "correct" (inner-first) order, so the 16 misses above are exactly the number of times the completion race happened such that the outer task (the transaction itself) overtook one of the inner tasks.

Right now, I'm thinking the best approach here might be to presume that most transaction tasks won't have pre-emptively had continuations added; specifically, that this is the exception rather than the rule:

Task<bool> expireTask = transaction.KeyExpireAsync(key, TimeSpan.FromSeconds(30));
expireTask.ContinueWith( /* some continuation here */); // <==== this line
bool committed = await transaction.ExecuteAsync();	

If we are right about that being rare, then because we're no longer targeting NET45, we could use - purely for the inner tasks in a transaction - TaskCreationOptions.RunContinuationsAsynchronously - and set the result directly rather than via the worker (however, all other tasks would continue to use the new dedicated thread-pool, not the default async pool). The result of this would be:

• the inner tasks are always completed eagerly (meaning: before the transaction itself completes)
• if you have scheduled a continuation on an inner task of a transaction, it'll uses the default pool rather than the custom pool, so when heavily contested there might be pauses; this is probably fine

Frankly, I expect that when using continuations, most people are moving to await rather than ContinueWith, in which case they would only be await-ing after the transaction has completed, which will then be a sync-await. In fact, with the above change it would now always be a sync await, rather than almost always.

I'll spike the change, and see how it works.

[mgravell]

fix looks viable:

09:34:09.699: hash hit: 40000, miss: 0; expire hit: 40000, miss: 0

adding PR (#950) for review

[mgravell]

merged; closing as "fixed next build" (I'll try to get this out today)