Framework Logging Performance

I have been working with my eScript logging framework for a couple of months now and it has been extremely helpful with debugging complicated script procedures. What keeps it from being truly useful in a production environment though is it is too damn slow. In an ideal world, I could leave logging on at all times, or at least for long periods of times for users or groups I want to keep track of. In order to do this, I need to make sure they do not notice a significant degradation in their work day.

The way the logging object functions work in the framework is basically to send one line at a time to the step function which then opens a file, writes the content along with a timestamp, and closes the file. It is these file operations that take the great majority of performance time. A given complicated script takes about 7 seconds with logging turned up to 5 which outputs a 63kb log file on my thick client. While I could expect server performance to be a bit faster, just turning logging off, reduces the performance time to under 2 seconds. What to do...

Buffer the output. It strikes me that I will do the exact same thing Siebel does with its own log files. Ever notice that the SQL Spool file or server log files are not always completely up to date with what you are executing in the GUI? This is because the application keeps a buffer of output and only writes the buffer when it is full. So I will do the same thing. I will store a new system parameter called 'Log Buffer' which will equal the number of lines to buffer. I will then create some new global variables to keep a running line count and one to buffer the output.

var giLogBuffer = Frame.GetSysPref("Log Buffer");
var giLogLines = 0;
var giLogCache = "";

All I have to do is modify my step function to leverage these values. Here is my step function again from the framework Log object with my mods:

step : function ( text, Lvl ) {
if (((Lvl == null)||(TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl))&&
 (giLogLines >= giLogBuffer)) {
  var fp = Clib.fopen(OutPutFileName, "a");
  Clib.fputs(giLogCache, fp);
  Clib.fputs(Frame.GetLocalTime()+" "+gsIndent + text + "\n", fp);
  Clib.fclose(fp);
  giLogLines = 0;
  giLogCache = "";
}
else {
  giLogLines++;
  giLogCache += Frame.GetLocalTime()+" "+gsIndent + text + "\n"
}
}

After setting the new buffer parameter to 20, performance improved drastically. My old 7 second run went down to 2 seconds. Could not even notice that logging was ramped up. My only concern is that things I really want to see don't appear in the log right away, like errors. So I need to modify the RaiseError function to artificially fill the buffer and force a log dump. Here is the new line I inserted (followed by the existing line):

giLogLines = giLogBuffer; //insure errors gets written to log file
Log.step("---End Function "+sFunction+"\n");

I would probably need to do something similar on the Application Close event. Not sure if user's hitting windows X will trigger this though. Something to think about.