Skip to: Site menu | Main content

XPlanner

Planning and tracking tool for agile teams following XP or Scrum

Optimization Print

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

AuthorizerImpl.getPermissionForPrincipal

~70 36 57.3
do/confinue/unfinished/stories 39.2 6 391.2

AuthorizerImpl.getPermissionForPrincipal

~60 8445 154
do/view/userstory 3.7 12 16.9

OutlineTag.getNextPrevId

~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

AuthorizerImpl.getPermissionForPrincipal

75 1956 1.65
do/confinue/unfinished/stories 17.4 6 718

AuthorizerImpl.getPermissionForPrincipal

~60 17000 0.15
do/view/task 15.9 84 46.8

AuthorizerImpl.getPermissionForPrincipal

34 11736 0.1
do/view/people 14.9 12 307

AuthorizerImpl.permissionMatches

24 23880 .037

AuthorizerImpl.getPermissionForPrincipal

19 11500 19

UseBeansTag.bindParametersAndExecute

17 24 26.1
do/view/iteration 7.8 60 32.1

OutlineTag.getNextPrevId -> find

33 96 10.3
do/view/project 7.2 60 29.5

AuthorizerImpl.hasPermissionForPrincipal

28 7824 0.066
do/view/userstory 5.6 60 22.9
do/view/iteration/tasks 4.0 6 166

AuthorizerImpl.hasPermissionForPrincipal

30 978 0.292
do/view/person 3.7 60 15.3
do/view/iteration/accuracy 1.7 3 144

AuthorizerImpl.hasPermissionForPrincipal

9 489 0.085
do/view/iteration/statistics 1.2 1 291

(cewolf) ChartImageTag

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

IterationMetrics.getWorkingHours

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

AuthorizerImpl.getPermissionForPrincipal

<2 79 0.373
do/confinue/unfinished/stories 29.3 12 131.33

AuthorizerImpl.getPermissionForPrincipal

~60 32000 20
do/view/userstory 12.7 24 28.58

OutlineTag.getNextPrevId

~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

AuthorizerImpl.getPermissionForPrincipal

9.5 1800 0.02
do/confinue/unfinished/stories 10.3 5 173

AuthorizerImpl.getPermissionForPrincipal

5 14145 0.005
do/view/task 12.9 70 15.5

AuthorizerImpl.getPermissionForPrincipal

4 9780 0.004
do/view/people 18 10 152

AuthorizerImpl.permissionMatches

15 20000 .012

AuthorizerImpl.getPermissionForPrincipal

3 10000 0.004

UseBeansTag.bindParametersAndExecute

33.4 20 25.4
do/view/iteration 11.8 50 20

OutlineTag.getNextPrevId -> find

35 80 4.41
do/view/project 10 50 16.8

AuthorizerImpl.hasPermissionForPrincipal

5 6520 .005
do/view/userstory 9.5 50 16
do/view/iteration/tasks 1 2 40

AuthorizerImpl.hasPermissionForPrincipal

2 624 0.002
do/view/person 11.2 50 19
do/view/iteration/accuracy 1.1 3 30

AuthorizerImpl.hasPermissionForPrincipal

1 489 0.001
do/view/iteration/statistics 15.3 3 149

(cewolf) ChartImageTag

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

IterationMetrics.getWorkingHours

?? ? ??
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