Introduction
I needed a class to very quickly log lines of text to a file in a multi threaded application. In addition, I needed to record the exact time of the log (accurate to 1 micro second) in the log file.
The recording needs to be very fast so the text to be written is placed on a queue and is written to disc on another worker thread, hence even busy disc performance does not slow the important recording thread. Minimal locks keep the record to queue operation as fast as possible.
DateTime.Now
returns a time accurate to only about 20ms. To get better accuracy, this code uses the High Performance Timer and adjusts the tick count to match up with the DateTime
. This is done by building a small table recording the HP Ticks and DateTime
Ticks after sleep operations, and then using linear interpolation to calculate the DateTime
at the record time. The table building and interpolation take place on the non critical worker thread. Recording DateTime
after sleep operations gives a DateTime
that corresponds to the actual time with minimal inaccuracy (see other articles about accurate clock times in the Windows OS).
This method of calling only QueryPerformanceCounter
and then converting this long to an accurate date time string
on the non critical thread gives the best possible performance. The times will always be increasing even for small changes in DateTime
(e.g. NTP clock adjustments) because any adjustment in the clock is spread out over the sleep time. The HP counter rolls every 90 years or at reboot hence no check for that.
Performance on my machine - a thread looping continuously can log every 2 micro seconds. This code is fully tested and used in production on my 4 processor box.
using System;
using System.Threading;
using System.Collections;
using System.IO;
using System.Runtime.InteropServices;
public class FastFileWriter
{
private class Item
{
public long time=0;
public string text;
}
private int qActive;
private Queue[] q = new Queue[3];
private int timePosition;
private int timeSearchBelow, timeSearchAbove;
private long[,] timeArray=new long[5,2];
private StreamWriter outfile;
private Thread thread;
[DllImport("kernel32.dll")]
static extern int QueryPerformanceCounter(ref long x);
public FastFileWriter(string filename, bool append)
{
try { outfile = new StreamWriter(filename, append); }
catch { throw new Exception("Could not open the log file: "+filename); }
qActive=0;
q[0]=new Queue();
q[1]=new Queue();
q[2]=new Queue();
timePosition=0;
timeSearchBelow=0; timeSearchAbove=1;
timeArray[timePosition,0]=0;
Thread.Sleep(50);
QueryPerformanceCounter(ref timeArray[timePosition,0]);
timeArray[timePosition,1]=DateTime.Now.Ticks;
timePosition++;
thread = new Thread(new ThreadStart(this.Run));
thread.Start();
}
public void Write(string s)
{
Item item=new Item();
item.text=s;
lock(this)
{
QueryPerformanceCounter(ref item.time);
q[qActive].Enqueue(item);
}
}
private void Run()
{
while (true)
{
Thread.Sleep(10000);
QueryPerformanceCounter(ref timeArray[timePosition,0]);
timeArray[timePosition,1]=DateTime.Now.Ticks;
timePosition++;
Write("");
lock(this)
{
if (++qActive>2) qActive=0; }
Queue qOld; if (qActive>=2) qOld=q[0]; else qOld=q[qActive+1];
Flush(qOld);
CleanUpTimeArray();
}
}
private void Flush(Queue qOld)
{
while ( qOld.Count > 0 )
{
Item item= (Item) qOld.Dequeue();
DateTime t=new DateTime( GetDateTime( item.time ) );
if (item.text!="") outfile.WriteLine( t.ToString
("yyyy-MM-dd HH:mm:ss.ffffff") +"|"+item.text );
}
outfile.Flush();
}
private long GetDateTime(long tHP)
{
while (true)
{
if (tHP>=timeArray[timeSearchBelow,0] && tHP<=timeArray[timeSearchAbove,0])
{
double diff_tHP= tHP-timeArray[timeSearchBelow,0];
double diff_HPHP= timeArray[timeSearchAbove,0]-
timeArray[timeSearchBelow,0];
double diff_DTDT= timeArray[timeSearchAbove,1]-
timeArray[timeSearchBelow,1];
long offset= Convert.ToInt64(diff_tHP*diff_DTDT/diff_HPHP);
return offset+timeArray[timeSearchBelow,1];
}
else
{
if ( tHP>timeArray[timeSearchAbove,0])
{
timeSearchBelow=timeSearchAbove;
timeSearchAbove++;
}
else
{
timeSearchAbove=timeSearchBelow;
timeSearchBelow--;
}
}
}
}
private void CleanUpTimeArray()
{
while (true)
{
if (timeSearchBelow>0)
{
for (int i=1; i<timePosition; i++)
{
timeArray[i-1,0]=timeArray[i,0];
timeArray[i-1,1]=timeArray[i,1];
}
timeSearchBelow--;
timeSearchAbove--;
timePosition--;
}
else
{
return;
}
}
}
public void Dispose()
{
thread.Abort();
lock (this)
{
Thread.Sleep(50);
QueryPerformanceCounter(ref timeArray[timePosition,0]);
timeArray[timePosition,1]=DateTime.Now.Ticks;
Flush(q[0]);
Flush(q[1]);
Flush(q[2]);
}
outfile.Close();
}
}