Click here to Skip to main content
15,867,453 members
Articles / Programming Languages / C#
Article

Logging Class with QueryPerformanceCounter

Rate me:
Please Sign up or sign in to vote.
2.76/5 (14 votes)
24 May 2006CPOL1 min read 51.7K   129   26   12
Logging class with high performance timer and background thread Synchronise Sleep

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.

C#
using System; 
using System.Threading;
using System.Collections;
using System.IO;
using System.Runtime.InteropServices;
public class FastFileWriter
{
    private class Item
    { // class for holding data items on the write queues
        public long time=0; // This is the High Performance Timer time
        public string text; // This is the line of text to write to the file
    }
private int qActive; // three write queues for incoming data
private Queue[] q = new Queue[3];
private int timePosition; // an array of HP Timer Tick vs DateTime Ticks at sync points
private int timeSearchBelow, timeSearchAbove; // which we search at file 
                                              // write time in order 
private long[,] timeArray=new long[5,2]; // to assign a DateTime to any given HP time
private StreamWriter outfile; // The file we write to
private Thread thread; // The thread on which we write to the file
[DllImport("kernel32.dll")] // The High Performance Timer System Call
static extern int QueryPerformanceCounter(ref long x);
public FastFileWriter(string filename, bool append)
{
    // create the outfile, exception on error
    try { outfile = new StreamWriter(filename, append); }
    catch { throw new Exception("Could not open the log file: "+filename); }
    // setup our queues
    qActive=0;
    q[0]=new Queue();
    q[1]=new Queue();
    q[2]=new Queue();
    // fill in the first point in the timerArray
    // timeArray[0,0] is the HP Timer ticks
    // timeArray[0,1] is the corresponding DateTime ticks
    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) // Fast Write safe for multi threaded calls
{
    Item item=new Item();
    item.text=s;
    lock(this) // here we need a lock... 
    {
        QueryPerformanceCounter(ref item.time); //move outside if you run 4 queues
        q[qActive].Enqueue(item); 
    }
}
private void Run() // The worker thread which writes to the file
{
    while (true)
    {
        Thread.Sleep(10000); // Change this to 100 seconds (100000) or as desired
        // sync time
        QueryPerformanceCounter(ref timeArray[timePosition,0]); // read this first 
                                                          //because it changes quickly
        timeArray[timePosition,1]=DateTime.Now.Ticks; // read this seconds because it 
                                                      // only changes slowly
        timePosition++;
        // write a dummy to the queue so it's never completely empty
        Write(""); // so even if no data arrives for a long time the 
                    // timerArray does not fill up
        // swap incoming messages to the next queue
        lock(this) // here we need a lock... but it's just over one line of code
        { 
	   if (++qActive>2) qActive=0; }
	   // flush the oldest queue
	   Queue qOld; if (qActive>=2) qOld=q[0]; else qOld=q[qActive+1];
	   Flush(qOld);
	   // clean up the timerArray list by deleting old times from the bottom
	   // note time in other queues will all be > the last time read
	   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)
    { 
        // reads the timeArray to find the DateTime.Ticks at the given HPC time
        // there must always be a higher and lower entry in the timerArray or 
        // this code will crash
        // it's for this reason that we need to maintain three write queues
        while (true)
        {
            if (tHP>=timeArray[timeSearchBelow,0] && tHP<=timeArray[timeSearchAbove,0])
            { // the enquired time is between timeSearchBelow and timeSearchAbove
                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
            { // need to change timeSearchBelow and timeSearchAbove
                if ( tHP>timeArray[timeSearchAbove,0])
                { // move up
                    timeSearchBelow=timeSearchAbove;
                    timeSearchAbove++; // will crash out of bounds if no higher entry
                }
                else
                { // move down
                    timeSearchAbove=timeSearchBelow; 
                    timeSearchBelow--; // will crash out of bounds if no lower entry
                }
            }
        }
    }
    private void CleanUpTimeArray()
    {
        while (true)
        {
            if (timeSearchBelow>0)
            { // if timeSearchBelow>0 then shift all the subsequent entries down
                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()
    { // Call to flush all the queues and end the worker thread
        thread.Abort();
        lock (this)
        { // Lock in case someone tries to write after calling dispose
            Thread.Sleep(50);
            // sync time
            QueryPerformanceCounter(ref timeArray[timePosition,0]); 
            timeArray[timePosition,1]=DateTime.Now.Ticks; 
            // Flush all the queues
            Flush(q[0]);
 	   Flush(q[1]);
 	   Flush(q[2]);
       }
       // Close File
       outfile.Close();
    }
}

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)



Comments and Discussions

 
GeneralBetter way... Pin
w.hooper15-Apr-09 22:51
w.hooper15-Apr-09 22:51 
GeneralSomething to keep in mind... Pin
Stonie19-Dec-06 15:14
Stonie19-Dec-06 15:14 
If you thinking of implementing this you should also keep in mind that CPUs that feature speed step, can make the results of QueryPerformanceCounter() unreliable.

There might be way around it, but you will need to do your research. Wink | ;)

Generalwrite frequency Pin
cduced13-Jul-06 4:35
cduced13-Jul-06 4:35 
GeneralRe: write frequency Pin
w.hooper13-Jul-06 5:07
w.hooper13-Jul-06 5:07 
GeneralMissing ")" Pin
cduced24-May-06 6:44
cduced24-May-06 6:44 
NewsUnsafe for Multiple or hyperthreaded CPUs Pin
TekCat23-May-06 9:41
TekCat23-May-06 9:41 
GeneralRe: Unsafe for Multiple or hyperthreaded CPUs [modified] Pin
w.hooper23-May-06 19:20
w.hooper23-May-06 19:20 
GeneralRe: Unsafe for Multiple or hyperthreaded CPUs [modified] Pin
TekCat24-May-06 5:01
TekCat24-May-06 5:01 
GeneralRe: Unsafe for Multiple or hyperthreaded CPUs [modified] Pin
w.hooper24-May-06 21:32
w.hooper24-May-06 21:32 
GeneralRe: Unsafe for Multiple or hyperthreaded CPUs [modified] Pin
Scope25-May-06 4:10
Scope25-May-06 4:10 
GeneralRe: Unsafe for Multiple or hyperthreaded CPUs [modified] Pin
TekCat29-May-06 10:25
TekCat29-May-06 10:25 
GeneralGreat article Pin
hillgoat19-May-06 8:21
hillgoat19-May-06 8:21 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.