This article is in continuation of previous two articles (here and here) in this series and talks about other metrics captured as part of IWS reports. We will use the IWS reports generated in the previous articles (refer Resources section at the end).
Let's take this opportunity to introduce other parts of the report and highlight how they can be useful.
Backlogs can build for asynchronous flows in a composite. For example for asynchronous BPEL process the incoming message is first stored in a database before processing. Due to issues in downstream processing or incorrect configurations backup can build. Note that currently only BPEL and EDN is supported.
The Test 2 execution spanned two snapshots (snapshot interval of 5 mins). We generated IWS report for entire test. If we generate report while the test is running you can see backlogs in BPEL engine internal queue. Here is except from the report generated for 12/10/15 1:22:00 PM and 12/10/15 1:32:00 PM
Section 2 of the report shows the backlogs for the entire composite.
Section 4 shows the backup breakdown per component basis and should be referred if large backlogs are shown for the composite (under section 2 of report)
With IWS configured to BASIC level or above IWS will start collecting information about BPEL Processes. Section 5 of the report lists provides useful details about the synchronous and asynchronous business process such as counts of instances started, completed and faulted and average execution times.
For Asynchronous BPEL processes additional information such as dehydration/redydration counts, dehydration time and callback processing time is also provided.
Reviewing the process data for Test 2 and comparing again the benchmark it is clear that the Asynchronous BPEL Process which makes invocation to external web service is taking much longer to complete (about 40 secs compared to 1 sec). Note that this Asynchronous process also calls the synchronous sub-process but the execution time for Test 2 is comparable to benchmark period so synchronous process is not contributing to performance degradation.
At NORMAL collection level stats such as start, completed, fault counts and execution times for key BPEL activities such as Receive, Invoke and On-Message will be collected and displayed in the report. If you want information about all BPEL activities including Assign etc set the IWS collection at FINEST level. This information is shown on Section 6 of the report.
Reviewing the BPEL activities for Test 2 it is clear that Invoke2 activity which represent call to external service is taking on average about 41 secs as opposed to about 1 sec. So, clearly this activity is causing the BPEL Process to slow down. Tracking this activity to the external adapter and noting the latency (section 3B - Outbound Endpoints) establishes the root cause of the issue.
Section 3C of the report lists the Wire Stats. This provides information about message flow of messages as seen on composite wires. The stats include message counts and latency information. The latency value as shown is the average time time taken by the thread to return as measured at the wires. This stat is particularly valuable to identify and isolate slow components inside composite.
Reviewing the wire stats for Test 2 reveals that the latency recorded at the wire connecting the BPEL invoke to web service binding adapter indicate latency of around 41 secs as opposed to about 1 sec for the corresponding wire for benchmark.
IWS report provide valuable data points that can help simplify the analysis by providing the information for entire system in single report. It provides ability to go back in time and analyze issues reported.
In last installment of this series I will cover the remaining topics share some inner details of IWS design and architecture.