Experience millisecond logging in WebObjects. HOW-TO

Hi Gang,

Here is a little HOW-TO I have put together on some logging topics.

Part I - direct action timing logging

We have wrapped our direct actions in some timing logging we have  
found very helpful. Our app needs to scale and does not have much  
state and and most things are handled in a direct action. This  
logging helps us figure out what is going on in production. We can  
determine what direct actions are slow/fast, see the uri for the  
direct action, and determine how the app is performing in general. It  
is really quite simple, but surprisingly helpful. Here is an example  
from our log files:

[2005-07-06 08:19:54.540] <WorkerThread2> START performActionNamed=  
productSearch, requestNumber= 2096
[2005-07-06 08:19:54.540] <WorkerThread2> START request().uri()= /cgi- 
bin/WebObjects/ShopToIt.woa/5/wa/products?catId=1000159&catCrumbIds
=1000006-1000159&topAttIds=1000336-1003440-1000294&sortBy=5&page=4 ,  
requestNumber= 2096
... more logging deleted ...
[2005-07-06 08:19:54.624] <WorkerThread2> END   performActionNamed=  
productSearch , requestNumber= 2096 , processing time= 84 ms

Here we have logged the start of the request ('START'), the direct  
action name, a request number, and the URI requested. Then the end of  
the direct action ('END') and the computed processing time to  
complete the direct action.

Further we can sort the log by processing time:

$ grep 'END ' LogFile.log |  sort -k13,14 -gnr | head

[2005-07-06 08:19:54.624] <WorkerThread2> END   performActionNamed=  
productSearch , requestNumber= 2096 , processing time= 843 ms
[2005-07-06 05:42:28.128] <WorkerThread1> END   performActionNamed=  
product , requestNumber= 1019 , processing time= 834 ms
[2005-07-06 04:37:00.221] <WorkerThread1> END   performActionNamed=  
products , requestNumber= 543 , processing time= 82 ms

or look at a specific request, note the URI we can pop into a browser  
to try it out:

$ grep 'requestNumber= 2096' LogFile.log
[2005-07-06 08:19:54.540] <WorkerThread2> START performActionNamed=  
productSearch, requestNumber= 2096
[2005-07-06 08:19:54.540] <WorkerThread2> START request().uri()= /cgi- 
bin/WebObjects/ShopToIt.woa/5/wa/products?catId=1000159&catCrumbIds
=1000006-1000159&topAttIds=1000336-1003440-1000294&sortBy=5&page=4 ,  
requestNumber= 2096
[2005-07-06 08:19:54.624] <WorkerThread2> END   performActionNamed=  
productSearch , requestNumber= 2096 , processing time= 84 ms

or see how the app is performing right now:

$ grep 'END ' LogFile.log | tail
[2005-07-06 14:50:20.798] <WorkerThread3> END   performActionNamed=  
category , requestNumber= 3827 , processing time= 40 ms
[2005-07-06 14:50:56.461] <WorkerThread0> END   performActionNamed=  
category , requestNumber= 3828 , processing time= 185 ms
[2005-07-06 14:51:40.912] <WorkerThread1> END   performActionNamed=  
products , requestNumber= 3829 , processing time= 144 ms
[2005-07-06 14:52:06.689] <WorkerThread2> END   performActionNamed=  
category , requestNumber= 3830 , processing time= 40 ms
[2005-07-06 14:52:16.003] <WorkerThread3> END   performActionNamed=  
category , requestNumber= 3831 , processing time= 40 ms
[2005-07-06 14:52:25.126] <WorkerThread0> END   performActionNamed=  
products , requestNumber= 3832 , processing time= 2938 ms
[2005-07-06 14:52:39.048] <WorkerThread1> END   performActionNamed=  
products , requestNumber= 3833 , processing time= 568 ms
[2005-07-06 14:53:06.515] <WorkerThread2> END   performActionNamed=  
product , requestNumber= 3834 , processing time= 53 ms
[2005-07-06 14:53:52.234] <WorkerThread3> END   performActionNamed=  
jumpTo , requestNumber= 3835 , processing time= 49 ms
[2005-07-06 14:53:58.637] <WorkerThread0> END   performActionNamed=  
products , requestNumber= 3836 , processing time= 74 ms


This is the code. We have wrapped the super.performActionNamed method  
with the logging.

public class SSDirectAction extends WODirectAction {
     private static int requestCount = 0;

     public WOActionResults performActionNamed(String actionName) {
         // start processing... log time stamp

         int localRequestCount = requestCount++;
         NSLog.out.appendln("START performActionNamed= " + actionName  
+ ", requestNumber= " + localRequestCount);
         NSLog.out.appendln("START request().uri()=    " + request 
().uri() + " , requestNumber= " +localRequestCount);

         ... dispatch your direct action ...
         super.performActionNamed(actionName);

         // done processing... log results

         // all the funny spaces are to allow excel to delimit the  
values by space into separate columns
         NSLog.out.appendln("END   performActionNamed= " + actionName  
+ " , requestNumber= " + localRequestCount + " ,
             processing time= " + (System.currentTimeMillis() -  
timeStamp) + " ms");
     }
}


Part II - Millisecond timestamps

You may have noticed in my examples we have millisecond timestamps on  
the log entries. How to do this is the topic of part 2. Millisecond  
logging helps us examine our db queries with more precision. For  
example:

[2005-07-06 05:25:16.646] <WorkerThread1>  evaluateExpression:  
<com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression:  
"SELECT t0."
CITY_NAME", t0."COUNTRY_CODE", t0."COUNTRY_ID", t0."LATITUDE",  
t0."LOCATION_ID", t0."LONGITUDE", t0."POSTAL_CODE",  
t0."PROVINCE_CODE", t0."P
ROVINCE_ID", t0."PROVINCE_NAME" FROM "LOCATION" t0 WHERE  
t0."POSTAL_CODE" = 'V3H 2E3'">
[2005-07-06 05:25:16.719] <WorkerThread1> 1 row(s) processed

73 ms to fetch 1 row?

Apple's doc on this subject is a bit vague ( and incomplete with  
errors!) but I have put together something that works. You are  
welcome to use it, but the risk is all yours of course!

There are two parts, creating a new logger and installing the logger.  
First here is the class to do the logging:

/**
* @author janger - Jun 23, 2005
* This class provides a replacement for the default logging class in  
order to provide millisecond time intervals.
*/
public class CSPrintStreamLogger extends PrintStreamLogger {
     // the format for the time stamp in the log
     private NSTimestampFormatter gdf = new NSTimestampFormatter("%Y-% 
m-%d %H:%M:%S.%F");

     /**
      * The constructor implies you are setting the printStream  
elsewhere. Check this if the log is empty.
      * @author janger - Jun 23, 2005
      *
      */
     public CSPrintStreamLogger() {
         super();
     }

     /**
      * Main constructor.
      * @author janger - Jun 23, 2005
      * @param printStream
      */
     public CSPrintStreamLogger(PrintStream printStream) {
         super(printStream);
     }

     /**
      * prints a blank line
      * @author janger - Jun 23, 2005
      * @see com.webobjects.foundation.NSLog.Logger#appendln()
      */
     public synchronized void appendln() {
         printStream().println();
     }

     /**
      * prints a log entry with millisecond accuracy
      * @author janger - Jun 23, 2005
      * @see com.webobjects.foundation.NSLog.Logger#appendln 
(java.lang.Object)
      */
     public synchronized void appendln(Object arg0) {
         printStream().println("[" + gdf.format(new NSTimestamp()) +  
"] <" + Thread.currentThread().getName() + "> " + arg0);

     }

     /**
      * flushes the print stream? apple's doc on this is vague. This  
is implemented because we are told we have to in the doc.
      * @author janger - Jun 23, 2005
      * @see com.webobjects.foundation.NSLog.Logger#flush()
      */
     public void flush() {
         super.flush();
     }
}

Second here is how to install the new logger:

     /**
      * Redirects log files to locations specified by OUTPUT_LOG_FILE  
and ERROR_LOG_FILE properties and adds millisecond precision to  
logging timestamps. Millisecond precision is nice for examining sql  
query times.
      * @author john anger, [email protected] - Jun 24, 2005
      */
     public static void setupLogging() {
         CSPrintStreamLogger outLogger = new CSPrintStreamLogger 
(System.out);
         String out_log_filename = NSProperties.getProperty 
("OUTPUT_LOG_FILE", null);

         // sends debug and out messages to the log file if  
specified, System.out otherwise
         if (null != out_log_filename) {
             NSLog.out.appendln("Redirecting output and debug logging  
to " + out_log_filename);
             // New print stream based on path.
             PrintStream aStream = NSLog.printStreamForPath 
(out_log_filename);
             outLogger = new CSPrintStreamLogger(aStream);
         }

         outLogger.setIsVerbose(true);
         outLogger.setIsEnabled(true);

         NSLog.setOut(outLogger);
         NSLog.out.setAllowedDebugLevel(NSLog.DebugLevelDetailed);
         NSLog.setDebug(outLogger, NSLog.DebugLevelDetailed);

         // sends error messages to error file if specified,  
System.err otherwise
         PrintStream errStream = System.err;
         String err_log_filename = NSProperties.getProperty 
("ERROR_LOG_FILE", null);

         if (null != err_log_filename) {
             NSLog.err.appendln("Redirecting error logging to " +  
err_log_filename);
             // New print stream based on path.
              errStream = NSLog.printStreamForPath(err_log_filename);
         }
         CSPrintStreamLogger errLogger = new CSPrintStreamLogger 
(errStream);
         NSLog.setErr(errLogger);
         NSLog.err.setIsVerbose(true);
         NSLog.err.setAllowedDebugLevel(NSLog.DebugLevelDetailed);

         System.out.println("NSLog.out.allowedDebugLevel()=" +  
NSLog.out.allowedDebugLevel());
         System.out.println("NSLog.debug.allowedDebugLevel()=" +  
NSLog.debug.allowedDebugLevel());
         System.out.println("NSLog.err.allowedDebugLevel()=" +  
NSLog.err.allowedDebugLevel());
     }

Call the setupLogging() method from somewhere in your setup code and  
that should be about all you have to do. When we are developing we  
set the OUTPUT_LOG_FILE and ERROR_LOG_FILE properties to save our log  
files outside of the eclipse console since we find eclipse handles  
big logs so slowly. In production it just defaults to the expected  
log files. Some of us here at ClickSpace use Apple's console  
application to view the logs, it is nice but it tends to hog memory.  
You may also want to adjust the setIsVerbose flags in setupLogging().  
I have everything cranked up here.

Enjoy!
John & Gang at http://www.ClickSpace.com and http://www.shoptoit.com