async/await deadlock caused by Thread.Sleep?

Question

I have a couple of classes that look like this:

Class REST

public class REST
{   
    ...
    public async Task<Status> GetStatus()
    {
        var message =  new HttpRequestMessage(HttpMethod.Get, "https://localhost...");
        message.Headers.TryAddWithoutValidation("Authorization",
            $"Basic {Convert.ToBase64String(Encoding.UTF8.GetBytes("admin:admin"))}");

        HttpResponseMessage response = null;
        try
        {
            response = await HttpClient.SendAsync(message, HttpCompletionOption.ResponseContentRead);
            return JsonConvert.DeserializeObject<Status>(response.Content.ReadAsStringAsync().Result);
        }
        catch (Exception e)
        {
            Console.WriteLine(e);
            throw;
        }
    }
}

Class Logger

public class Logger
{   
    private static ReaderWriterLockSlim writeLock = new ReaderWriterLockSlim();
    public async Task Log(int number, LogMessage message)
    {
        var time = DateTime.Now.ToString("O");
        var fileName = "C:/temp/random.log";
        writeLock.EnterWriteLock();

        try
        {
            if (File.Exists(fileName))
            {
                if (new FileInfo(fileName).Length >= 10000000)
                {
                    await WaitForRestCall(fileName);
                    File.Move(fileName, $"C:/temp/random_{Current}.log");
                    Console.WriteLine($"Logging message {number}, timestamp = {message.TimeStamp}");
                    using (var sw = File.CreateText(fileName))
                    {
                        var log = $"{number}\t{time}\t{message.Message}";
                        sw.WriteLine(log);
                    }

                    Current++;
                }
                else
                {
                    Console.WriteLine($"Logging message {number}, timestamp = {message.TimeStamp}");
                    using (var sw = File.AppendText(fileName))
                    {
                        var log = $"{number}\t{time}\t{message.Message}";
                        sw.WriteLine(log);
                    }
                }
            }
            else
            {
                Console.WriteLine($"Logging message {number}, timestamp = {message.TimeStamp}");
                using (var sw = File.CreateText(fileName))
                {
                    var log = $"{number}\t{time}\t{message.Message}";
                    sw.WriteLine(log);
                }
            }
        }
        catch (Exception ex)
        {
            throw;
        }
        finally
        {
            writeLock.ExitWriteLock();
        }
    }

    private async Task WaitForRestCall(string fileName)
    {
        var finishedReading = false;
        do
        {
            var check = await REST.Instance().GetStatus();
            if (!check.OK)
            {
                Console.WriteLine($"Waiting for task to finish.");
                Thread.Sleep(1000);
            }
            else
            {
                finishedReading = true
            }
        } while (!finishedReading);
    }
}

(Both are singleton classes, that's why the Instance() method is called there)

I'm testing this interaction between the classes with this Console app:

Console

class Program
{
    static void Main(string[] args)
    {
        Log();
        Console.ReadKey();
    }

    public static Task Log()
    {
        string oneKBMessage = "<1KB string here>"

        var logger = Logger.Instance();

        var tasks = Enumerable.Range(0, 100000).Select(i => Task.Run(async () =>
        {
            await logger.Log(i, new LogMessage() { Message = oneKBMessage, TimeStamp = DateTime.Now });
        }));

        return Task.WhenAll(tasks);
    }
}

Now, I followed Stephen Cleary's advice to make everything async all the way up, but when the application has to check with the REST API if it doesn't return "Done" and goes to sleep, the next cycle of that do/while when the REST class calls the API it freezes everything there. I assume there's a deadlock, but I can't see why it's happening.

Any ideas?

Thanks

Answer 1

Everything that stated by Gabriel Luci are completely true, but I want talk about the scenario that causes your application not responding:

1. You simultaneously start 100,000 threads, so all threads in thread pool will be consumed!
2. All of them except one wait behind your lock
3. One thread can enter the lock and is waited by Thread.Sleep
4. After sleep elapsed want to resume but no thread remains to continue execution
5. Even without any Sleep, because default number of threads in thread pool is far less than 100,000 , any newly created thread (each takes 500ms!) will be consumed to start new task instead of continuation already awaited task!
6. Starvation!

Answer 2

My guess is that the call writeLock.EnterWriteLock(); blocks too many threads. Your program creates 100,000 Task.Run tasks at the same time, and all of them request ownership of the same lock. So all available threads in the ThreadPool are immediately blocked, and there is no thread available to process the continuation of the single asynchronous workflow that has acquired the ownership of the lock, and thus is allowed to make progress. The ThreadPool is designed to respond to this starvation event by injecting one new thread every 500 msec. This rate is obviously too slow for serving all 100,000 tasks in a timely manner.

If this is indeed the source of the problem, then a possible solution is to use a lock that can be awaited asynchronously, like the SemaphoreSlim.

---

Update: another option instead of the SemaphoreSlim is the AsyncReaderWriterLock class, from Stephen Cleary's Nito.AsyncEx.Coordination package.

Answer 3

I see a couple red flags:

First, change Thread.Sleep(1000) to await Task.Delay(1000) so you're not blocking the thread. That may be part of your problem, although I don't see quite how at the moment.

Second, your Main method:

static void Main(string[] args)
{
    Log();
    Console.ReadKey();
}

There are two issues:

1. Log() returns a Task that you are not observing to see when it has completed. You are probably getting a compiler warning about that.
2. Your Main method is void, which means it can't use await.

The reason these are a problem is that the await keyword will return when it acts on an incomplete Task (and the rest of the method is signed up as the "continuation" to happen when after the waiting is done). Usually it returns its own Task object, but if it can't because the method is void, it returns nothing. But it still returns.

Because you're not doing anything with the Task returned from Log(), your Main method continues and you never know if it completes.

I see you are using Console.ReadKey() to keep the program running, which is "ok". But you could just change your Main method to async Task and await Log():

static async Task Main(string[] args)
{
    await Log();
}

That is assuming you are using C# 7.1+, since that's when you could start returning a Task from Main().

Also, you are creating 100,000 threads but only allowing one to work at any one time. Why not just create a regular for or foreach loop and do them one at a time?

for (var i = 0; i < 100000; i++)
{
    await logger.Log(i, new LogMessage() { Message = oneKBMessage, TimeStamp = DateTime.Now });
}

Then you don't even need the locks - at least for this specific use case. If there are other cases where you will call it from different threads, then keep the locks.