Programmer's Guide
Optimizing Web Applications

Using method timing

A sensible strategy for improving the performance of an application involves identifying the areas in the application that use the largest percentage of execution time. By optimizing the most severe bottlenecks, you can often realize a substantial improvement in overall application performance.

JRun provides a method timing feature for measuring performance of individual methods within a servlet. You can measure execution times for methods that you create, as well as for the methods in EJBs, third-party libraries, and helper classes.

How method timing works

You configure how method timing monitors your application by specifying values for timing parameters in the InstrumentationService in the SERVER-INF/jrun.xml file.

The method timing feature provides two levels of method timing:

• Current method timing  Monitors the execution of methods that are part of the application.
• Method call timing  Also called invoked method timing. Monitors the execution of methods called within application methods.

The general strategy for detecting performance problems in methods is to run the application twice, using different settings for method timing:

• The first time, using current method timing, generate execution statistics for all methods that are part of the application. The result of this pass is to isolate methods that require large amounts of execution time.
• The second time, using method call timing, generate execution statistics for methods called by the methods identified by the first pass. Using the results from this pass, you should be able to determine where the bottlenecks occur.

For example, a servlet's doGet method calls another method:

public void doGet {

...
  ...xyz()...
...
}

Current method timing of the doGet method generates the execution time required by the method, which includes the time required by the call to method xyz. Method call timing generates the execution time required by method xyz. The results should indicate whether the execution time is primarily within the doGet method or specifically in method xyz.

Configuring method timing

Method timing is controlled through the MethodInstrumentor service, defined in the jrun.xml file. This service lets you specify the following:

• Classes to exclude  Controlled by the excludeCallsTo attribute. By default, methods in the java.*, javax.*, and sun.* packages are not timed.
• Classes containing methods to be timed  Controlled by the className attribute.
• Whether to time direct subclasses  Controlled by the directSubclasses attribute. This is useful for classes, such as javax.servlet.http.HttpServlet, which are commonly extended to define a servlet.
• Enable current method timing  Controlled by the instrumentMethods attribute. Specify true or false.
• Specify the methods to time  Controlled by the instrumentMethod attribute. Specify method names using as many lines of instrumentMethod attributes as necessary; specify an asterisk (*) to time all methods.
• Enable method call timing  Controlled by the instrumentCalls attribute. Specify true or false.
• Specify the method calls to time  Controlled by the instrumentCallsTo attribute. Specify method names using as many lines of instrumentCallsTo attributes as necessary; specify an asterisk (*) to time all method calls.
• Output options  Controlled by the outputToStandardLogger and outputToRequestThread attributes. Specify true or false.

Printing instrumentation details to the output

The JRun logger processes performance output. By default, JRun writes output to a log file, but you can direct the output to the client or to another file by configuring the LoggerService mechanism in the jrun.xml file.

Viewing execution times

JRun includes the JRunTimingFilter that collects statistics about the execution times of the methods defined in the InstrumentationService for output to the web. The JRunTimingFilter calls the JRunStatistics servlet to create a table at the bottom of the target resource that displays the timing information.

The following lines define the JRunTimingFilter in the default-web.xml file:

<filter>

��<filter-name>JRunTimingFilter</filter-name>
��<filter-class>jrun.servlet.filters.TimingFilter</filter-class>
</filter>
<filter-mapping>
��<filter-name>JRunTimingFilter</filter-name>
��<url-pattern>/*</url-pattern>
</filter-mapping>

The default url-pattern mapping is /*, so when the JRunTimingFilter is enabled, it is invoked on every request.

The JRunTimingFilter takes two initialization parameters, as the following table describes:

Initialization parameter	Description
statsPage	Defines the name of the statistics page to include after the response. The default is /JRunStatistics.
mimeTypes	Defines a comma-separated list of response MIME types that JRun applies the JRunTimingFilter to. Each MIME type can have a single wildcard (*) at the end. The default is text/*.

The JRunTimingFilter is disabled by default. You must uncomment the filter definition and filter mapping to enable it.

The following lines from the default-web.xml file define the JRunStatistics servlet. Do not edit these settings.

<servlet>

��<servlet-name>JRunStatistics</servlet-name>
��<jsp-file>/jrunx/instrument/Results.jsp</jsp-file>
</servlet>
<servlet-mapping>
��<servlet-name>JRunStatistics</servlet-name>
��<url-pattern>/JRunStatistics</url-pattern>
</servlet-mapping>

After you enable the JRunTimingFilter, JRun inserts the amount of time the page took to execute, plus any methods processed by the InstrumentationService, at the bottom of each page, as the following figure shows:

For more information on configuring the InstrumentationService, see Chapter 9, "Configuring method timing".

Message format

Each time a call is made to a method that you time, JRun writes two messages to the output destination. The first message contains identifying information, text that indicates that method timing is starting, and the start time of the method. The second message contains the same identifying information, text that indicates that method timing is ending, as well as the end time and elapsed time of the method, measured in milliseconds.

Current message timing format

The message format for a current method call contains the following components:

currentTimeMillis loglevel type,className,hashCode,methodName,methodType,elapsed

These values are explained in the following table:

Value	Description
currentTimeMillis	The date and time of the message. Time is recorded in milliseconds.
loglevel	The level of the timing message: info, warning, error, or debug.
type	A string that signifies entering or exiting a method.
className	The class name containing the method.
hashCode	The hash code is a unique object reference that is useful in a multithreaded environment. If two threads are working on the same servlet at the same time, the method timing messages are interleaved; the hash code enables you to differentiate the messages.
methodName	The name of the method.
methodType	The signature of the method, including the return type, such as V for void.
elapsed	The elapsed time of the method call (for method exits only), in milliseconds.

The following is an example of timing messages generated by entering and exiting a doGet method:

01/13 10:57:37 info METHOD ENTER SimpleServlet 7126423 
   doGet(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) 11

01/13 10:57:37 info METHOD EXIT SimpleServlet 7126423 
   doGet(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) 25 0

Method call timing

The message format for an invoked method call contains the following components:

currentTime loglevel type,className hashCode,methodName,

methodType,callClassName,callMethodName,callMethodType,line,elapsed

This message format contains all of the components of a current method call message, plus additional components, which appear in bold.

The additional values are explained in the following table:

Value	Description
callClassName	The class name of a method to be timed
callMethodName	The name of the invoked method, called by the current method (methodName)
callMethodType	The signature of the invoked method (callMethodName)
line	The line number of the statement in the method (methodName) that includes the invoked method (callMethodName)

Examples

The following sections describe examples of using method timing.

Enabling default settings for method timing

The default method timing settings in the jrun.xml file work well for servlets.

To enable current method timing:

1. Set the instrumentMethods attribute to True.
2. Execute one or more servlets.
3. View the log file for the JRun server.

Enabling settings for EJB timing

To enable EJB timing, you must make the following modifications to the jrun.xml file:

• Add a className attribute for the EJB class to be timed; for example, javax.ejb.SessionBean.
• Enable timing through instrumentMethods and instrumentCalls attributes.
• Specify the methods and called methods to be timed through the instrumentMethod and instrumentCallsTo attributes.

Enabling settings for other classes

You can use JRun method timing to time any classes handled by the JRun class loader. This includes servlets, JSPs, EJBs, helper classes, and JavaBeans. To enable method timing for a class such as a JavaBean, make the following modifications to the jrun.xml file:

• Add a className attribute for the class to be timed; for example, helpers.DataObject.
• Enable timing through instrumentMethods and instrumentCalls attributes.
• Specify the methods and called methods to be timed through the instrumentMethod and instrumentCallsTo attributes.

Send me an e-mail when comments are added to this page | Comment Report

Current page: http://livedocs.adobe.com/jrun/4/Programmers_Guide/servletoptimizing7.htm

Add Comment