2

For my console application, I have implemented a simple file logger. The logger uses StringBuilder to keep appending log entries and writes the LogText data to the LogFile at the end. This results in having only one file I/O operation. The application execution must be extremely fast and hence, I have implemented Parallel.ForEach along with async-await and reduced I/O operations wherever possible.

The problem is that Logger is not thread safe. Using lock or Monitor to synchronize the shared resource logger inside Parallel.ForEach loop slows down the performance. Is there any optimal way to synchronize the shared resource which does not affect execution speed much?

I am open to alternative approaches or suggestions.

Logger.cs

public class Logger
{
    private readonly string LogFile;
    private readonly StringBuilder LogText;

    public Logger(string logFile)
    {
        LogFile = logFile;
        LogText = new StringBuilder();
    }

    public void Write(string message)
    {
        LogText.AppendLine(message);
    }
    
    public void WriteToFile()
    {
        File.AppendAllText(LogFile, LogText.ToString());
    }
}

Program.cs

public class Program
{
    public static void Main(string[] args)
    {
        string logFile = args[0];
        string workingDirectory = args[1];
        Logger logger = new Logger(logFile);
        logger.Write($"INFO | Execution Started");

        try
        {
            List<string> files = Directory.EnumerateFiles(workingDirectory, "*", SearchOption.AllDirectories).ToList();
            Parallel.ForEach(files, async file =>
            {
                List<string> results = await PerformCPUBoundComputationAsync();
                foreach(string result in results)
                {
                    logger.Write($"INFO | Item: {result}");
                }
                string response = await MakePostRequestAsync(results);
                logger.Write($"INFO | Response: {response}");
            });
        }
        catch (Exception ex)
        {
            logger.Write($"ERROR | {ex.Message}");
        }
        finally
        {
            logger.Write($"INFO | Execution Ended");
            logger.WriteToFile();
        }
    }
}
halfer
  • 19,824
  • 17
  • 99
  • 186
Ronak Thakkar
  • 59
  • 1
  • 1
  • 7
  • 1
    "I have made another thing, is it good?" questions should go to [codereview](https://codereview.stackexchange.com/). There are dozens of questions regarding [lock-free](https://stackoverflow.com/q/9103758/1997232) synchronization too, please do research first. – Sinatr Oct 22 '20 at 07:32
  • 1
    Hrm, why not just use a logging framework that has taken care of all these issues and many more you will have ? However there are some very suspect parts of this code, `Parallel.ForEach(files, async file` You are using Parallel.ForEach to spin up a bunch of async voids, `PerformCPUBoundComputation` is async, seems a little strange. Obviously this is not thread safe at all, but you know that – TheGeneral Oct 22 '20 at 07:32
  • @TheGeneral, shouldn't everybody try to wrote his own buble-sort and logger? – Sinatr Oct 22 '20 at 07:34
  • @Sinatr I guess it is... character building... – TheGeneral Oct 22 '20 at 07:36
  • 1
    Does the log need to be in chronological order of operation? does it matter if the log is slightly out of order? – TheGeneral Oct 22 '20 at 07:45
  • Chronology is not required – Ronak Thakkar Oct 22 '20 at 07:47
  • `PerformCPUBoundComputation()` uses `Task.Run()` to follow `async`-`await` – Ronak Thakkar Oct 22 '20 at 07:50
  • `PerformCPUBoundComputation()` returns a `Task` that your anonymous method awaits, but your anonymous method isn't awaited by `Parallel.ForEach`. – ProgrammingLlama Oct 22 '20 at 07:53
  • 1
    Is`MakePostRequest` IO bound work ? Why are you not awaiting this ? – TheGeneral Oct 22 '20 at 07:57
  • No - It makes an API call. It is awaited. – Ronak Thakkar Oct 22 '20 at 07:58
  • 1
    Api call means IO bound, ie its heading out over your network card – TheGeneral Oct 22 '20 at 07:59
  • 1
    As a side note, the `Parallel.ForEach` [is not async-friendly](https://stackoverflow.com/questions/15136542/parallel-foreach-with-asynchronous-lambda). The lambda passed is [async void](https://learn.microsoft.com/en-us/archive/msdn-magazine/2013/march/async-await-best-practices-in-asynchronous-programming#avoid-async-void). What happens is that the asynchronous operations are not awaited, and the `Parallel.ForEach` will return before the completion of these operations. This is probably not what you want. – Theodor Zoulias Oct 22 '20 at 08:19
  • How many log entries are generated during the whole operation on average? And what is the duration of the whole operation on average? I am asking because I would expect the contention for a lock to be negligible for anything less than, say, 10,000 log entries per second. – Theodor Zoulias Oct 22 '20 at 08:54
  • At most 100 log entries inside the loop – Ronak Thakkar Oct 22 '20 at 16:57

1 Answers1

1

This is not using your Logger class, I just want to show you an alternative approach

First we don't use Parallel.ForEach for IO bound work, it's not suitable, and we definitely don't give it an async lambda (which is an unobserved async void), which means Parallel.ForEach will finish before all the tasks complete.

As for your issues:

  1. To solve the completed task problem, let's use WhenAll
  2. To solve the thread safety issue, let's make a separate string builder for each task. It's a little allocatey, however it's lock free.
  3. Let's write all the logs at the end

The async and await pattern will return threads back to the thread pool when it's completing IO-bound work. The tasks scheduler will use those threads for CPU bound work.

var tasks = Directory
   .EnumerateFiles(workingDirectory, "*", SearchOption.AllDirectories)
   .Select(async x =>
   {
      var sb = new StringBuilder();
      List<string> results = // do cpu bound work, no need for fake async, 
      // thats to say no need to offload to another thread. 
      foreach (string result in results)
         sb.AppendLine($"INFO | Item: {result}");
      string response = await MakePostRequestAsync(results);
      sb.AppendLine($"INFO | Response: {response}");
      return sb;
   });

// await all your work to finish
var logs = await Task.WhenAll(tasks);

// write the results to the file
using var sw = new StreamWriter("FileName");
sw.WriteLine($"INFO | Execution Started");

foreach (var log in logs)
   sw.WriteLine(log);

sw.WriteLine($"INFO | Execution Ended");

Note : this may cause allocation and memory pressure depending on how big the log gets. In which case you may need to go back to a synchronization primitive, and take the penalty of the lock.

Another efficient approach, is to use something like Tpl Dataflow pipeline, do your calculations, do your posts, then batch the results for the writes which would likely be less allocatey and will have the advantage of a dealing with the sync and async workloads.

Processing (parallel)
       v
Posting (parallel)
       v
Batched Log Writes (Singular)
halfer
  • 19,824
  • 17
  • 99
  • 186
TheGeneral
  • 79,002
  • 9
  • 103
  • 141
  • I am performing file hash calculations in `PerformCPUBoundComputationAsync()` which takes up a lot of time, so I thought of offloading the computation to a new thread using `Task.Run()` - if possible want to avoid sequential calculation of different types of hashes – Ronak Thakkar Oct 22 '20 at 08:19
  • 1
    @RonakThakkar `Select(async x =>` means you are starting new hot tasks (and when the scheduler sees fits, thread pool threads) to do your processing asynchronously – TheGeneral Oct 22 '20 at 08:22
  • How about using `ConcurrentQueue` to store log entries in thread safe manner and then use it to write to log file? – Ronak Thakkar Oct 22 '20 at 08:32
  • 2
    @RonakThakkar yes that would be fine as well, however if you had problems with the performance of `lock` you will have performance problems with any concurrent collection – TheGeneral Oct 22 '20 at 08:33
  • 1
    Starting multiple tasks for CPU-bound workloads, and awaiting them with `Task.WhenAll(tasks)`, is not a good idea. What will happen is that the `ThreadPool` will be immediately saturated, and then a new thread will be injected every 500 msec during the duration of the whole operation. This will cause oversubscription (more threads than processors) and overhead at the operating system level. Using the `Parallel` class or PLINQ is much preferable IMHO. – Theodor Zoulias Oct 22 '20 at 08:35
  • 1
    @TheodorZoulias, the Task Scheduler will divi out threads regardless anyway, the advantage with not using parallel or plinq is the threads will go back to the threadpool when a completion port is queue up with the io work. Eitherway, if this is majorly cpu, you would expect all cores to be used. but i think i see where you are getting to, and its a worthy point – TheGeneral Oct 22 '20 at 08:39
  • Yes, the `Parallel` and PLINQ will employ a set number of threads during the whole operation, but this should not be a problem, unless the application does also other things in parallel. – Theodor Zoulias Oct 22 '20 at 08:51
  • 1
    @TheodorZoulias since the OP said file hashing late in the comments, which has a significant IO component and the Hashing being CPU, then the posting being IO again, as well as writing logs. My gut feeling now is this should more than likely be a pipeline. It would give the best of all worlds. Being able to reign in parallelism of CPU work, efficiently que up IO work, and batch file writes. What do you think? I would quickly spin one up to show the concept to the OP, however i am on dinner duty tonight :P – TheGeneral Oct 22 '20 at 08:55
  • Certainly, this job may be a good match for the [TPL Dataflow](https://learn.microsoft.com/en-us/dotnet/standard/parallel-programming/dataflow-task-parallel-library) library. But I wouldn't expect to be trivial. If the files are large then they could not be passed efficiently through the pipeline, and so they would need to be split in `byte[]` chunks. Calculating the hash of each file from multiple chunks should be tricky. – Theodor Zoulias Oct 22 '20 at 09:07
  • @TheGeneral @TheodorZoulias To provide more clarification - `PerformCPUBoundComputationAsync()` computes MD5, SHA1 and SHA2 hashes for the files – Ronak Thakkar Oct 22 '20 at 17:02
  • 2
    @RonakThakkar calculating hashes is not particularly CPU intensive. The program is spending more time waiting for data to come from the disk, than processing these data. You should be able to conform this by watching the CPU utilization while the program is running. My 4-cores PC shows less than 10% CPU load, while hashing a big file. What you should avoid is reading each file multiple times, one for each type of hash. You can form a pipeline of `CryptoStream`s, and read each file once. – Theodor Zoulias Oct 23 '20 at 08:08
  • 2
    TheGeneral I made some experiments with the TPL DataFlow, and I saw some marginal performance improvements (~10%) by offloading the calculation of the hash to a different thread than the thread that reads the file. These meager gains are coming at the cost of much complexity (dealing with the methods of the `ICryptoTransform` interface, using the `ArrayPool` to avoid excessive buffer allocations etc), so I don't think that it's worth the effort. – Theodor Zoulias Oct 23 '20 at 08:21
  • 2
    @TheodorZoulias ahh ok yeah interesting, nice work. Yeah I figured it was going to be a bit of mucking around. Though i would have just read and hashed in the one method, also knowing the was other async work to do. anyway once again, empirical results are good results. If you want to make an answer ill be sure to upvote. – TheGeneral Oct 23 '20 at 08:24