Hello,
In this article, I will present you a solution in order to measure performance and time processing on server side. This technical solution allow to quickly obtain a detailed report of performance in an application by the measure of the execution time (for example) for queries in persistence layer (Hibernate, JDBC) via AOP or “hard coding” and the display time of JSP with the possibility to indicate a significant task in a measurement made.
- Technologies
The monitor consists of a specific call to a method named “StopWatch.getInstance().start(‘TASKNAME’)” before the execution of the method to monitor, then another specific call to a method named “StopWatch.getInstance().stop(‘TASKNAME’)” after the execution of the method to monitor (StopWatch, StopWatchTask).To make these specific calls, we will use:
- an AOP layer (AOPALLIANCE library in Spring framework) to measure the execution time of the methods in the persistence layer HIBERNATE;
- direct calls (BEFORE, AFTER) to the business of monitoring in the methods of the persistence layer JDBC to monitor the performance of SQL (in the project in attachement, see JdbcUtilsServiceImpl);
- direct calls (BEFORE, AFTER) to the business of monitoring in JSP to display in console the detailed report of performance at the end of the display of a JSP page;
The detailed report of the execution stack diplayed in console helps developers to highlight the main bottlenecks.
- a Spring context defined in a XML file spring-business-config.xml,
- a servlet context listener named SpringContextLoader to load this Spring context,
- a singleton named ApplicationContextContainer which will give an access to the Spring context (see my post on this topic Access to Spring context in all places or layers of an application),
- a mock HIBERNATE persistence layer with the classes Business1DaoHibernateImpl, Business2DaoHibernateImpl,
- a mock JDBC persistence layer with the class JdbcUtilsServiceImpl,
- a JSP page index.jsp to display the detailed report in console,
- an AOP layer with a probe named PerformanceMonitor,
- a simple test class named PerfMeasureTest,
- the JARs cglib-2.2.2.jar, commons-collections-3.1.jar, commons-dbcp-1.4.jar, commons-logging-1.1.1.jar, commons-pool-1.4.jar, jstl.jar (version 1.1.2), jta-1.1.jar, spring-2.5.6.jar, spring-webmvc-2.5.6.jar and standard.jar (version 1.1.2).
- in the methods saveOrUpdate(), save(), update() and delete() of the classes Business1DaoHibernateImpl and Business2DaoHibernateImpl,
- in the method executeQuery(String sql) in the class JdbcUtilsServiceImpl,
- Spring context
The Spring context is defined in a XML file spring-business-config.xml:01
<?
xml
version
=
"1.0"
encoding
=
"UTF-8"
?>
02
<!DOCTYPE beans PUBLIC
03
"-//SPRING//DTD BEAN//EN"
05
06
<
beans
default-autowire
=
"no"
default-lazy-init
=
"true"
default-dependency-check
=
"none"
>
07
08
<!-- PERSISTENCE LAYER JBDC SQL MOCK -->
09
<
bean
name
=
"JdbcUtilsServiceImpl"
class
=
"com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl"
/>
10
11
<!-- PERSISTENCE LAYER DAO HIBERNATE MOCK -->
12
<
bean
name
=
"Business1DaoHibernateImpl"
class
=
"com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl"
/>
13
<
bean
name
=
"Business2DaoHibernateImpl"
class
=
"com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl"
/>
14
15
<!-- AOP LAYER AOPALLIANCE -->
16
<
bean
id
=
"performanceMonitor"
class
=
"com.ho.test.perf.measure.commons.aop.PerformanceMonitor"
/>
17
18
<
bean
name
=
"performanceMonitor.proxy"
class
=
"org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator"
>
19
<
property
name
=
"beanNames"
>
20
<
list
>
21
<
value
>Business1DaoHibernateImpl</
value
>
22
<
value
>Business2DaoHibernateImpl</
value
>
23
</
list
>
24
</
property
>
25
<
property
name
=
"interceptorNames"
>
26
<
list
>
27
<
value
>performanceMonitor</
value
>
28
</
list
>
29
</
property
>
30
</
bean
>
31
</
beans
>
… more, we declare a servlet context listener named SpringContextLoader to load this Spring context in the web deployment descriptor web.xml:
01
<?
xml
version
=
"1.0"
encoding
=
"UTF-8"
?>
02
<
web-app
...>
03
...
04
<
listener
>
05
<
listener-class
>com.ho.test.perf.measure.utils.SpringContextLoader</
listener-class
>
06
</
listener
>
07
<
context-param
>
08
<
param-name
>CONFIG_SPRING_FILE</
param-name
>
09
<
param-value
>/WEB-INF/spring-business-config.xml</
param-value
>
10
</
context-param
>
11
</
web-app
>
The code of servlet context listener SpringContextLoader:
01
public
class
SpringContextLoader
implements
ServletContextListener {
02
/**
03
* Method contextDestroyed
04
* @param arg0
05
* @see javax.servlet.ServletContextListener#contextDestroyed(javax.servlet.ServletContextEvent)
06
*/
07
public
void
contextDestroyed(ServletContextEvent arg0) {
08
}
09
10
/**
11
* Method contextInitialized
12
* @param arg0
13
* @see javax.servlet.ServletContextListener#contextInitialized(javax.servlet.ServletContextEvent)
14
*/
15
public
void
contextInitialized(ServletContextEvent ctx) {
16
String springFileName = ctx.getServletContext().getInitParameter(
"CONFIG_SPRING_FILE"
);
17
ApplicationContextContainer.getInstance(springFileName, ctx.getServletContext());
18
}
19
}
… and singleton ApplicationContextContainer:
01
public
class
ApplicationContextContainer {
02
03
private
static
Log log = LogFactory.getLog(ApplicationContextContainer.
class
);
04
05
private
final
static
String SPRING_BUSINESS_CONFIG_XML =
"/WEB-INF/spring-business-config.xml"
;
06
07
/**
08
* Instance
09
*/
10
private
static
ApplicationContextContainer instance =
null
;
11
12
/**
13
* Contains the spring configuration.
14
*/
15
private
XmlWebApplicationContext ctx =
null
;
16
17
private
ApplicationContextContainer() {}
18
19
/**
20
* Getinstance method.
21
*/
22
public
static
synchronized
ApplicationContextContainer getInstance() {
23
return
getInstance(SPRING_BUSINESS_CONFIG_XML,
null
);
24
}
25
public
static
synchronized
ApplicationContextContainer getInstance(String springContextFile, ServletContext servletContext) {
26
if
(
null
== instance) {
27
instance =
new
ApplicationContextContainer();
28
instance.ctx =
new
XmlWebApplicationContext();
29
instance.ctx.setConfigLocation(springContextFile);
30
instance.ctx.setServletContext(servletContext);
31
instance.ctx.refresh();
32
}
// end-if
33
return
instance;
34
}
35
36
/**
37
* Retrieve the spring bean corresponding to the given key.
38
* @param key
39
* @return
40
*/
41
public
static
Object getBean(String key) {
42
return
getInstance().ctx.getBean(key);
43
}
44
45
public
XmlWebApplicationContext getContext() {
46
return
ctx;
47
}
48
}
- TASK concept
StopWatch: This singleton measures the duration of execution for a set of tasks. It contains all tasks to monitor in a MAP whose the key is the taskname of task. A task is defined by the class StopWatchTask.01
public
class
StopWatch {
02
//...
03
04
/**
05
* Contains the unique instance of the class.
06
*/
07
private
static
StopWatch instance =
null
;
08
09
/**
10
* Contains all the tasks in the order of arrival.
11
*/
12
private
Collection<StopWatchTask> tasks =
new
ArrayList<StopWatchTask>();
13
14
/**
15
* Contains all tasks. The task name is used as key in the map.
16
*/
17
private
Map<String, StopWatchTask> tasksByName =
new
HashMap<String, StopWatchTask>();
18
19
//...
20
21
/**
22
* Startup / create the task corresponding to the unique name of the given task.
23
* @param taskname
24
* @return
25
*/
26
public
StopWatchTask start(String taskname) {
27
// Try to retreive the corresponding task
28
StopWatchTask correspondingTask =
new
StopWatchTask(taskname, ident);
29
// The task doesn't exist, adds its reference in the lists of tasks
30
tasks.add(correspondingTask);
31
tasksByName.put(taskname, correspondingTask);
32
33
34
// Start the task
35
{
36
correspondingTask.start();
37
ident++;
38
}
// end-block
39
40
return
correspondingTask;
41
}
42
43
/**
44
* Stop the corresponding task to the unique reference of given task
45
* @param taskname
46
* @return
47
*/
48
public
StopWatchTask stop(String taskname) {
49
StopWatchTask correspondingTask = tasksByName.get(taskname);
50
correspondingTask.stop();
51
ident--;
52
//Output to the console because the measurements are performed
53
// on asynchronously calls in controllers from the JSP layer PRESENTATION
54
//System.out.println(correspondingTask.toString());
55
56
return
correspondingTask;
57
}
58
59
//...
60
61
/**
62
* Method toString
63
* @return
64
* @see java.lang.Object#toString()
65
*/
66
@Override
67
public
String toString() {
68
// Displaying the stack of execution of tasks
69
String output =
"StopWatchReport execution Stack \n"
;
70
for
(StopWatchTask currTask : tasks) {
71
output += currTask +
"\n"
;
72
}
73
74
// Showing the significant tasks
75
output +=
"\nStopWatchReport significant task \n"
;
76
for
(StopWatchTask currTask : tasks) {
77
if
(currTask.isSignificant()) {
78
output += currTask.dumpWithoutIdent() +
"\n"
;
79
}
80
}
81
82
return
output;
83
}
84
}
StopWatchTask: This class defines a monitored task and measures the duration of execution of this task.
01
public
class
StopWatchTask {
02
03
//...
04
05
/**
06
* Hour (in ms) of tasks startup.
07
*/
08
private
long
startTime =
0
;
09
10
/**
11
* Duration of execution of the task in ms.
12
*/
13
private
long
execTime =
0
;
14
15
/**
16
* Name/Reference of task.
17
*/
18
private
String name;
19
20
/**
21
* Constructor of task.
22
*/
23
public
StopWatchTask(String name,
int
indent) {
24
this
.name = name;
25
this
.indent = indent;
26
}
27
28
/**
29
* Start the task.
30
*/
31
public
final
void
start() {
32
startTime = Calendar.getInstance().getTimeInMillis();
33
}
34
35
/**
36
* Stop the task.
37
* (and update the execution duration (exectime) and the accrued total duration (totalExecTime) of the task.
38
*/
39
public
final
void
stop() {
40
long
endTime = Calendar.getInstance().getTimeInMillis();
41
execTime = endTime - startTime;
42
//totalExecTime+= execTime;
43
}
44
45
public
String dumpWithoutIdent() {
46
return
"Task "
47
+
"name='"
+ name +
"' "
48
+
"execTime='"
+ execTime +
"' "
49
//+ "total : " + totalExecTime
50
;
51
}
52
53
/**
54
* Method toString
55
* @return
56
* @see java.lang.Object#toString()
57
*/
58
@Override
59
public
String toString() {
60
String identStr =
""
;
61
for
(
int
i=
0
; i<indent; i++) {
62
identStr +=
"\t"
;
63
}
64
65
String output = identStr + dumpWithoutIdent();
66
if
(!
""
.equals(log)) {
67
output +=
"\n"
+ identStr + log;
68
}
69
70
return
output;
71
}
72
73
//...
74
}
- Classes to monitor
JdbcUtilsServiceImpl: This classes is monitored and contains direct calls to “StopWatch.getInstance().start(…);” and “StopWatch.getInstance().stop(…);”.01
public
class
JdbcUtilsServiceImpl
implements
IJdbcUtils {
02
/**
03
* Execute query.
04
* @param sql the sql
05
* @return the query execution result as a List
06
*/
07
public
List executeQuery(String sql) {
08
StopWatch.getInstance().start(sql);
09
try
{
10
Thread.currentThread().sleep(PerformanceMonitor.getRandomSleepTime());
11
}
catch
(Throwable th){
12
}
finally
{
13
StopWatch.getInstance().stop(sql);
14
}
15
return
new
ArrayList();
16
}
17
}
Business1DaoHibernateImpl: This classes will be monitor by AOP.
01
public
class
Business1DaoHibernateImpl
implements
IBusiness1 {
02
03
/**
04
* Save or update object into database.
05
*/
06
public
void
saveOrUpdate() {
07
//...
08
}
09
10
/**
11
* Save object into database.
12
*/
13
public
void
save() {
14
//...
15
}
16
/**
17
* Update object into database.
18
*/
19
public
void
update() {
20
//...
21
}
22
23
/**
24
* Delete object into database.
25
*/
26
public
void
delete() {
27
//...
28
}
29
}
Business2DaoHibernateImpl: This classes will be monitor by AOP.
01
public
class
Business2DaoHibernateImpl
implements
IBusiness1 {
02
03
/**
04
* Save or update object into database.
05
*/
06
public
void
saveOrUpdate() {
07
//...
08
}
09
/**
10
* Save object into database.
11
*/
12
public
void
save() {
13
//...
14
}
15
/**
16
* Update object into database.
17
*/
18
public
void
update() {
19
//...
20
}
21
22
/**
23
* Delete object into database.
24
*/
25
public
void
delete() {
26
//...
27
}
28
}
- AOP Alliance
The class PerformanceMonitor is a probe used to intercept the calls to the methods of the beans Business1DaoHibernateImpl, Business2DaoHibernateImpl defined in the Spring Context via the bean performanceMonitor.proxy which is type of org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator. This probe allows the measure of the processing time in the methods of previous beans.As you could see in the below code, the probe:- generates the MethodKey of intercepted method with getMethodKey(…),
- creates the task corresponding to the name generated (BEFORE the execution of intercepted method) with StopWatch.getInstance().start(…),
- executes the intercepted method/business,
- stops the corresponding task (AFTER the execution of intercepted method) with StopWatch.getInstance().stop(…),
01
/**
02
* <p>Title: PerformanceMonitor</p>
03
* <p>
04
* This probe is used to measure the response time functions Spring via AOP.
05
* </p>
06
*
07
* @a2.Version
08
*/
09
public
class
PerformanceMonitor
implements
MethodInterceptor {
10
11
/**
12
* @see org.aopalliance.intercept.MethodInterceptor#invoke(org.aopalliance.intercept.MethodInvocation)
13
*/
14
public
Object invoke(MethodInvocation method)
throws
Throwable {
15
// Generates the MethodKey of intercepted method
16
String methodKey = getMethodKey(method);
17
18
// Business executed BEFORE the execution of intercepted method
19
StopWatch.getInstance().start(methodKey);
20
21
Object output =
null
;
22
try
{
23
// Execution of intercepted method
24
output = method.proceed();
25
}
finally
{
26
// Business executed AFTER the execution of intercepted method
27
StopWatch.getInstance().stop(methodKey);
28
}
// end-if
29
30
return
output;
31
}
32
33
/**
34
* Generates the MethodKey of intercepted method
35
* @return the key used to store the items in the cache.
36
*/
37
private
String getMethodKey(MethodInvocation method) {
38
StringBuffer cacheNameBuffer =
new
StringBuffer();
39
//...
40
return
cacheNameBuffer.toString();
41
}
42
}
- Tests
Test n°1: JSP page
After the deployment of Web application on an AS, for example TOMCAT:1
INFO: Pre-instantiating singletons in org.springframework.beans.factory. support.DefaultListableBeanFactory@54956254: defining beans [JdbcUtilsServiceImpl,Business1DaoHibernateImpl,Business2DaoHibernateImpl, performanceMonitor,performanceMonitor.proxy]; root of factory hierarchy
… open the URL http://localhost:8080/testPerfMeasure/index.jsp. This JSP page index.jsp is monitored and contains direct calls to several services in persistence layer (monitored too), “StopWatch.getInstance().start(…);” and “StopWatch.getInstance().stop(…);”.
01
<%@ page language=
"java"
import
=
"java.util.*"
%>
02
<%@ page
import
=
"com.ho.test.perf.measure.commons.tools.StopWatch"
%>
03
<%@ page
import
=
"com.ho.test.perf.measure.utils.ApplicationContextContainer"
%>
04
<%@ page
import
=
"com.ho.test.perf.measure.commons.jdbc.IJdbcUtils"
%>
05
<%@ page
import
=
"com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1"
%>
06
<%
07
StopWatch.getInstance().clear();
08
StopWatch.getInstance().start(
"index.jsp"
);
09
%>
10
<%
@page
pageEncoding=
"UTF-8"
contentType=
"text/html; charset=UTF-8"
%>
11
12
<HTML>
13
<HEAD>
14
<TITLE>TEST</TITLE>
15
<META http-equiv=
"content-type"
content=
"text/html; charset=UTF-8"
>
16
</HEAD>
17
<BODY>
18
19
<%
20
IBusiness1 business1 = (IBusiness1) ApplicationContextContainer.getInstance().getBean(
"Business1DaoHibernateImpl"
);
21
IBusiness1 business2 = (IBusiness1) ApplicationContextContainer.getInstance().getBean(
"Business2DaoHibernateImpl"
);
22
IJdbcUtils jdbcUtils = (IJdbcUtils) ApplicationContextContainer.getInstance().getBean(
"JdbcUtilsServiceImpl"
);
23
24
jdbcUtils.executeQuery(
"SELECT * FROM HUO_TEST WHERE ID=123"
);
25
business1.save();
26
business2.delete();
27
28
%>
29
See in the console/log, the report of execution stack allowing to highlight the main bottlenecks.
30
<%
31
StopWatch.getInstance().stop(
"index.jsp"
);
32
System.out.println(StopWatch.getInstance().toString());
33
StopWatch.getInstance().clear();
34
%>
35
36
</BODY>
37
</HTML>
… and the processing time report has been displayed in the browser and the ouputs in console could be:
1
StopWatchReport execution Stack
2
Task name='index.jsp' execTime='7575'
3
Task name='SELECT * FROM HUO_TEST WHERE ID=123' execTime='2181'
4
Task name='com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1.save()' execTime='2464'
5
Task name='com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1.delete()' execTime='2816'
6
7
StopWatchReport significant task
Test n°2: Main class
The project in attachement contains a test class named PerfMeasureTest:01
public
static
void
main(String[] args) {
02
03
// Clean the set of tasks
04
StopWatch.getInstance().clear();
05
06
// Task 1
07
StopWatch.getInstance().start(
"task 1"
);
08
{
09
// Task 2
10
StopWatch.getInstance().start(
"task 2"
);
11
{
12
StopWatch.getInstance().start(
"task 2a"
);
13
try
{Thread.sleep(
500
);}
catch
(InterruptedException e) {}
14
StopWatch.getInstance().stop(
"task 2a"
);
15
//
16
StopWatch.getInstance().start(
"task 2c"
);
17
try
{Thread.sleep(
125
);}
catch
(InterruptedException e) {}
18
StopWatch.getInstance().stop(
"task 2c"
);
19
//
20
StopWatch.getInstance().start(
"task 2d"
);
21
try
{Thread.sleep(
30
);}
catch
(InterruptedException e) {}
22
StopWatch.getInstance().start(
"task 2d1"
);
23
try
{Thread.sleep(
252
);}
catch
(InterruptedException e) {}
24
StopWatch.getInstance().stop(
"task 2d1"
);
25
StopWatch.getInstance().stop(
"task 2d"
);
26
}
27
StopWatch.getInstance().stop(
"task 2"
);
28
29
// Task 3
30
StopWatch.getInstance().start(
"task 3"
);
31
{
32
try
{Thread.sleep(
10
);}
catch
(InterruptedException e) {}
33
StopWatch.getInstance().start(
"task 3a"
).setSignificant();
34
try
{Thread.sleep(
45
);}
catch
(InterruptedException e) {}
35
StopWatch.getInstance().stop(
"task 3a"
);
36
}
37
StopWatch.getInstance().stop(
"task 3"
);
38
39
// Task 3a
40
StopWatch.getInstance().start(
"task 3a"
);
41
try
{Thread.sleep(
55
);}
catch
(InterruptedException e) {}
42
StopWatch.getInstance().stop(
"task 3a"
);
43
44
}
45
StopWatch.getInstance().stop(
"task 1"
);
46
47
// Task 3a
48
StopWatch.getInstance().start(
"task 3a"
);
49
try
{Thread.sleep(
65
);}
catch
(InterruptedException e) {}
50
StopWatch.getInstance().stop(
"task 3a"
);
51
52
// Display the execution report of StopWatch
53
System.out.println(StopWatch.getInstance());
54
}
… os, the outputs in console could be:
01
StopWatchReport execution Stack
02
Task name='task 1' execTime='1056'
03
Task name='task 2' execTime='945'
04
Task name='task 2a' execTime='500'
05
Task name='task 2c' execTime='163'
06
Task name='task 2d' execTime='282'
07
Task name='task 2d1' execTime='252'
08
Task name='task 3' execTime='56'
09
Task name='task 3a' execTime='45'
10
Task name='task 3a' execTime='55'
11
Task name='task 3a' execTime='65'
12
13
StopWatchReport significant task
14
Task name='task 3a' execTime='45'
- Limitations and Evolutions of this solution
Performance verification of the requests in the persistence layer and SQL queries should be performed on an isolated server dedicated to tests because the design / use of “taskName” in the classes StopWatch, StopWatchTask is not fixed/frozen…. i.e. if several users use the same server, the business will not create a TASK for each user query submitted but will use the same TASK because its “taskName” is identical for each control point. This is why when you get to index.jsp, there may be several TASKS already created in the list and display all the previous queries are also displayed.Submit “taskName” with a prefix, for exammple, the name of current user and the current date in milliseconds,
o Create an instance of the list of tasks (StopWatch) by each entry point controls (index.jsp) and by user.
o Use semaphores and synchronized, - Others solutions
An other solution to get measures of performance and time processing on server side and display the results in comments of each JSP page, the processing time of the BUSINESS layer and PRESENTATION layer:
In the front dispatcher (method “execute” of “DispatchAction” in Struts, in the Spring MVC “Controller”) or simply in a HTTP filter, we could save the processing time in a Session attribute named EXECTIME:1
Calendar perfBegin = Calendar.getInstance();
2
//...
3
long
execTime = (Calendar.getInstance().getTimeInMillis() - perfBegin.getTimeInMillis());
4
request.setAttribute(
"EXECTIME"
, execTime);
5
//...
..then in the JPS page, dispay this time from the “EXECTIME” attribute:
01
[...]
02
<html>
03
<head>
04
<%
05
Calendar perfStart = Calendar.getInstance();
06
%>
07
[...]
08
<!--
09
EXECTIME BUSINESS LAYER : ${EXECTIME}
10
EXECTIME PRESENTATION LAYER : <%=(Calendar.getInstance().getTimeInMillis() - perfStart.getTimeInMillis())%>
11
-->
12
</body>
13
</html>
To illustrate our previous explanations, we will create a Web project with:
More, in our project, the execution/processing time of methods to monitor in the persistence layers (Hibernate and JDBC) will be random between 1 second and 5 seconds:
01 | /** |
02 | * Returns a number in milliseconds between 1000 (1sec) and 5000 (5sec) |
03 | * @return |
04 | */ |
05 | public static long getRandomSleepTime(){ |
06 | int lower = 1000 ; |
07 | int higher = 5000 ; |
08 |
09 | long random = ( long )(Math.random() * (higher-lower)) + lower; |
10 | return random; |
11 | } |
I don’t have been exhaustive in this article, but, I hope that it will be useful for your needs about the measures of performance and time processing on server side.
For more informations, you could contact me.
Download: testPerfMeasure.zip
Best regards,
Huseyin OZVEREN