Have you ever wondered what is going on with the client requests sent toa Sling based application and what Sling is doing in the background so thatyou can worry about your primary job, the Web based application you arebuilding? Have you been tasked to find out, why your latest super Web basedapplication suffers from performance degradation from time to time?
In case you are tempted to answer the above questions with a firm yes Ithink you will be happy to hear that the days of implementing a tracker overand over again in each new project has gone. With Sling you get a trackerfor request processing for free and out of the box: The RequestProgressTracker.
Sling creates such a RequestProgressTracker instance for eachrequest being processed and also uses it to track various processing stepslike resource and servlet/script resolution. You may add your own logging andtracking to this instance and at the end of the request dump it either intoyour HTML response or have it written to the log file or to a real filesystemfile or to the JCR repository or wherever you like.
Functionality of the RequestProgressTracker
First things first: What can we do with this tracker ? This is a simple questionto answer. These are the API methods of the RequestProgressTracker:
- Logging simple and formatted messages. This is mainly used to mark some stateduring request processing. A message added to the internal log of messagestogether with a time stamp.
- Timing sections of request processing. Timing parts of request processingconsists of two steps: First you start a (named) timer before the part to betimed and after that part you log the timer by the same name.
- Get all messages. If you want to process the logged messages yourself, e.g.to write them to a file or the JCR repository.
- Dump all messages to a
java.io.PrintWriter. If you just wantto add the request progress information to your generated HTML page as anHTML comment, for example.
Show Me an Example
Let's go. Let us explore a very simple example of just dumping the contentsof the tracker. First launch Sling - this can be as easy as just runningthe Sling Standaline Application you get from the Apache SlingDownloadspage.
After downloading and unpacking the Sling Standalone application, open a commandshell and change to the directory of the unpackedorg.apache.sling.launchpad.app-3-incubator.jar file and launchit with:
The argument "-p 8888" instructs Sling to listen on port 8888. You maychange this to any free port you like. The default port is 8080. The argument"-f -" causes log messages to be written to the standard output. This isvery convenient for development. By default log messages go to thelogs/error.log file in the Sling Home directory (sling by default). Toget a list and short explanation on available command line options, use theparameter "-h".
Next connect Sling using WebDAV and create a folder /apps/sling/nonexistingand in that folder create a file GET.esp with the followingcontents:
Now in your browser request a resource which you know is not existing. For examplein a fresh installation of Sling, there is no resource at /missing.txt.So requesting that will give you the following response (line numbers added by theauthor):
As you can see from this simple dump resolving the addressed resource tookan unmeasurable amount of time (0 milliseconds, line 3). Next you see, thatresolution of the script took another 5 milliseconds (line 7) and finallyrunning the script from the point of the call upto the point of requesting thedump used 8 milliseconds.
Further you see normal log entries like the one on line 9 and timer relatedmessages on the other lines: Lines 1, 2, 4, 5 and 8 marking timer starts and theother lines 3, 6 and 7 marking timing points.
You may notice that the timer "/apps/sling/nonexisting/GET.esp#0" is only dumpedwhen started but not when terminated. The reason for this is of course, thatthe timer is only logged when the script has finished but we dump the log beforethe script has terminated. Hence this log entry has not been added yet.
This example also shows you nicely how resource resolution and script resolutionwork hand-in-hand: The request to /missing.txt could not be resolvedto an actual JCR Node, so the resource resolver created a so-calledNonExistingResource whose resource type is set to sling:nonexisting.This resource type is then used to resolve the script /apps/sling/nonexisting/GET.esp. As you can see theresource sling:nonexisting type has been converted to the (relative) pathsling/nonexisting which is then used for the script resolution.
Log Dump Method
dump(PrintWriter writer) -- Write all log messages to thegiven java.io.PrintWriter.
Logging Your Own Entries
The first example above contained only messages added by Sling itself, lets addsome messages of our own now into the log. To this avail we change theGET.esp script as follows:
We added three logging statements: Two statements with a fixed message and athird statement with a java.text.MessageFormat format string andits associated parameters. The output of this script when requesting the/missing.txt resource again is as follows (line numbers added by theauthor):
You will see the three log statements we added in the lines 9-11. Note especiallythe message on line 10, which formats the message by replacing the respectivecall parameters.
Logging Methods
log(String message) -- Log this exact message
log(String format, Object... args) -- Log a message whichis constructed from applying the arguments args to thejava.text.MessageFormat pattern format.
Timing Sections of the Script
Sometimes you might suspect timing issues in the scripts you have written andyou want to see where all these CPU cycles are being burnt. Here comes thetimer support the ResourceProgressTracker. The tracker allowsfor a virtually unlimited number of named timers. A timer is created or resetby calling the startTimer(String) method and the time ellapsed sincethe last timer start can be logged by calling any of the logTimermethods.
Let's see the timer functionality in action. Thus we adapt our GET.espto add a timer:
Here we define a timer named test and get the following output (linenumbers added by the author):
In the dumped log you find the entry for the timer start in line 9 and the entryfor logging the elapsed time of the named timer in line 11. In our example weused the simple method of logging by just supplying the timer name to thelogTimer(String) method. You may log a more elaborate message withthe logTimer(String, String, Object...) method, which is alsoused by Sling to log timings for the resource and script resolution
Timer Methods
startTimer(String timerName) -- Start a timer with thegiven name. If a timer with the same name already exists it is reset to zero.
logTimer(String timerName) -- Logs the number ofmilliseconds elapsed since the named timer was last started. The name of thetimer is used as the log message.
logTimer(String timerName, String format, Object... args)-- Logs the number of milliseconds elapsed since the named timer was laststarted with a message constructed by applying the args parametersto the MessageFormat pattern format.
Please note that only the startTimer method resets the timer tozero. The logTimer methods just log the number of millisecondselapsed. Therefore these latter methods may also be called multiple times tolog the increase of elapsed time.
Wrap-Up
In the previous sections you have seen how easy it is to use theRequestProgressTracker provided by Sling to track the processingof any requests. In this wrap-up I want to present three more bullet pointswith respect to the request progress tracker.
Helper Methods
getMessages() -- Return all messages from the requestprogress tracker as an java.util.Iterator of Strings. This methodmay be used if you want to handle the logged messages other than just dumpingthem to some PrintWriter.
done() -- This may be called to log a terminatingmessage. Currently this method has no other effect.
Automatic Logging of Messages
Sling includes a request filter, which dumps the request progress trackerto using a logger with name org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilterat debug level. To log the request progress tracker messages to a log filejust configure this logger for the debug log level.