4

I'm trying to create a simple asynchronous logger. The idea to make the logging calls non-blocking and as unobtrusive as possible. Please consider the following simplified codes -

class Logger {
    public async void Log(string message) {
        LogTable log = new LogTable(); //LogTable is an SqlServer table
        log.Timestamp = DateTime.Now;
        log.Message = message;
        log.SomeProp = SomeVariableTimeCalculation();
        var db = new Entities(); //db is an EF6 context
        db.Entry(log).State = EntityState.Added;
        db.LogTables.Add(log);
        await db.SaveChangesAsync();
   }
}

It can be used it as follows (not awaiting on any Log(...) call) -

class Account
    private readonly Logger logger = new Logger();
    public void CreateAccount(Account acc) {
        logger.Log("CreateAccount Start");
        //Maybe some async operations here
        logger.Log("CreateAccount Validation Start");
        bool isValid = Validate(acc);
        logger.Log("CreateAccount Validation End");
        if(isValid) {
            logger.Log("CreateAccount Save Start");
            acc.Save();
            logger.Log("CreateAccount Save End");
        }
        else {
            logger.Log("Account validation failed");
        }
        logger.Log("CreateAccount End");
    }
}

My questions are -

  1. There are multiple async Log(...) calls one after another. Can the compiler potentially choose to run all them in parallel simultaneously? If yes, does the compiler know to maintain the order of these calls so that logger.Log("CreateAccount Validation Start"); doesn't end up running before logger.Log("CreateAccount Start");?

  2. If the compiler doesn't preserve order, then is there a way around it other than maintaining a queue within the Logger class?

UPDATE: A clarification - my main concern is avoiding race conditions that could, for example, result in logger.Log("CreateAccount Validation Start"); running/completing before logger.Log("CreateAccount Start"); and calling Log without blocking CreateAccount.

Achilles
  • 1,099
  • 12
  • 29
  • 2
    @AlGoreRhythm [`async` is not about multithreading](http://stackoverflow.com/q/17661428/11683). – GSerg Feb 01 '17 at 15:52
  • Entity Framework does not support multiple concurrent calls to the DB (I'm assuming EF based on the `SaveChangesAsync()` method). If these calls do run in parallel you'll get an Exception. – Erik Philips Feb 01 '17 at 15:56
  • 1
    @ErikPhilips *A single context* cannot perform concurrent calls. The code creates a new context for each call. Different contexts can both perform operations concurrently just fine. – Servy Feb 01 '17 at 15:57
  • @Servy yes I wasn'y quite as explicit as that. It was more of a comment around being careful under these conditions. – Erik Philips Feb 01 '17 at 15:59
  • It looks like you want to have two unrelated execution flows, where each flow would preserve strict order within itself, but it would not matter if any commands of one flow executed before or after any commands of the other flow. This is not exactly what `async/await` is about. You probably want to explicitly create some kind of background worker and post logging requests to it. – GSerg Feb 01 '17 at 15:59
  • @GSerg Yes, thank you. It's an ASP.NET MVC application with the `Log` method being called all over (in controllers, libraries etc). What form would the background worker take? – Achilles Feb 01 '17 at 16:22
  • @Achilles In any way you like. E.g. you could start with http://stackoverflow.com/a/15120092/11683, change the methods to return `void` and accept the logging parameters (e.g. `public void Log(string message)`), and change `previousTask` to be `Task.Run(() => Task.FromResult(true))`. Natually in the `ContinueWith` you'd have `ContinueWith(t => ActuallyDoLog(message))`, where `ActuallyDoLog` is your current `public async void Log(string message)`. – GSerg Feb 01 '17 at 17:07
  • @GSerg Thank you, this is very helpful. – Achilles Feb 01 '17 at 18:12
  • @GSerg The whole point of that answer is that it's generic. You don't copy-paste it and change the code a bit for each specific situation. You have the queue in your code once, and you create instances of it and call it using whatever code you have to run. Note that that specific code is set up for work done synchronously, not asynchronously. For asynchronous work you'd need to unwrap the `Task`, as [shown here](http://stackoverflow.com/questions/32993301/rising-events-without-blocking-and-receiving-events-in-the-right-order/32993768#32993768). – Servy Feb 01 '17 at 18:50
  • @GSerg Your proposed change, without properly making `Log` expose a `Task` and having the queue properly handle it, would result in exactly the same bug that the OP has in their current code. Also, there's absolutely no reason to wrap `Task.FromResult` in a call to `Task.Run`. That's just pointlessly adding extra work. – Servy Feb 01 '17 at 18:51
  • @Servy Thank you. Could you please elaborate on the synchronous vs asynchronous bit? So far, my (somewhat fuzzy) understanding is that this will ultimately result in a chain of `.ContinueWith` which would act like a pseudo-queue but I'm definitely missing something because I've no idea of the wrap/unrap etc here. – Achilles Feb 01 '17 at 19:22
  • @Achilles Your method is inherently asynchronous, not synchronous, so you need to make sure that the next operation can continue after your asynchronous operation finishes entirely, rather than when it returns for the first time (which is when it finishes *starting* the asynchronous operation). The version I linked to is specifically designed to work with an asynchronous operation, so just use that one, rather than the one GSerg linked to. You can see the difference in code yourself, it's just adding an `Unwrap` call. – Servy Feb 01 '17 at 19:36
  • @Servy I made the changes and tested them before posting that comment. The whole point of that answer is not that it's generic, it's that it provides a way to chain a next piece of work to the previous piece of work, whether or not it has been completed. I removed the generics from that code and left one `public void Log(string message)`, specifically to make the usage simpler (as opposed to e.g. `AddTask(() => Log(Message))`, having to write that each time would be unhelpful). There is no exposed `Task` and it works like it should, processing `Log` requests on another thread. – GSerg Feb 01 '17 at 19:57
  • @GSerg The solution to preventing the caller from having to do that (because they shouldn't; it would be requiring the caller to manage the synchronization of the logger that it should be responsible for) is simply to have the `Log` class handle calling out to the queue, not to copy-paste the code from the queue into that method. And for the record, yes, the point of that answer *is* that it's generic. (I'd know, I wrote it, and I know I intentionally wrote it to be generic.) – Servy Feb 01 '17 at 20:03
  • @Servy The log class is handling the queue. Not sure I explained well. [Here](http://pastebin.com/pZ0GLhRN)'s what I was thinking about. – GSerg Feb 01 '17 at 20:18
  • @GSerg Again, it shouldn't do that. You don't copy-paste all of the code form the task queue every time you want to use it. You just create an instance of it and enqueue the operations you want to perform in it. Keep the task queueing logic in one place, not copy-pasted all throughout your code base. In addition to that, you also did it wrong, for all of the reasons I've told you before. Your code doesn't actually work correctly, and has superfluous code, in addition not leaving the task queuing logic in the task queue class. – Servy Feb 01 '17 at 20:20

3 Answers3

2

Can the compiler potentially choose to run all them in parallel simultaneously?

No. Asynchrony is completely different than parallelism.

If the compiler doesn't preserve order, then is there a way around it other than maintaining a queue within the Logger class?

The compiler does preserve order (that is, await is used for sequential asynchronous code). However, a queue is still not a bad idea because you probably don't want to hit the actual database on every logging call.

Stephen Cleary
  • 437,863
  • 77
  • 675
  • 810
  • Thanks. I think I should rephrase the question. I didn't mean to compare async with parallelism. When you say the compiler does preserve order of the ansyc calls, does it know to run the subsequent async calls after the previous ones have completed? – Achilles Feb 01 '17 at 16:08
  • 1
    As long as you await the previous ones they will run in sequence. – Lasse V. Karlsen Feb 01 '17 at 16:12
  • @LasseV.Karlsen Yes, but that would defeat the purpose. I'm basically trying to do it so that the `Log` calls run in their asynchronously and in order but without blocking the `CreateAccount` method. – Achilles Feb 01 '17 at 16:19
  • @Achilles Then I [guessed](http://stackoverflow.com/questions/41983875/is-the-order-of-async-calls-maintained-in-net-implementing-logger-with-async-a#comment71146159_41983875) right. – GSerg Feb 01 '17 at 16:19
  • While it is true that parallelism and asynchrony are different *the OP's particular asynchronous code involves some amount of parallelism*, so saying that there is no parallelism going on here is simply wrong. (The operations aren't able to run *entirely* in parallel, but, as is, the code won't run entirely sequentially either.) – Servy Feb 01 '17 at 17:00
1

Barring any other explicit use of tasks/threads/parallelism, an async method always runs synchronously from the perspective of it's caller until it hits the first await1.

So you Log calls cannot return until at least the point that they're waiting for SaveChangesAsync to complete.

1It may continue to run synchronously at this point, however, if the awaitable in question has already completed. So that's the earliest point at which it may return control to its caller, not a guaranteed point of return of control.

Damien_The_Unbeliever
  • 234,701
  • 27
  • 340
  • 448
  • 1
    But they can still run into race conditions if a `Log` gets to `SaveChangesAsync` and then a subsequent log starts and gets all the way to the end and saves before the first one finishes saving. Unlikely perhaps, but possible. – Servy Feb 01 '17 at 15:52
  • @Servy - agreed - but hopefully there aren't too many issues here given that the timestamp is being taken explicitly before saving. So provided its not producing actual errors, it should be possible to order the log messages correctly based on the saved data. – Damien_The_Unbeliever Feb 01 '17 at 15:54
  • The point is that a log entry with a later timestamp can be added to the dictionary before an entry with an earlier timestamp. That's what the question asks about, and it can happen. – Servy Feb 01 '17 at 15:57
  • Thanks Servy, yes avoiding the race conditions was the intent of the question. I think I will edit it to make it clear. – Achilles Feb 01 '17 at 16:09
0

I think what you're essentially asking is whether this will output 1, 2, 3, ..., 999, 1000

for (int i = 1; i <= 1000; ++i)
{
    logger.Log(i.ToString());
}

The simple answer is no. Each task could and probably often will take a slightly different duration to execute compared to others, so e.g. the task for 5 could execute before the task for 4 is complete.

sellotape
  • 8,034
  • 2
  • 26
  • 30