new webapp performance
Hi,
I'm impressed by the development of the new webapp. There is however one thing that I hope is just not addressed yet. The performance is rather low. Just starting a process takes allmost two seconds.
There are however some obvious delays in the system almost 1.5 secons is 'lost' beginning and committing a transaction and flushing the logs. See the log below.
01:52:21,093 DEBUG [LogFilter] request http://127.0.0.1:8080/jbpm/participant/home.jsf 01:52:21,093 DEBUG [LogFilter] request parameter [linkDummyForm:_link_hidden_]=newExe1 01:52:21,093 DEBUG [LogFilter] request parameter [taskInstanceId]= 01:52:21,093 DEBUG [LogFilter] request parameter [processDefinitionId]=1 01:52:21,093 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/taskreassign.xhtml]=[Ljava.lang.Object;@13214d1 01:52:21,093 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/manager/home.xhtml]=[Ljava.lang.Object;@1b3d448 01:52:21,093 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/participant/home.xhtml]=[Ljava.lang.Object;@3b84ee 01:52:21,093 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/login.xhtml]=[Ljava.lang.Object;@1fac7cf 01:52:21,093 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/administrator/home.xhtml]=[Ljava.lang.Object;@7a8ba4 01:52:21,093 DEBUG [JbpmPhaseListener] after phase RESTORE_VIEW(1) 01:52:21,093 DEBUG [JbpmPhaseListener] after phase APPLY_REQUEST_VALUES(2) 01:52:21,093 DEBUG [JbpmPhaseListener] after phase PROCESS_VALIDATIONS(3) 01:52:21,093 DEBUG [JbpmPhaseListener] after phase UPDATE_MODEL_VALUES(4) 01:52:21,093 DEBUG [ParticipantBean] starting new process instance 1 01:52:21,093 DEBUG [JbpmContextInfo] creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]' 01:52:21,093 DEBUG [JbpmContext] creating JbpmContext 01:52:21,093 DEBUG [DbPersistenceServiceFactory] creating persistence service 01:52:21,093 DEBUG [DbPersistenceService] creating hibernate session 01:52:21,093 DEBUG [DbPersistenceService] beginning hibernate transaction 01:52:21,234 DEBUG [GraphElement] event 'process-start' on 'ProcessDefinition(websale)' for 'Token(/)' 01:52:21,296 DEBUG [TaskController] creating task instance variable 'item' from process variable 'item', value 'null' 01:52:21,296 DEBUG [VariableContainer] create variable 'item' in 'TaskInstance[Create new web sale order]' with value 'null' 01:52:21,296 DEBUG [TaskController] creating task instance variable 'quantity' from process variable 'quantity', value 'null' 01:52:21,296 DEBUG [VariableContainer] create variable 'quantity' in 'TaskInstance[Create new web sale order]' with value 'null' 01:52:21,296 DEBUG [TaskController] creating task instance variable 'address' from process variable 'address', value 'null' 01:52:21,296 DEBUG [VariableContainer] create variable 'address' in 'TaskInstance[Create new web sale order]' with value 'null' 01:52:21,296 DEBUG [GraphElement] event 'task-create' on 'Task(Create new web sale order)' for 'Token(/)' 01:52:21,375 DEBUG [TaskInstance] assigning task 'Create new web sale order' to 'ernie' 01:52:21,375 DEBUG [GraphElement] event 'task-assign' on 'Task(Create new web sale order)' for 'Token(/)' 01:52:21,375 DEBUG [Services] executing default save operations 01:52:21,375 DEBUG [HibernateSaveOperation] saving process instance 01:52:21,375 DEBUG [SaveLogsOperation] flushing logs to logging service. 01:52:21,906 DEBUG [CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@66a008' 01:52:21,906 DEBUG [TaskBean] selecting task instance 246 01:52:21,906 DEBUG [TaskInstanceVariableMap] initializing task instance in variables map 01:52:21,906 DEBUG [JbpmPhaseListener] after phase INVOKE_APPLICATION(5) 01:52:21,906 DEBUG [JbpmPhaseListener] starting new transaction for the rendering phase 01:52:21,906 DEBUG [DbPersistenceService] committing hibernate transaction 01:52:22,921 DEBUG [DbPersistenceService] beginning hibernate transaction 01:52:22,953 DEBUG [TaskForms] task form path for 'Task(Create new web sale order)' is '/form.create.xhtml' 01:52:22,968 DEBUG [TaskInstanceVariableMap] fetched value 'null' for task variable 'item' 01:52:22,968 DEBUG [TaskInstanceVariableMap] fetched value 'null' for task variable 'quantity' 01:52:22,968 DEBUG [TaskInstanceVariableMap] fetched value 'null' for task variable 'address' 01:52:22,968 DEBUG [JbpmPhaseListener] after phase RENDER_RESPONSE(6) 01:52:22,968 DEBUG [JbpmContext] closing JbpmContext 01:52:22,968 DEBUG [Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@15decc0 01:52:22,968 DEBUG [DbPersistenceService] committing hibernate transaction 01:52:23,015 DEBUG [DbPersistenceService] closing hibernate session 01:52:23,015 DEBUG [Services] closing service 'logging': org.jbpm.logging.db.DbLoggingService@ba936a 01:52:23,015 DEBUG [Services] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@12421db
Ending one task takes even longer, more than 11 seconds. With delays in the same areas as above with the addition of the assignmenthandler.
01:53:40,062 DEBUG [LogFilter] request http://127.0.0.1:8080/jbpm/common/taskform.jsf 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:_id30]=e 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:_link_hidden_]= 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:_id28]=e 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:taskInstanceId]=246 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:_id26]=e 01:53:40,062 DEBUG [LogFilter] request parameter [taskform_SUBMIT]=1 01:53:40,062 DEBUG [LogFilter] request parameter [taskform:transitionButton]=Save and Close Task 01:53:40,062 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/com mon/taskform.xhtml]=[Ljava.lang.Object;@12ad974 01:53:40,062 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/taskreassign.xhtml]=[Ljava.lang.Object;@13214d1 01:53:40,062 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/manager/home.xhtml]=[Ljava.lang.Object;@1b3d448 01:53:40,078 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/login.xhtml]=[Ljava.lang.Object;@1fac7cf 01:53:40,078 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/administrator/home.xhtml]=[Ljava.lang.Object;@7a8ba4 01:53:40,078 DEBUG [JbpmPhaseListener] after phase RESTORE_VIEW(1) 01:53:40,078 DEBUG [JbpmPhaseListener] after phase APPLY_REQUEST_VALUES(2) 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [TaskInstanceVariableMap] no task instance was set so returning null 01:53:40,078 DEBUG [JbpmPhaseListener] after phase PROCESS_VALIDATIONS(3) 01:53:40,078 DEBUG [TaskBean] selecting task instance 246 01:53:40,078 DEBUG [JbpmContextInfo] creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]' 01:53:40,078 DEBUG [JbpmContext] creating JbpmContext 01:53:40,078 DEBUG [DbPersistenceServiceFactory] creating persistence service 01:53:40,078 DEBUG [DbPersistenceService] creating hibernate session 01:53:40,078 DEBUG [DbPersistenceService] beginning hibernate transaction 01:53:40,171 DEBUG [TaskInstanceVariableMap] initializing task instance in variables map 01:53:40,171 DEBUG [TaskInstanceVariableMap] setting task variable 'item' to 'e' 01:53:40,171 DEBUG [TaskInstanceVariableMap] setting task variable 'quantity' to 'e' 01:53:40,171 DEBUG [TaskInstanceVariableMap] setting task variable 'address' to 'e' 01:53:40,171 DEBUG [JbpmPhaseListener] after phase UPDATE_MODEL_VALUES(4) 01:53:40,171 DEBUG [TaskBean] saving the task parameters org.jbpm.webapp.bean.TaskInstanceVariableMap@1aa9b4d 01:53:40,171 DEBUG [TaskBean] saving variable 'item': e 01:53:40,562 DEBUG [VariableContainer] variable type change. deleting 'item' from 'TaskInstance[Create new web sale order]' 01:53:40,562 DEBUG [VariableContainer] create variable 'item' in 'TaskInstance[Create new web sale order]' with value 'e' 01:53:40,562 DEBUG [TaskBean] saving variable 'address': e 01:53:40,562 DEBUG [VariableContainer] variable type change. deleting 'address' from 'TaskInstance[Create new web sale order]' 01:53:40,562 DEBUG [VariableContainer] create variable 'address' in 'TaskInstance[Create new web sale order]' with value 'e' 01:53:40,562 DEBUG [TaskBean] saving variable 'quantity': e 01:53:40,562 DEBUG [VariableContainer] variable type change. deleting 'quantity' from 'TaskInstance[Create new web sale order]' 01:53:40,562 DEBUG [VariableContainer] create variable 'quantity' in 'TaskInstance[Create new web sale order]' with value 'e' 01:53:40,562 DEBUG [Services] executing default save operations 01:53:40,562 DEBUG [HibernateSaveOperation] saving process instance 01:53:40,562 DEBUG [SaveLogsOperation] flushing logs to logging service. 01:53:41,296 DEBUG [CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@2ed1e8' 01:53:41,296 DEBUG [TaskBean] Submitted button:default 01:53:41,312 WARN [StatefulPersistenceContext] Narrowing proxy to class org.jbpm.graph.node.StartState - this operation breaks == 01:53:41,312 DEBUG [GraphElement] event 'task-end' on 'Task(Create new web sale order)' for 'Token(/)' 01:53:41,375 DEBUG [TaskController] submitting task variable 'item' to process variable 'item', value 'e' 01:53:41,375 DEBUG [VariableContainer] create variable 'item' in 'TokenVariableMap13e6577' with value 'e' 01:53:41,375 DEBUG [TaskController] submitting task variable 'quantity' to process variable 'quantity', value 'e' 01:53:41,375 DEBUG [VariableContainer] create variable 'quantity' in 'TokenVariableMap13e6577' with value 'e' 01:53:41,375 DEBUG [TaskController] submitting task variable 'address' to process variable 'address', value 'e' 01:53:41,375 DEBUG [VariableContainer] create variable 'address' in 'TokenVariableMap13e6577' with value 'e' 01:53:41,375 DEBUG [TaskInstance] completion of task 'Create new web sale order' results in taking the default transition 01:53:41,390 DEBUG [GraphElement] event 'before-signal' on 'StartState(Create new web sale order)' for 'Token(/)' 01:53:41,390 DEBUG [GraphElement] event 'node-leave' on 'StartState(Create new web sale order)' for 'Token(/)' 01:53:41,390 DEBUG [GraphElement] event 'transition' on 'Transition(66db4e)' for 'Token(/)' 01:53:41,390 DEBUG [GraphElement] event 'node-enter' on 'TaskNode(Evaluate web order)' for 'Token(/)' 01:53:41,390 WARN [StatefulPersistenceContext] Narrowing proxy to class org.jbpm.graph.node.TaskNode - this operation breaks == 01:53:41,531 DEBUG [TaskController] creating task instance variable 'item' from process variable 'item', value 'e' 01:53:41,531 DEBUG [VariableContainer] create variable 'item' in 'TaskInstance[Evaluate web order]' with value 'e' 01:53:41,531 DEBUG [TaskController] creating task instance variable 'quantity' from process variable 'quantity', value 'e' 01:53:41,531 DEBUG [VariableContainer] create variable 'quantity' in 'TaskInstance[Evaluate web order]' with value 'e' 01:53:41,531 DEBUG [TaskController] creating task instance variable 'address' from process variable 'address', value 'e' 01:53:41,531 DEBUG [VariableContainer] create variable 'address' in 'TaskInstance[Evaluate web order]' with value 'e' 01:53:41,531 DEBUG [TaskController] creating task instance variable 'comment' from process variable 'comment', value 'null' 01:53:41,531 DEBUG [VariableContainer] create variable 'comment' in 'TaskInstance[Evaluate web order]' with value 'null' 01:53:41,531 DEBUG [GraphElement] event 'task-create' on 'Task(Evaluate web order)' for 'Token(/)' 01:53:41,531 DEBUG [GraphElement] executing action 'CreateTimerAction(fc63be)' 01:53:41,531 DEBUG [GraphElement] event 'timer-create' on 'Task(Evaluate web order)' for 'Token(/)' 01:53:41,734 DEBUG [ExpressionAssignmentHandler] resolving first term 'user(ernie)' 01:53:42,375 DEBUG [TaskInstance] assigning task 'Evaluate web order' to 'ernie' 01:53:42,375 DEBUG [GraphElement] event 'task-assign' on 'Task(Evaluate web order)' for 'Token(/)' 01:53:42,375 DEBUG [GraphElement] event 'after-signal' on 'StartState(Create new web sale order)' for 'Token(/)' 01:53:42,375 DEBUG [Services] executing default save operations 01:53:42,375 DEBUG [HibernateSaveOperation] saving process instance 01:53:42,375 DEBUG [SaveLogsOperation] flushing logs to logging service. 01:53:44,296 DEBUG [CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@2ed1e8' 01:53:44,296 DEBUG [TaskBean] assignmentlogs: [task-assign[ernie,TaskInstance[Evaluate web order]]] 01:53:44,296 DEBUG [JbpmPhaseListener] after phase INVOKE_APPLICATION(5) 01:53:44,296 DEBUG [JbpmPhaseListener] starting new transaction for the rendering phase 01:53:44,296 DEBUG [DbPersistenceService] committing hibernate transaction 01:53:47,093 DEBUG [DbPersistenceService] beginning hibernate transaction 01:53:47,109 DEBUG [LogFilter] request http://127.0.0.1:8080/jbpm/participant/home.jsf 01:53:47,109 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/taskreassign.xhtml]=[Ljava.lang.Object;@13214d1 01:53:47,109 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/manager/home.xhtml]=[Ljava.lang.Object;@1b3d448 01:53:47,109 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/common/login.xhtml]=[Ljava.lang.Object;@1fac7cf 01:53:47,109 DEBUG [LogFilter] session parameter [org.apache.myfaces.application.jsp.JspStateManagerImpl.SERIALIZED_VIEW-/administrator/home.xhtml]=[Ljava.lang.Object;@7a8ba4 01:53:47,109 DEBUG [JbpmPhaseListener] after phase RESTORE_VIEW(1) 01:53:47,109 DEBUG [JbpmContextInfo] creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]' 01:53:47,109 DEBUG [JbpmContext] creating JbpmContext 01:53:47,109 DEBUG [DbPersistenceServiceFactory] creating persistence service 01:53:47,109 DEBUG [DbPersistenceService] creating hibernate session 01:53:47,109 DEBUG [DbPersistenceService] beginning hibernate transaction 01:53:51,828 DEBUG [JbpmPhaseListener] after phase RENDER_RESPONSE(6) 01:53:51,828 DEBUG [JbpmContext] closing JbpmContext 01:53:51,828 DEBUG [Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1e74fe9 01:53:51,828 DEBUG [DbPersistenceService] committing hibernate transaction 01:53:51,859 DEBUG [DbPersistenceService] closing hibernate session 01:53:51,859 DEBUG [Services] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@1788551
I see all these actions are DB related and my DB is not running locally, but at the other end of a 2Mbit ADSL line. So that would account for some delay, but this high? I'll do another run tomorrow with hibernate debugging on to see if I can pinpoint it a little.
