Troubleshooting WebSphere Message Broker / IBM Integration Bus production issues using statistics gathering

Let’s imagine situation in production or ramp up bench test environment, while particular message flow takes too much time to process messages. One of the ways to cope with this situation is nothing but to gather execution statistics and then figure out the bottlenecks using collected data.

Collecting message flow statistics

IIB message flow statistics records dynamic information about runtime behavior of chosen message flow. Statistics provides information at the message flow, thread, node and terminal level

Thus flow performance can be measured and different places of processing can be compared in terms of performance. It is to underline that no code or properties changes nor redeployment needed to request statistics collection.

The message flow statistics are enabled using command “mqsichangeflowstats” or via Integration Explorer GUI. The output available in user trace, XML publication message or SMF117 records on z/OS

In concrete terms, we create test message flow that takes SWIFT payment message MT103 process it trough 3 almost identical ESQL compute nodes and put in the output queue.

The picture depicts 3 nodes with the code as follows:

CREATE COMPUTE MODULE ABNAMRO_MF_Compute1

CREATE FUNCTION Main() RETURNS BOOLEAN

BEGIN

CALL CopyMessageHeaders();

CALL CopyEntireMessage();

RETURN TRUE;

END;

CREATE PROCEDURE CopyMessageHeaders() BEGIN

DECLARE I INTEGER 1;

DECLARE J INTEGER;

SET J = CARDINALITY(InputRoot.*[]);

WHILE I < J DO

SET OutputRoot.*[I] = InputRoot.*[I];

SET I = I + 1;

END WHILE;

END;

CREATE PROCEDURE CopyEntireMessage() BEGIN

SET OutputRoot = InputRoot;

END;

END MODULE;

The only difference for the node compute2 is additional looping in CopyEntireMessage ordr aimed to simulate higher load :

CREATE PROCEDURE CopyEntireMessage() BEGIN

DECLARE I INTEGER 1;

DECLARE J INTEGER 500 ;

DECLARE K INTEGER 1;

– Just to slow down processing

WHILE I < J DO

SET K = CARDINALITY(InputRoot.*[]);

SET I = I + 1;

END WHILE;

SET OutputRoot = InputRoot;

END;

We create 2 MQ queues (ABNAMRO.IN and ABNAMRO.OUT) on Queue Manager of the broker BRKLOC01.

Then we deploy the app on BRKLOC01:

The MT103 test message below:

Single Customer Credit Transfer with Direct Account Relationship. Moneylaundering G.m.b.H. orders UBS, Zürich, to pay euro 51,958.47 to ABN Amro Bank, Amsterdam, for the account of J. van der Wal.

{1:F01UBSWCHZH80AXXX1234000123}{2:I103ABNANL2AXXXXN}{3:{103:TGT}{113:NNNN}}{4:

:20:494931/DEV

:23B:CRED

:32A:030828EUR51958,47

:33B:EUR51958,47

:50K:MONEYLAUNDERING GMBH

ZURICH

:59:/502664959

J. VAN DER WAL LEDEBOERSTRAAT 27

AMSTERDAM

:71A:SHA

-}

We use the batch script below in order to send multiple messages for testing :

ECHO OFF

set start=%time%

:: runs your command

FOR /L %%A IN (1,1,10) DO (

REM ECHO %%A

call “C:\Program Files (x86)\IBM\WebSphere MQ\bin\amqsput.exe” ABNAMRO.IN QLWSRV2008R2X64VL1 < MT103.txt

call “C:\Program Files (x86)\IBM\WebSphere MQ\bin\amqsget.exe” ABNAMRO.OUT QLWSRV2008R2X64VL1 < MT103.txt

)

set end=%time%

set options=”tokens=1-4 delims=:.”

for /f %options% %%a in (“%start%”) do set start_h=%%a&set /a start_m=100%%b %% 100&set /a start_s=100%%c %% 100&set /a start_ms=100%%d %% 100

for /f %options% %%a in (“%end%”) do set end_h=%%a&set /a end_m=100%%b %% 100&set /a end_s=100%%c %% 100&set /a end_ms=100%%d %% 100

set /a hours=%end_h%-%start_h%

set /a mins=%end_m%-%start_m%

set /a secs=%end_s%-%start_s%

set /a ms=%end_ms%-%start_ms%

if %hours% lss 0 set /a hours = 24%hours%

if %mins% lss 0 set /a hours = %hours% – 1 & set /a mins = 60%mins%

if %secs% lss 0 set /a mins = %mins% – 1 & set /a secs = 60%secs%

if %ms% lss 0 set /a secs = %secs% – 1 & set /a ms = 100%ms%

if 1%ms% lss 100 set ms=0%ms%

:: mission accomplished

set /a totalsecs = %hours%*3600 + %mins%*60 + %secs%

echo command took %hours%:%mins%:%secs%.%ms% (%totalsecs%.%ms%s total)

Sample command to start collection of statistics for a specific message flow

mqsichangeflowstats <Broker> -s -e <EGName> -f <Message flow> -c active -t basic -n advanced -o usertrace

In our case it’s :

mqsichangeflowstats BRKLOC01 -s -e Z_UDEPLOY -k ABNAMRO_APP -f ABNAMRO_MF -c active -t basic -n advanced -o usertrace

(Here the k option is for application, the new concept of IIB 9)

This command enables the broker to produce accounting and statistics information for the specified message flow. The information produced will contain basic threadData and advanced nodeData.

As soon as the statistics gathering is enabled we will run load.bat script :

message <-}>

no more messages

Sample AMQSGET0 end

Sample AMQSPUT0 start

target queue is ABNAMRO.IN

Sample AMQSPUT0 end

Sample AMQSGET0 start

message <{1:F01UBSWCHZH80AXXX1234000123}{2:I103ABNANL2AXXXXN}{3:{103:TGT}{113:NN

NN}}{4:>

message <:20:494931/DEV>

message <:23B:CRED>

message <:32A:030828EUR51958,47>

message <:33B:EUR51958,47>

message <:50K:MONEYLAUNDERING GMBH>

message <ZURICH>

message <:59:/502664959>

message <J. VAN DER WAL LEDEBOERSTRAAT 27>

message <AMSTERDAM>

message <:71A:SHA>

message <-}>

no more messages

Sample AMQSGET0 end

command took 0:2:31.72 (151.72s total)

C:\SVNL\ws8\IIBSTATSTEST>

The accounting and statistics information generated will be written to a user trace, hence will need to be formatted using commands as follows:

mqsireadlog <Broker> -u -e <EGName> -f –o trace.xml

mqsiformatlog -i trace.xml -o trace.log

or :

mqsireadlog BRKLOC01 -u -e Z_UDEPLOY -f -o trace.xml

Then formatting :

mqsiformatlog -i trace.xml -o trace.log

The command to stop producing the above accounting and statistics information is as follows:

mqsichangeflowstats <Broker> -s -e <EGName> -f <Message flow> -c inactive -t basic -n advanced -o usertrace

A re-deploy of the message flow with automatically cancel accounting and statistics on that flow.

The formatted trace fragment is as follows:

2015-03-19 21:38:19.404002 6936 UserTrace BIP2382I: IIB node statistics.

ProcessID=’6824′,

Key=’0′,

Label=”Compute3”,

Type=”ComputeNode”,

TotalElapsedTime=’2275′,

MaximumElapsedTime=’0′,

MinimumElapsedTime=’0′,

TotalCPUTime=’22′,

MaximumCPUTime=’0′,

MinimumCPUTime=’0′,

CountOfInvocations=’0′,

NumberOfInputTerminals=’1′,

NumberOfOutputTerminals=’6′.

Statistical information for node ”Compute3”.

This is an information message produced by IIB statistics.

Or there is a way to get visual representation of the statistics in the IIB Explorer:

Looking on the chart it becomes obvious that the bottleneck is the node 2:

Integration Node BRKLOC01
Integration Server Z_UDEPLOY
Flow ABNAMRO_MF
Label Type TotalElapsedTime
Compute1 ComputeNode 4175
Compute2 ComputeNode 7967
Compute3 ComputeNode 2275
MQ Input MQInputNode 2399
MQ Output MQOutputNode 3999

Leave a Reply

You must be logged in to post a comment.



 
       
iBudget    |   No More Money Falling Through Your Fingers        Home page
Popular Posts

Sorry. No data so far.

 
App store
Available on the iPhone
 
    Why Using Feedburner in Blogs Is So Important?