# Async time logging in multithread application

I have a simple producer-consumer multhithread application, I am trying to measure a few points in both threads for benchmarking. What I came up with is the TPL dataflow library of .Net, and I have also found a few supporting posts on this idea. However, I am a bit suspicious if it is the most accurate/reliable way to get time bits. Because it critical to get these values as sensitive as we could (micro/nano second level)

### Logger Class

public interface ILogMessage
{
long OrderId { get; set; }
}
/// <summary>
/// Queue Thread Time measurement Points
/// </summary>
public class QueueLoggerPoint : ILogMessage
{
public DateTime BeforeProcTime { get; set; }
public DateTime AfterProcTime { get; set; }
public long OrderId { get; set; }
}
/// <summary>
/// Order Thread Time measurement Points
/// </summary>
public class OrderLoggerPoint : ILogMessage
{
public DateTime BeforeDequeue { get; set; }
public DateTime AfterSend { get; set; }
public long OrderId { get; set; }
}

public static class Loggit
{
public async static Task Write(ILogMessage message)
{
string log = "";
string path = "";
if (message is QueueLoggerPoint)
{
QueueLoggerPoint type = (QueueLoggerPoint)message;
log = string.Format(@"OrderId: {0} // Before Proc Time: {1}, After Proc Time: {2}",
type.OrderId, type.BeforeProcTime.ToString("hh:mm:ss.fff"), type.AfterProcTime.ToString("hh:mm:ss.fff"));
}
else
{
OrderLoggerPoint type = (OrderLoggerPoint)message;
log = string.Format(@"OrderId: {0} // Before Dequeue: {0}, After Send: {1}",
type.OrderId, type.BeforeDequeue.ToString("hh:mm:ss.fff"), type.AfterSend.ToString("hh:mm:ss.fff"));
path = Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "Log/send.txt");
}
using (StreamWriter sw = File.AppendText(path))
{
await sw.WriteLineAsync(log);
}
}
}


### Application

public class Application
{
public ActionBlock<ILogMessage> LogQueue { get; set; }

/// <summary>
/// Constructor
/// </summary>
public Application()
{
LogQueue = new ActionBlock<ILogMessage>(async (item) => { await Loggit.Write(item); },
new ExecutionDataflowBlockOptions { MaxDegreeOfParallelism = 1 });
}

/// <summary>
/// Task.Factory.StartNew(() => { QueueWorker(); });
/// </summary>
public void QueueWorker()
{
//Simulating the process inside these methods
while (runFlag)
{
foreach (var item in source)
{
QueueLoggerPoint point = new QueueLoggerPoint();
point.OrderId = item.OrderId;
point.BeforeProcTime = DateTime.UtcNow;

//Some process on item

point.AfterProctime = DateTime.UtcNow;
LogQueue.SendAsync(point);
}
}
}
/// <summary>
/// Task.Factory.StartNew(() => { OrderWorker(); });
/// </summary>
public void OrderWorker()
{
//Simulating the process inside these methods
while (runFlag)
{
OrderLoggerPoint point = new OrderLoggerPoint();
point.OrderId = item.OrderId;
point.BeforeDequeue = DateTime.UtcNow;
var item = MyQueue.Dequeue();

//Some process on item

SendItemToSomeWhere(item);
point.AfterSend = DateTime.UtcNow;
LogQueue.SendAsync(point);
}
}

}


Note: As the comments below deliberating Stopwatch, I realized that I need the exact timings when the runtime run where, rather than the time intervals of the code blocks, because I need to compare when an item insert into first thread then out then insert into second thread then out comparatively.

• As a general rule, DataTime.Now and friends are not going to precise enough for performance profiling; generally Stopwatch is your friend (though it won't give you much by way of sub-microsecond accuracy), but I've not had a hard look at your code. Commentary by Eric Lippert on this matter – VisualMelon Oct 27 '17 at 9:27
• this blog post and the references inside lead me to use DateTime.UtcNow rather than StopWatch if I read the chart right way :) – ibubi Oct 27 '17 at 9:43
• That's an interesting read! It says at the bottom "For precise time interval measurements we should be using System.Diagnostics.StopWatch which uses the high resolution timer (QueryPerformanceCounter). The resolution of both DateTime.Now and DateTime.UtcNow is very low – about 10 ms – this is a huge time interval!" which is what I'm referring to, but perhaps this isn't the main concern in your application. – VisualMelon Oct 27 '17 at 10:46
• It is related with my main concern indeed. I've just looked into charts in the blog post and quickly designed my code according to this, but I think it is wrong, I should use Stopwatch as you said. – ibubi Oct 27 '17 at 11:03
• This does not look like real code. There is no runFlag or source definition - thus -1 and vote-to-close-as-broken/not-written-code. – t3chb0t Nov 6 '17 at 4:53