Author |
Message
|
shalabh1976 |
Posted: Tue Jun 17, 2003 9:02 am Post subject: Performance comparisons of nodes |
|
|
 Partisan
Joined: 18 Jul 2002 Posts: 381 Location: Gurgaon, India
|
We did some user traces for the transactions running on z/OS and it did come up with some wierd results.
There apeared to be significant time variations for the same node for different transactions in the order of thousands.
This appears to be surprising and we think this may be due to the no of machine cycles alloted to the process at the given time.
Has anybody some other views ?
Also the flow order node consistently came out as an expensive node.
While compute nodes took something in the range of 0.001 sec, for the same transaction a flow order came up with 0.24 sec .
Can anybody explain/help ?
P.S. :Database nodes turned out to be much faster than expected(0.0003 sec). |
|
Back to top |
|
 |
kirani |
Posted: Tue Jun 17, 2003 8:13 pm Post subject: |
|
|
Jedi Knight
Joined: 05 Sep 2001 Posts: 3779 Location: Torrance, CA, USA
|
May I know how are you measuring this timing?
In case of FlowOrder node, what is your criteria for Start and End Time?
What processing are you doing in the first and second terminal of the floworder node?
Take a look at performance supportPac which gives more insight on the performance of each node. _________________ Kiran
IBM Cert. Solution Designer & System Administrator - WBIMB V5
IBM Cert. Solutions Expert - WMQI
IBM Cert. Specialist - WMQI, MQSeries
IBM Cert. Developer - MQSeries
|
|
Back to top |
|
 |
shalabh1976 |
Posted: Wed Jun 18, 2003 8:06 am Post subject: |
|
|
 Partisan
Joined: 18 Jul 2002 Posts: 381 Location: Gurgaon, India
|
Kiran,
We ran a user trace which gave us the time the message left the flow.
So if you subtract the time it left the previous node you get the time spent in any node.
The wide variations in the performance of many nodes has opened up a pandora's box and a lot of research is going into it now.
The matter has been raised with hursley and further disscussions are on.
Theoretically, since a flow order node has no code it should not take any time but is the trace showing the time taken to process the first branch of the flow order node ?
We added those and it still did not match the time taken in the flow order
node.
Is there something in MQSI internals we don't know about ? |
|
Back to top |
|
 |
Craig B |
Posted: Wed Jun 18, 2003 9:39 am Post subject: |
|
|
Partisan
Joined: 18 Jun 2003 Posts: 316 Location: UK
|
Hi,
From your last update it would seem that you are tracing the flow with the -l normal option which does not add too much overhead on to the flow and shows how long is take in each node. Would it be possible to insert a small extract of the normal level trace to show the timings you have for the FlowOrder node, Database nodes and compute nodes. _________________ Regards
Craig |
|
Back to top |
|
 |
shalabh1976 |
Posted: Wed Jun 18, 2003 1:52 pm Post subject: |
|
|
 Partisan
Joined: 18 Jul 2002 Posts: 381 Location: Gurgaon, India
|
Here it is :
2003-06-13 10:13:21.842608 23 UserTrace BIP4124I: Message propagated to 'out' terminal of compute node 'Common_Initial_Routing.DETERMINE.ROUTE'.
2003-06-13 10:13:21.842944 23 UserTrace BIP4241I: Message propagated to target Label node by RouteToLabel node 'Common_Initial_Routing.RouteToLabel1'.
A RouteToLabel node has received a message and is propagating it to the appropriate Label node.
No user action required.
2003-06-13 10:13:21.843040 23 UserTrace BIP4220I: Message propagated to out terminal from node 'Common_Initial_Routing.FCD.REQUEST'.
A label node has received a message and is propagating it to any nodes connected to its out terminal.
No user action required.
2003-06-13 10:13:21.843136 23 UserTrace BIP4160I: Message propagated to match terminal by check node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.FlowOrder'.
The check node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.FlowOrder' has matched a received message against the criteria and is propagating it to any nodes connected to its match terminal.
No user action required.
2003-06-13 10:13:21.874544 23 UserTrace BIP4124I: Message propagated to 'out' terminal of compute node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.DPHeader&ATSHeader.Processing'.
2003-06-13 10:13:21.878320 23 UserTrace BIP4201I: Message propagated to out terminal from node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.ResetContentDescriptor1'.
A reset content descriptor node has received a message and is propagating it to any nodes connected to its out terminal.
No user action required.
2003-06-13 10:13:21.879088 23 UserTrace BIP4124I: Message propagated to 'out' terminal of compute node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.Assignment2EnvironmentVariable'.
2003-06-13 10:13:21.879296 23 UserTrace BIP4160I: Message propagated to match terminal by check node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.FlowOrder'.
The check node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.FlowOrder' has matched a received message against the criteria and is propagating it to any nodes connected to its match terminal.
No user action required.
2003-06-13 10:13:22.153088 23 UserTrace BIP4124I: Message propagated to 'out' terminal of compute node 'Common_Initial_Routing.MQSI.XML2FCD01.HF1.MQSIFINCOM01_021.XML2FCD.Convert'.
2003-06-13 10:13:22.153248 23 UserTrace BIP4160I: Message propagated to match terminal by check node 'Common_Initial_Routing.Common_Log_Message2.FlowOrder1'.
The check node 'Common_Initial_Routing.Common_Log_Message2.FlowOrder1' has matched a received message against the criteria and is propagating it to any nodes connected to its match terminal.
No user action required.
2003-06-13 10:13:22.154064 23 UserTrace BIP4124I: Message propagated to 'out' terminal of compute node 'Common_Initial_Routing.Common_Log_Message2.Set Properties for Log'.
2003-06-13 10:13:22.154816 23 UserTrace BIP2638I: The MQ output node 'Common_Initial_Routing.Common_Log_Message2.TLR.MQI.LOG' attempted to write a message to the specified queue 'TLR.MQI.LOG' connected to queue manager ''. The MQCC was 0 and the MQRC was 0. |
|
Back to top |
|
 |
Craig B |
Posted: Wed Jun 18, 2003 10:51 pm Post subject: |
|
|
Partisan
Joined: 18 Jun 2003 Posts: 316 Location: UK
|
As you indicated in your first update, from the normal trace the execution time of each node can be calculated. Each line shows the propagation OUT of a node from one of its terminals, and so for each line that is the time that the flow left that particular node. So if the time on the line before is subtracted then that gives the total time for the current Node (current line of the trace being looked at). Looking at the extract of the trace then this gives the following node times. The first coimpute node in the trace extract we do not have an execution time for since we do not have the previous time to perform a calculation. Therefore in the table this has 'time N/A' since the time is not available.
For the flow Common_Initial_Routing :
time N/A : Compute node : 'DETERMINE.ROUTE'.
0.000336 : RouteToLabel node : 'RouteToLabel1'.
0.000096 : Label node : 'FCD.REQUEST'.
0.000096 : FlowOrder node : 'MQSI.XML2FCD01.HF1.FlowOrder'. First Path
0.031408 : Compute node : 'MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.DPHeader&ATSHeader.Processing'.
0.003776 : RCD node : 'MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.ResetContentDescriptor1'.
0.000768 : Compute node : 'MQSI.XML2FCD01.HF1.COMMON_DP&ATSHeader_Processing1.Assignment2EnvironmentVariable'.
0.000208 : FlowOrder node : 'MQSI.XML2FCD01.HF1.FlowOrder'. Second Path
0.273792 : Compute node : 'MQSI.XML2FCD01.HF1.MQSIFINCOM01_021.XML2FCD.Convert'.
0.000160 : FlowOrder node : 'Common_Log_Message2.FlowOrder1'. First Path
0.000816 : Compute node : 'Common_Log_Message2.Set Properties for Log'.
0.000797 : MQ output node : 'Common_Log_Message2.TLR.MQI.LOG'
This shows that the two compute nodes that we have times for are the most expensive nodes in this flow, with the most expensive being MQSI.XML2FCD01.HF1.MQSIFINCOM01_021.XML2FCD.Convert at 0.273792 seconds execution time. _________________ Regards
Craig |
|
Back to top |
|
 |
|