Have you ever wondered what is going on with the client requests sent to a Sling based application and what Sling is doing in the background so that you can worry about your primary job, the Web based application you are building? Have you been tasked to find out, why your latest super Web based application suffers from performance degradation from time to time?

In case you are tempted to answer the above questions with a firm yes I think you will be happy to hear that the days of implementing a tracker over and over again in each new project has gone. With Sling you get a tracker for request processing for free and out of the box: The RequestProgressTracker.

Sling creates such a RequestProgressTracker instance for each request being processed and also uses it to track various processing steps like resource and servlet/script resolution. You may add your own logging and tracking to this instance and at the end of the request dump it either into your HTML response or have it written to the log file or to a real filesystem file 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 question to answer. These are the API methods of the RequestProgressTracker:

• Logging simple and formatted messages. This is mainly used to mark some state during request processing. A message added to the internal log of messages together with a time stamp.
• Timing sections of request processing. Timing parts of request processing consists of two steps: First you start a (named) timer before the part to be timed 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 want to add the request progress information to your generated HTML page as an HTML comment, for example.

Show Me an Example

Let's go. Let us explore a very simple example of just dumping the contents of the tracker. First launch Sling - this can be as easy as just running the Sling Standaline Application you get from the Apache Sling Downloads page.

After downloading and unpacking the Sling Standalone application, open a command shell and change to the directory of the unpacked org.apache.sling.launchpad.app-3-incubator.jar file and launch it with:

$ java -jar org.apache.sling.launchpad.app-3-incubator.jar -p 8888 -f -

The argument "-p 8888" instructs Sling to listen on port 8888. You may change 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 is very convenient for development. By default log messages go to the logs/error.log file in the Sling Home directory (sling by default). To get a list and short explanation on available command line options, use the parameter "-h".

Next connect Sling using WebDAV and create a folder /apps/sling/nonexisting and in that folder create a file GET.esp with the following contents:

<%
response.setContentType("text/plain");
response.setCharacterEncoding("UTF-8");

request.requestProgressTracker.dump(response.writer);
%>

Now in your browser request a resource which you know is not existing. For example in 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 the author):

 1:      0 (2008-06-18 10:18:26) Starting Request Processing
 2:      0 (2008-06-18 10:18:26) Starting ResourceResolution
 3:      0 (2008-06-18 10:18:26) URI=/missing.txt resolves to Resource=NonExistingResource, path=/missing.txt, elapsed = 0ms
 4:      0 (2008-06-18 10:18:26) Starting ServletResolution
 5:      0 (2008-06-18 10:18:26) Starting resolverServlet(NonExistingResource, path=/missing.txt)
 6:      5 (2008-06-18 10:18:26) Using Servlet /apps/sling/nonexisting/GET.esp, elapsed = 5ms
 7:      5 (2008-06-18 10:18:26) URI=/missing.txt handled by Servlet=Script /apps/sling/nonexisting/GET.esp, elapsed = 5ms
 8:      5 (2008-06-18 10:18:26) Starting /apps/sling/nonexisting/GET.esp#0
 9:     13 (2008-06-18 10:18:26) Dumping SlingRequestProgressTracker Entries, elapsed = 13ms

As you can see from this simple dump resolving the addressed resource took an unmeasurable amount of time (0 milliseconds, line 3). Next you see, that resolution of the script took another 5 milliseconds (line 7) and finally running the script from the point of the call upto the point of requesting the dump used 8 milliseconds.

Further you see normal log entries like the one on line 9 and timer related messages on the other lines: Lines 1, 2, 4, 5 and 8 marking timer starts and the other lines 3, 6 and 7 marking timing points.

You may notice that the timer "/apps/sling/nonexisting/GET.esp#0" is only dumped when started but not when terminated. The reason for this is of course, that the timer is only logged when the script has finished but we dump the log before the script has terminated. Hence this log entry has not been added yet.

This example also shows you nicely how resource resolution and script resolution work hand-in-hand: The request to /missing.txt could not be resolved to an actual JCR Node, so the resource resolver created a so-called NonExistingResource 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 the resource sling:nonexisting type has been converted to the (relative) path sling/nonexisting which is then used for the script resolution.

Log Dump Method

• dump(PrintWriter writer) -- Write all log messages to the given java.io.PrintWriter.

Logging Your Own Entries

The first example above contained only messages added by Sling itself, lets add some messages of our own now into the log. To this avail we change the GET.esp script as follows:

<%
request.requestProgressTracker.log("Starting Script Execution");

request.requestProgressTracker.log("Script {0} of type {1}",
        sling.script.scriptResource.path,
        sling.script.scriptResource.getResourceType());


response.setContentType("text/plain");
response.setCharacterEncoding("UTF-8");

request.requestProgressTracker.log("End Of Script Execution");

request.requestProgressTracker.dump(response.writer);
%>

We added three logging statements: Two statements with a fixed message and a third statement with a java.text.MessageFormat format string and its associated parameters. The output of this script when requesting the /missing.txt resource again is as follows (line numbers added by the author):

 1:      0 (2008-06-18 10:22:28) Starting Request Processing
 2:      0 (2008-06-18 10:22:28) Starting ResourceResolution
 3:      1 (2008-06-18 10:22:28) URI=/missing.txt resolves to Resource=NonExistingResource, path=/missing.txt, elapsed = 1ms
 4:      1 (2008-06-18 10:22:28) Starting ServletResolution
 5:      1 (2008-06-18 10:22:28) Starting resolverServlet(NonExistingResource, path=/missing.txt)
 6:      4 (2008-06-18 10:22:28) Using Servlet /apps/sling/nonexisting/GET.esp, elapsed = 3ms
 7:      4 (2008-06-18 10:22:28) URI=/missing.txt handled by Servlet=Script /apps/sling/nonexisting/GET.esp, elapsed = 3ms
 8:      4 (2008-06-18 10:22:28) Starting /apps/sling/nonexisting/GET.esp#0
 9:     13 (2008-06-18 10:22:28) Starting Script Execution
10:     13 (2008-06-18 10:22:28) Script /apps/sling/nonexisting/GET.esp of type nt:file
11:     13 (2008-06-18 10:22:28) End Of Script Execution
12:     13 (2008-06-18 10:22:28) Dumping SlingRequestProgressTracker Entries, elapsed = 13ms

You will see the three log statements we added in the lines 9-11. Note especially the message on line 10, which formats the message by replacing the respective call parameters.

Logging Methods

• log(String message) -- Log this exact message
• log(String format, Object... args) -- Log a message which is constructed from applying the arguments args to the java.text.MessageFormat pattern format.

Timing Sections of the Script

Sometimes you might suspect timing issues in the scripts you have written and you want to see where all these CPU cycles are being burnt. Here comes the timer support the ResourceProgressTracker. The tracker allows for a virtually unlimited number of named timers. A timer is created or reset by calling the startTimer(String) method and the time ellapsed since the last timer start can be logged by calling any of the logTimer methods.

Let's see the timer functionality in action. Thus we adapt our GET.esp to add a timer:

<%
request.requestProgressTracker.startTimer("test");

request.requestProgressTracker.log("Script {0} of type {1}",
        sling.script.scriptResource.path,
        sling.script.scriptResource.getResourceType());


response.setContentType("text/plain");
response.setCharacterEncoding("UTF-8");

request.requestProgressTracker.logTimer("test");

request.requestProgressTracker.dump(response.writer);
%>

Here we define a timer named test and get the following output (line numbers added by the author):

 1:      0 (2008-06-18 11:11:39) Starting Request Processing
 2:      0 (2008-06-18 11:11:39) Starting ResourceResolution
 3:      1 (2008-06-18 11:11:39) URI=/missing.txt resolves to Resource=NonExistingResource, path=/missing.txt, elapsed = 1ms
 4:      1 (2008-06-18 11:11:39) Starting ServletResolution
 5:      1 (2008-06-18 11:11:39) Starting resolverServlet(NonExistingResource, path=/missing.txt)
 6:      5 (2008-06-18 11:11:39) Using Servlet /apps/sling/nonexisting/GET.esp, elapsed = 4ms
 7:      6 (2008-06-18 11:11:39) URI=/missing.txt handled by Servlet=Script /apps/sling/nonexisting/GET.esp, elapsed = 5ms
 8:      6 (2008-06-18 11:11:39) Starting /apps/sling/nonexisting/GET.esp#0
 9:     12 (2008-06-18 11:11:39) Starting test
10:     13 (2008-06-18 11:11:39) Script /apps/sling/nonexisting/GET.esp of type nt:file
11:     13 (2008-06-18 11:11:39) test, elapsed = 1ms
12:     13 (2008-06-18 11:11:39) Dumping SlingRequestProgressTracker Entries, elapsed = 13ms

In the dumped log you find the entry for the timer start in line 9 and the entry for logging the elapsed time of the named timer in line 11. In our example we used the simple method of logging by just supplying the timer name to the logTimer(String) method. You may log a more elaborate message with the logTimer(String, String, Object...) method, which is also used by Sling to log timings for the resource and script resolution

Timer Methods

• startTimer(String timerName) -- Start a timer with the given name. If a timer with the same name already exists it is reset to zero.
• logTimer(String timerName) -- Logs the number of milliseconds elapsed since the named timer was last started. The name of the timer is used as the log message.
• logTimer(String timerName, String format, Object... args) -- Logs the number of milliseconds elapsed since the named timer was last started with a message constructed by applying the args parameters to the MessageFormat pattern format.

Please note that only the startTimer method resets the timer to zero. The logTimer methods just log the number of milliseconds elapsed. Therefore these latter methods may also be called multiple times to log the increase of elapsed time.

Wrap-Up

In the previous sections you have seen how easy it is to use the RequestProgressTracker provided by Sling to track the processing of any requests. In this wrap-up I want to present three more bullet points with respect to the request progress tracker.

Helper Methods

• getMessages() -- Return all messages from the request progress tracker as an java.util.Iterator of Strings. This method may be used if you want to handle the logged messages other than just dumping them to some PrintWriter.
• done() -- This may be called to log a terminating message. Currently this method has no other effect.

Automatic Logging of Messages

Sling includes a request filter, which dumps the request progress tracker to using a logger with name org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter at debug level. To log the request progress tracker messages to a log file just configure this logger for the debug log level.

• Print version

  Printer-friendly version

• Recent Discussions

• PlanetDay

  The latest posts on PlanetDay

• Links on Daigg