While working on the BAF file project I learned a very interesting life lesson. See like most new computer science graduates I have worked on few actual projects, and quite frankly the few I have finished could not be considered corporation ready. While writing a few console applications, file parsers, corba interfaces, etc I learned a valuable lesson in documentation and log files. Log files can save your life if done correctly, and if you are really up to speed they can save many long hours of debuging too. In my case I fell in love with trace log messages. Trace logs are the log files that trace a programs execution so you can get a general idea of where your software is failing or producing an error. Now, most trace logs I have had the pleasure to work with are not quite where I wanted to be when I approached trace logs in my program. Most of the time they are a little more helpful then debug messages when trying to pinpoint an application’s problem. So when I faced the decision to add trace messages I decided to go all out.
My first logging framework was log4cplus, which is a very nice and complete logging framework for C++. I used it for one linux application I wrote and it works perfectly despite being several years old. Unfortunetly I was uncomfortable with how much work it took to write a message each new function ( two lines instead of one ) and it would not compile in windows so for my next application, bafprp, I set out to write my own.
When I completed the class I was left with one macro to print a log message depending on the level you wanted, ie, LOG_TRACE( string ), LOG_DEBUG( string ), etc. I then made sure I was adding trace messages to each and every function as I made them, instead of later on in the design. For example, an empty function would look like
void BafRecord::getType()
{
LOG_TRACE( "BafRecord::getType" );
LOG_TRACE( "/BafRecord::getType" );
return;
}
Each function would have a start and stop trace message.
Now this might raise an eyebrow or two but I assure you it definitely helps when your program crashes and you do not have a nice debugger on hand. Like say, if a non-technical user is using it.
This is how my linux application was programmed and I went the extra step in bafprp to work these in while I was working. Enough about this though, a short while ago, after adding one of the major structure types to the program my application slowed down from parsing a 12 meg file in 2 seconds to 2 minutes and I was greatly concerned over the well being of my design.
I tried many things, first I greatly reduced the number of memory copies my program executed, then I changed my file input so that it would read the entire file at the start and reference a data bank instead of reading the file each cycle. However none of these things put a dent in the processing time. So then I went online to try and find a nice and easy code profiler. Code profilers will basically watch your program execution and tell you which function your program is spending the most amount of time in. I ended up finding LTProf which allowed me to profile my program without recompiling or changing my program at all. I am actually very surprised at how well it works with compiled binaries. After running a release version of my program it was still able to accuratly determine function names and operate like it had a window into the source code.
I found that my time stamp function, NowTime, which returns the current time as a string, was taking a noticably large amount of my program’s time. Thinking back to what code uses this function I discovered the flaw.
When I wrote the log program I wrote the log level exception into the log class. This way if the program tried to log a trace message it would get sent to the output class, which would then pass it on to the logs if the level was at or below the log level type. However this was not enough. as it turns out simply creating the log message twice in each function had a substantial effect on the processing speed of my program.
Needless to say as soon as I moved the log level check to the macro the process speed dropped from 2 minutes to 30 seconds. Now some might say that trace logs this detailed are excessive, however I believe they can help greatly when dealing with a malfunctioning program. So as a final statement, be careful when you design systems, and beaware of how to use your tools. And if your program runs 3 times longer then a similar program, there is probably something horribly wrong.
