App Connect

App Connect

Join this online user group to communicate across IBM product users and experts by sharing advice and best practices with peers and staying up to date regarding product enhancements.


#Applicationintegration
#App Connect
#AppConnect
#Integration
#Automation
 View Only

Detecting and Diagnosing Message Flow Hangs and Performance Issues in IBM App Connect Enterprise with processingTimeoutAction=logWarning

By JAMES JOSE posted 13 days ago

  

IBM App Connect Enterprise (ACE) provides a Workload Management (WLM) policy mechanism that allows administrators to define a processing timeout for message flows. When a flow thread exceeds the configured timeout, ACE performs the action specified by the processingTimeoutAction property. Previously, the primary action available for handling a timeout was restartExecutionGroup, which restarts the integration server. While restarting the server can help recover from a completely hung flow, it can be disruptive when the flow is experiencing a temporary delay or performance degradation.

Starting with ACE V13.0.9.0, a new logWarning option provides a non-disruptive alternative. Instead of restarting the integration server, ACE writes a warning to the local error log (syslog on Linux/AIX, Windows Event Log on Windows) when a flow thread exceeds the configured processing timeout. The integration server and its other flows continue running. This provides an early indication of both message flow performance degradation and potentially hung transactions, while allowing administrators to investigate the underlying cause without immediately disrupting the integration server.

When to use logWarning
Use logWarning when you want to monitor message flow processing time and identify flows that exceed an expected processing threshold without automatically restarting the integration server. It can be particularly useful for detecting flows that are taking longer than expected, identifying potential back-end performance problems, detecting flow threads that remain blocked for an extended period, correlating timeout events with activity log and Flow Thread Reporter data, and investigating performance issues without interrupting other flows running in the integration server.


1. Background — The WLM Processing Timeout Policy

An ACE WLM policy allows you to specify a processingTimeoutSec value for a message flow. A background WLM monitor checks periodically whether a flow thread has been processing a message longer than the configured threshold. When the threshold is exceeded, it indicates that message processing has taken longer than expected.

This can occur for different reasons. For example:

  • Performance degradation — the flow is still making progress, but is taking significantly longer than expected. This could be caused by increased processing time or a slow back-end dependency.
  • Potential hang — the flow thread is blocked for an extended period, for example while waiting for an unresponsive database, HTTP endpoint, or MQ queue manager.

When a timeout is detected, ACE performs the action configured by processingTimeoutAction.

2. Configuring the WLM Policy

Create or update a WLM policy in your policy project. Set Processing timeout (seconds) to the required threshold and set Processing timeout action to logWarning. The following example shows the Credit_WLM policy configured with a 10-second processing timeout and the logWarning action.

Figure 1: ACE Toolkit WLM policy editor showing the Credit_WLM policy with a 10-second processing timeout and logWarning configured.

Apply the WLM settings to the message flow through the BAR editor. Select the message flow in the Manage tab and expand Workload Management in the Properties panel. There are two ways to configure the processing timeout:

  • Using a WLM Policy: Select a policy that has already been created in the policy project, for example {UPIPolicy}:Credit_WLM. The timeout and action defined in the policy are then applied to the flow.
  • Directly in the BAR file: If you are not using a separate WLM policy project, you can configure Processing Timeout (Second) and Processing Action directly on the message flow.

Figure 2: ACE Toolkit BAR editor showing CreditUPIFlow.msgflow with the Credit_WLM WLM policy or setting the Processing Timeout (Second) and Processing Action directly.

Choosing the right timeout value

The timeout should be high enough to avoid warnings during normal variations in processing time, while still providing useful visibility into unusually long-running transactions. Use ACE Accounting and Statistics or activity log data to establish a baseline for normal processing time before selecting the value. In particular, consider the normal upper end of the processing-time distribution rather than using an arbitrary timeout value. For example, if normal processing occasionally takes longer during peak load, setting the timeout too close to the normal processing time can result in unnecessary warnings.

3. What Gets Logged

When a flow thread exceeds the configured processing timeout, ACE writes BIP7872W to the local error log. What happens after that depends on whether the flow eventually completes.

Processing eventually completes

If the flow remains blocked for some time but eventually completes, ACE writes BIP7873I when processing finishes. For example, a back-end system might take a long time to respond, or a node-level socket timeout might eventually expire and allow the flow to continue through its error path. The time between BIP7872W and BIP7873I provides useful information about how long the processing continued after the WLM threshold was exceeded.

Processing does not complete

If the flow thread remains blocked and does not complete, a corresponding BIP7873I will not be generated. In this situation, BIP7872W indicates that the configured processing threshold has been exceeded, but additional diagnostic information is required to determine whether the thread is actually hung. The Flow Thread Reporter can be used to investigate the current state of the thread. If the same currentFlowMessageId and stack remain unchanged across multiple snapshots, this provides strong evidence that the thread is not making forward progress.

Therefore, BIP7872W should be treated as the initial alert, while BIP7873I and additional diagnostic data help determine what happened to the processing after the timeout.

4. Example: A Flow Exceeding the Processing Timeout

The following example is based on an incident involving integration node FEDBKR, integration server UPI_EG, and flow CreditUPIFlow. The WLM processing timeout was configured to 10 seconds. The flow became blocked while waiting for the CBS back-end. The QueryCBS node had a 120-second socket timeout, so the thread eventually timed out and completed the error path.

In this example, BIP7872W was generated after the 10-second threshold was exceeded. BIP7873I was generated when processing eventually completed. The approximately 111-second gap between the two messages shows that the flow continued processing for a significant period after the WLM timeout was detected.

The key diagnostic fields in both messages are:


5. Investigating a Potentially Hung Flow

If BIP7872W is present but BIP7873I has not yet appeared, the flow thread may still be processing or may be blocked. The next step is to capture a Flow Thread Reporter snapshot:

mqsireportproperties NODEName -e ISName -o FlowThreadReporter -r

The report provides information such as the current message ID, thread ID, stack, and processing history. If the currentFlowMessageId matches the message ID reported in BIP7872W, and subsequent snapshots continue to show the same message ID and stack, this provides evidence that the thread has not made forward progress.

Additional diagnostic information can then be collected if required.

Java core dump

mqsichangeproperties NODEName -e ISName -o ComIbmInternalSupportManager/Java/JVM -n dump -v core

Process stack

On Linux:

pstack <pid of the IS>

On AIX:

procstack -F <pid of the IS>

These diagnostics can help identify where the thread is blocked and provide additional information for determining the underlying cause.

6. Correlating the Timeout with the Activity Log

The message ID reported in BIP7872W can be used to correlate the timeout with activity log entries for the same transaction. For example:

grep "00002F9C-6AB1F30A-00000003" activitylog.txt

The activity log entries for this message show the sequence of events leading up to the timeout.

Figure 3: Activity log entries for message 00002F9C-6AB1F30A-00000003, showing the relevant activity entries and timestamps.

The five entries shown in the screenshot are the only activity log records for this message ID, and they show the following:

  • BIP11516I / BIP11518I — HTTP Input receives the incoming request and starts processing.
  • BIP13072I — the QueryCBS node invokes the CBS web service. This is the last successful activity recorded before the long delay.
  • BIP13074E — approximately 120 seconds later, the web service invocation fails because the configured socket timeout expires.
  • BIP11507W — the local transaction is rolled back following the web service failure.

The large timestamp gap between the web service invocation and the subsequent failure indicates that the thread spent most of that time waiting for the CBS back-end.

Tip: Correlate the thread ID

The activity log also contains the thread ID. Filtering the activity log using the thread ID can help isolate entries associated with the affected thread when many threads are processing concurrently. For performance investigations, look for significant timestamp gaps between consecutive activity entries. These gaps can help identify external resource interactions that contribute to increased processing time.


7. Correlating with the Flow Thread Reporter

The ACE Flow Thread Reporter provides a real-time view of flow threads, including the thread ID, the current message ID, the current call stack, and the recent processing history. All timestamps in the Flow Thread Reporter output are in UTC.

Capture a report using:

mqsireportproperties FEDBKR -e UPI_EG -o FlowThreadReporter -r > FEDBKR_UPI_EG_FlowThreadReport.txt

In this example, the report captured during the incident shows thread 12188 with a currentFlowMessageId matching the message ID reported by BIP7872W.

Figure 4: Flow Thread Reporter output for thread 12188, showing the current message ID, stack, and processing history.

The key information includes:

  • tid: 12188 — identifies the thread that generated BIP7872W.
  • currentFlowMessageId — matches the message ID reported by BIP7872W.
  • stack — shows that the thread is currently within QueryCBS, indicating that the thread is waiting in that part of the flow.
  • history — shows that previous messages processed by the same thread completed normally.

The combination of the BIP7872W message, activity log, and Flow Thread Reporter provides a way to correlate the timeout with the specific transaction, thread, and flow node involved.

Automating diagnostic capture
For environments where rapid investigation is important, a watchdog script can monitor the local error log for BIP7872W and trigger collection of diagnostic information—for example, a Flow Thread Reporter snapshot, the process stack, and a Java core where appropriate. For a potential hang, collecting another set of diagnostics after an interval can help determine whether the thread has made progress. Comparing the two sets of diagnostics can show whether the currentFlowMessageId or stack has changed. If the same message ID and stack remain unchanged, the thread may still be blocked. If the message ID changes, the original processing has progressed or completed.

8. logWarning Compared with restartExecutionGroup

The existing restartExecutionGroup action continues to provide automatic recovery by restarting the integration server when the configured processing timeout is exceeded. The two actions have significantly different operational behaviour.
The choice between the two actions depends on the operational requirements of the integration environment. logWarning is useful when the primary requirement is visibility and diagnosis without automatically restarting the integration server. restartExecutionGroup can be used when automatic recovery through an integration server restart is required.

9. Summary

The logWarning option for processingTimeoutAction, introduced in ACE V13.0.9.0, provides a non-disruptive way to identify message flow processing that exceeds a configured WLM timeout. Configure the WLM policy with <processingTimeoutAction>logWarning</processingTimeoutAction> and select an appropriate processingTimeoutSec value based on observed message flow processing times.

When the threshold is exceeded, ACE writes BIP7872W to the local error log (syslog on Linux/AIX, Windows Event Log on Windows). The message includes useful correlation information such as the flow name, timeout value, thread ID, and message ID. From there, administrators can correlate the event with BIP7873I to determine whether processing subsequently completed, activity log entries to identify where significant processing delays occurred, Flow Thread Reporter data to determine the current state of the affected thread, and additional diagnostic information such as a process stack or Java core when required.

This makes logWarning useful not only for identifying potentially hung flow threads, but also for detecting message flow performance degradation and long-running transactions, while allowing the integration server and other flows to continue running.

0 comments
11 views

Permalink