Application performance mesurment
Test environment
I used Apache JMeter to create load tests. They were run against the latest version of XPlanner with upgraded copy of the production database
On staging machine (toolsstaging1)
Tomcat:
Version: 5.0.28
Memory options: -Xms768M -Xmx1280M
Run as a java process with JProfiler additions
MySQL
Version: 4.0.26
Standard configuration but max_allowed_packet=1024M
Run as a Windows service.
On my application
- Apache JMeter v2.1.1
- JProfiler GUI v4.1.3
- MySQL Administrator 1.1.9
The tested application had been deployed on toolsstaging1. JProfiler's additions collected all information about method invocations and published it on a TCP port. The GUI part, installed on my local machine gathered the data and showed in the JProfiler window.
Test
I created two kind of tests was creaded. The simulation of iteration planning and trying to reproduce the regular using of XPlanner. The tests consisted of the steps shown below:
Iteration planning simulation. The test was run by 6 threads 2 times.
- Login
- Add a story to the iteration
- Add a task to the story
- Move the story
- Continiue the story
- Edit the carried over story estimation
- Start the iteration
- Remove the original story
- Remove the caried over story
- Close iteration
- Logout
Regular using of xplanner. The test was run by 5 threads 2 times.
- Login
- Start a iteration
- The following actions run in random order:
- View 5 projects
- View 5 iterations (main page) and one view selected randomly from the following pages:
- All task
- Metrics
- Charts
- Accuracy
- History
- View 5 stories
- View 5 tasks and for one of them:
- Reopen task
- Edit time entry
- Close task
- View people page
- View 5 person pages
- Close iteration
- Logout
To run the test
- open Apache JMeter
- open load test xml definition file
- configure the project's HTTP Request Defaults to point at the tested application (server name and port no)
- configure the project user defined variables:
- userId - test user id
- password - test user password
- applicationName - the context of the application under tests
Test results before optimization
The following tables contain test results for every page involved in a given test.
The percentage column shows how much time given element (page or method) was run in a given context. For a page the total time is execution of all pages, for a method it is execution of a page the method is called from.
The tables contain all pages executed by the test. Only those methods are shown for which execution time was bigger than 10% of the execution of overall page.
Iteration planning
| Page name / method name | Relative percentage time[%] | Invocations number | Avg execution time[s] |
|---|---|---|---|
| do/view/iterations | 51.1 | 36 | 78.6 |
|
~70 | 36 | 57.3 |
| do/confinue/unfinished/stories | 39.2 | 6 | 391.2 |
|
~60 | 8445 | 154 |
| do/view/userstory | 3.7 | 12 | 16.9 |
|
~90 | 36 | 4.86 |
| do/login | 2.4 | 17 | 7.8 |
| do/start/iteration | 0.7 | 6 | 6.8 |
| do/move/continue/story | 0.6 | 12 | 2.96 |
| do/close/iteration | 0.2 | 6 | 1.84 |
| do/delete/userstory | 0.1 | 12 | 0.64 |
| do/edit/task | 0.1 | 12 | 0.55 |
| do/logout | 0.1 | 1 | 6.4 |
| do/edit/userstory | 0.1 | 12 | 0.45 |
Regular use of xplanner
| Page name / Method name | Relative percentage time[%] | Invocations number | Avg execution time[s] |
|---|---|---|---|
| do/view/projects | 17.5 | 12 | 360 |
|
75 | 1956 | 1.65 |
| do/confinue/unfinished/stories | 17.4 | 6 | 718 |
|
~60 | 17000 | 0.15 |
| do/view/task | 15.9 | 84 | 46.8 |
|
34 | 11736 | 0.1 |
| do/view/people | 14.9 | 12 | 307 |
|
24 | 23880 | .037 |
|
19 | 11500 | 19 |
|
17 | 24 | 26.1 |
| do/view/iteration | 7.8 | 60 | 32.1 |
|
33 | 96 | 10.3 |
| do/view/project | 7.2 | 60 | 29.5 |
|
28 | 7824 | 0.066 |
| do/view/userstory | 5.6 | 60 | 22.9 |
| do/view/iteration/tasks | 4.0 | 6 | 166 |
|
30 | 978 | 0.292 |
| do/view/person | 3.7 | 60 | 15.3 |
| do/view/iteration/accuracy | 1.7 | 3 | 144 |
|
9 | 489 | 0.085 |
| do/view/iteration/statistics | 1.2 | 1 | 291 |
|
71 | 8 | 25.8 |
| do/edit/task | 1.1 | 24 | 11.8 |
| do/edit/time | 0.8 | 12 | 16.2 |
| do/view/iteration/metrics | 0.4 | 1 | 106 |
|
23 | 1 | 24 |
| do/login | 0.3 | 24 | 3.58 |
| do/start/iteration | 0.3 | 6 | 13.7 |
| do/view/history | 0.1 | 1 | 20.7 |
| do/close/iteration | 0.0 | 6 | 0.43 |
| do/logout | 0.0 | 12 | 007 |
Optimization
The most time consuming methods are those connected with authorization. Below are the tunning steps I did to speed up the application:
- add a binary column to indicate if permission is positive or negative. So far the negative permissions had a minus sign as a prefix of permission name. That solution complicated queries to get the permissions from the database and also determining if the permission is negative or positive required string operations, which are more time consuming that the binary ones.
- The query to get all permission for all people was getting both person-specific permissions and role based permission in one go. That caused that the query was really complex and time consuming. I rewrote it to create two queries; one to get person specific permission and the other one to get role based permission. This solution speeded up the queries about 4 times.
- The factor which slowed down the application the most was inefficient permission caching framework. The cache for permissions for all people was invalidated after every logout. The refactoring I did was to separate the authorizer login from the caching. I use AOP for that. I extracted two beans from AuthorizerImpl; PermissionQueryHelper and PersonPermissionHelper. Those beans are responsible for getting permission from the database; respectively all permission for all people and permissions for a given person only. Using AOP I created advisors for that beans; those advisors are checking if the cache already contains the return value for a cached method; if does the original method is not called but the cached value is returned. If the cache doesn't contain the results, the method is called and the result, before it is returned to the caller, is put into cache. Other advisors were created to invalidate the cache. There are two joinpoints when the cache can is invalidated:
- Authenticator.logout() - the person specific cache
- EditPersonHelper.modifyRoles() - all caches
Test results after optimization
Iteration planning
| Page name / method name | Relative percentage time[%] | Invocations number | Avg execution time[s] |
|---|---|---|---|
| do/view/iterations | 48.4 | 79 | 23.95 |
|
<2 | 79 | 0.373 |
| do/confinue/unfinished/stories | 29.3 | 12 | 131.33 |
|
~60 | 32000 | 20 |
| do/view/userstory | 12.7 | 24 | 28.58 |
|
~90 | 72 | 7.5 |
| do/login | 0.1 | 24 | 0.145 |
| do/start/iteration | 1.7 | 12 | 7.74 |
| do/move/continue/story | 3 | 24 | 6.7 |
| do/close/iteration | 1 | 12 | 4.33 |
| do/delete/userstory | 1.4 | 24 | 3.17 |
| do/edit/task | 0.6 | 24 | 1.4 |
| do/logout | 0.2 | 12 | 0.9 |
| do/edit/userstory | 1.4 | 24 | 3.01 |
Regular use of xplanner
| Page name / method name | Relative percentage time[%] | Invocations number | Avg execution time[s] |
|---|---|---|---|
| do/view/projects | 5.7 | 10 | 48 |
|
9.5 | 1800 | 0.02 |
| do/confinue/unfinished/stories | 10.3 | 5 | 173 |
|
5 | 14145 | 0.005 |
| do/view/task | 12.9 | 70 | 15.5 |
|
4 | 9780 | 0.004 |
| do/view/people | 18 | 10 | 152 |
|
15 | 20000 | .012 |
|
3 | 10000 | 0.004 |
|
33.4 | 20 | 25.4 |
| do/view/iteration | 11.8 | 50 | 20 |
|
35 | 80 | 4.41 |
| do/view/project | 10 | 50 | 16.8 |
|
5 | 6520 | .005 |
| do/view/userstory | 9.5 | 50 | 16 |
| do/view/iteration/tasks | 1 | 2 | 40 |
|
2 | 624 | 0.002 |
| do/view/person | 11.2 | 50 | 19 |
| do/view/iteration/accuracy | 1.1 | 3 | 30 |
|
1 | 489 | 0.001 |
| do/view/iteration/statistics | 15.3 | 3 | 149 |
|
87.2 | 24 | 16 |
| do/edit/task | 0.1 | 20 | 0.48 |
| do/edit/time | 1.5 | 10 | 13 |
| do/view/iteration/metrics | 0.7 | 1 | 59 |
|
?? | ? | ?? |
| do/login | 0 | 10 | 0.057 |
| do/start/iteration | 0.7 | 5 | 11.7 |
| do/view/history | 0.2 | 1 | 16.6 |
| do/close/iteration | 0.0 | 5 | 0.26 |
| do/logout | 0.0 | 10 | 0.29 |


