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:
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:
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):
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:
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):
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 messagelog(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:
Here we define a timer named test and get the following output (line
numbers added by the author):
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.
