| Author |
Message
|
| nelson |
 Posted: Fri Oct 14, 2016 8:32 am Post subject: Slow flow deployment/start up |
 |
|
Partisan
Joined: 02 Oct 2012
Posts: 313
|
Hi all,
Working on IIB 9.0.0.6.
What could be the cause that a flow takes about 2-3 minutes to start up? We have tested the scenario with different flows and the situation is particular to flows that call a WS (MQ Input -> Compute -> SOAPRequest -> Compute - MQOutput). We tested deploying the flow in a blank EG and the start up time is the same. The same happens when deploying these flows (2-3 minutes to deploy). The non-WS flows don't present the issue.
Another fact is that the EG process when deploying/starting uses the 80%-90% server CPU during these 2-3 minutes.
Any idea?
Thanks in advance for your help. |
|
| Back to top |
|
 |
| mqjeff |
| Posted: Fri Oct 14, 2016 8:48 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
A user trace should help.
_________________
chmod -R ugo-wx / |
|
| Back to top |
|
|
| nelson |
| Posted: Fri Oct 14, 2016 10:11 am Post subject: |
|
|
Partisan
Joined: 02 Oct 2012
Posts: 313
|
| mqjeff wrote: |
| A user trace should help. |
During the deployment there is a difference of near three minutes between two instructions (while creating the SOAPRequest subflow). I separated the two instructions for clearness.
I see some WARNING's and after that (three minutes later) the flow is successfully created.
Any idea?
| Code: |
2016-10-14 13:49:26.400384 4885 UserTrace BIP2632I: Message received and propagated to 'out' terminal of MQ input node '.InputNode'.
2016-10-14 13:49:26.400548 4885 UserTrace BIP6060I: Node '.InputNode' used parser type ''Properties'' to process a portion of the incoming message of length '0' bytes beginning at offset '0'.
2016-10-14 13:49:26.400576 4885 UserTrace BIP6061I: Node '.InputNode' used parser type ''MQMD'' to process a portion of the incoming message of length '364' bytes beginning at offset '0'. The parser type was selected based on value ''MQHMD'' from the previous parser.
2016-10-14 13:49:26.405456 4885 UserTrace BIP6061I: Node '.InputNode' used parser type ''XMLS'' to process a portion of the incoming message of length '1021199' bytes beginning at offset '364'. The parser type was selected based on value ''XMLS'' from the previous parser.
2016-10-14 13:49:26.434688 4885 Information BIP2152I: Configuration message received from broker.
An execution group received a command from the Broker.
No user action required.
2016-10-14 13:49:26.434804 4885 Information BIP2153I: About to ''Change'' an execution group.
An execution group is about to perform an action.
No user action required.
2016-10-14 13:49:26.450916 4885 Information BIP2155I: About to ''create '' the deployed resource ''MYLIB'' of type ''library''.
An execution group is about to perform an action.
No user action required.
2016-10-14 13:49:26.481978 4885 UserTrace BIP2264I: Deployed resource ''MYLIB'' (uuid=''741750c4-5701-0000-0080-e1b8959c2202'', type=''.LIBZIP'') successfully created.
The message broker received a configuration message containing an instruction to create the deployed resource ''BHDOnline'' (uuid=''741750c4-5701-0000-0080-e1b8959c2202'', type=''.LIBZIP''), and successfully performed this action.
No user action required.
2016-10-14 13:49:27.160312 4885 Information BIP2155I: About to ''create '' the deployed resource ''mysubflow1'' of type ''.SUBFLOW''.
An execution group is about to perform an action.
No user action required.
2016-10-14 13:49:27.168978 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPActionBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.169172 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.169584 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPMessageBodyBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.169774 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.170226 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPActionBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.170406 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.170730 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPMessageBodyBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:49:27.170862 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.309062 4885 UserTrace BIP2264I: Deployed resource ''mysubflow1'' (uuid=''mysubflow1'', type=''.SUBFLOW'') successfully created.
The message broker received a configuration message containing an instruction to create the deployed resource ''mysubflow1'' (uuid=''mysubflow1'', type=''.SUBFLOW''), and successfully performed this action.
No user action required.
2016-10-14 13:52:14.330497 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPActionBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.330670 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.330997 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPMessageBodyBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.331126 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.331453 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPActionBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.331582 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.331752 4885 UserTrace BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPMessageBodyBasedDispatcher is now deprecated.''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.331880 4885 UserTrace BIP3487W: ''Please edit axis2.xml and replace with the same class in org.apache.axis2.dispatchers package''
An embedded component has written the 'WARNING' level diagnostic message included here.
Refer to the appropriate message in the embedded component's documentation.
2016-10-14 13:52:14.344860 4885 Information BIP2155I: About to ''create '' the deployed resource ''myflow'' of type ''.MSGFLOW''.
An execution group is about to perform an action.
No user action required.
2016-10-14 13:52:14.351789 4885 UserTrace BIP2264I: Deployed resource ''myflow'' (uuid=''251950c4-5701-0000-0080-e1b8959c2202'', type=''.MSGFLOW'') successfully created.
The message broker received a configuration message containing an instruction to create the deployed resource ''myflow'' (uuid=''251950c4-5701-0000-0080-e1b8959c2202'', type=''.MSGFLOW''), and successfully performed this action.
No user action required.
2016-10-14 13:52:37.418868 4885 UserTrace BIP4040I: The Execution Group ''myEG'' has processed a configuration message successfully.
A configuration message has been processed successfully. Any configuration changes have been made and stored persistently.
No user action required.
2016-10-14 13:52:37.419660 4885 UserTrace BIP2638I: The MQ output node '.outputNode' attempted to write a message to queue ''SYSTEM.BROKER.EXECUTIONGROUP.REPLY'' connected to queue manager ''myMQGR''. The MQCC was '0' and the MQRC was '0'.
2016-10-14 13:52:37.419672 4885 UserTrace BIP2622I: Message successfully output by output node '.outputNode' to queue ''SYSTEM.BROKER.EXECUTIONGROUP.REPLY'' on queue manager ''myMQGR''.
2016-10-14 13:52:37.419856 4885 Information BIP2154I: Execution group finished with Configuration message.
A command response will be sent to the broker.
No user action required. |
|
|
| Back to top |
|
|
| mqjeff |
| Posted: Fri Oct 14, 2016 10:29 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
How big is the WSDL?
_________________
chmod -R ugo-wx / |
|
| Back to top |
|
|
| nelson |
| Posted: Fri Oct 14, 2016 10:54 am Post subject: |
|
|
Partisan
Joined: 02 Oct 2012
Posts: 313
|
| mqjeff wrote: |
| How big is the WSDL? |
11 KB |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Fri Oct 14, 2016 11:02 am Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20756
Location: LI,NY
|
Are you trying to deploy a bar file that was created for a prior version of the broker? (hint the warning about the deprecated class reference).
_________________
MQ & Broker admin |
|
| Back to top |
|
|
| nelson |
| Posted: Mon Oct 17, 2016 8:08 pm Post subject: |
|
|
Partisan
Joined: 02 Oct 2012
Posts: 313
|
| fjb_saper wrote: |
| Are you trying to deploy a bar file that was created for a prior version of the broker? (hint the warning about the deprecated class reference). |
In fact, deployed the BAR in a previous version (Toolkit version) and works fine... Even though it seems to me a very weird behavior, the logs says it's doing "nothing" during near two minutes... |
|
| Back to top |
|
|
| Vitor |
| Posted: Tue Oct 18, 2016 4:37 am Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
| nelson wrote: |
| In fact, deployed the BAR in a previous version (Toolkit version) and works fine... |
I agree with my worthy associate. I think it's chewing on that depreciated class and, for some reason, this makes it contemplate the infinite for a few minutes before continuing. If a gun was put to my head (which usually means the business users have had another brilliant idea they want to implement in my beautiful brokers) I'd theorize that it's waiting for some kind of classloading dohicky which is timing out after a few minutes.
Rebuild the bar in the latest version.
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
| Craig B |
| Posted: Wed Oct 19, 2016 7:17 am Post subject: |
|
|
Partisan
Joined: 18 Jun 2003
Posts: 316
Location: UK
|
If the deploy was doing any classloading then I would expect to see BIP4397I messages in the trace indicating what classes it was loading and where it was getting them from.
Interestingly the BIP3487W: ''Dispatcher org.apache.axis2.engine.SOAPActionBasedDispatcher" seem to be related to the Axis2 engine that the brokers SOAP functionality uses. This is referenced in the Axis2 config file that is shipped with the Broker.
Usually a deploy will go "silent" while it is in its prepare phase of the deploy transaction. But the fact your gap is following by the creation of a subflow means it is still in the create phase. The deploy order of any BAR contents is:
1) File based deployed resources
2) Subflosw
3) Flows
So the three map gap is while its processing resources like WSDL, Schemas, JAR files etc.
If I had your BAR file or had a service trace for this then I could tell you exactly where the time is being spent and why.
_________________
Regards
Craig |
|
| Back to top |
|
|
| nelson |
| Posted: Wed Nov 02, 2016 12:21 pm Post subject: |
|
|
Partisan
Joined: 02 Oct 2012
Posts: 313
|
Thanks all for your comments.
I finally discovered that another WSDL within the library with about 700 operations is causing the slow behavior. The SOAPRequest node seems to triggers an entire WS schema files validation during the deployment/start up, since the SOAPRequest is not referencing that WSDL. If we remove that WSDL from the library or comment some operations the deployment is fast. |
|
| Back to top |
|
|
|
|
