Calculate the Total Processing Time of Any Flow in Your App

When we want to improve the performance of any application, the first step is to measure the processing time of building blocks of the application. In Mule applications, these building blocks are Mule flows. It becomes very important for us to measure the processing time of our flows to identify the hot spot in the application. There are many ways to achieve this in Mule, like adding a flow variable to store the current time-stamp at the beginning of the flow and at the the end of the flow subtract the current time-stamp by stored start-time (in a flow variable).

However, this becomes very difficult if we want to calculate processing time for multiple flows. We need add those loggers in each flow. Here, we are going to implement the simpler way to achieve this for all flows.

Option 1: Using timer-interceptor

MuleSoft provides different kinds of interceptors that you can use for different purposes. Check out more on interceptors in Mule here.

timer-interceptor is useful to measure the flow execution time. To use this, we just need to place timer-interceptor at the starting of our flow (just after inbound/source element) as shown below.

<flow name="mulebasicsFlow">
      <http:listener config-ref="HTTP_Listener_Configuration" path="/firstdemo" doc:name="HTTP" />
      <timer-interceptor /> 
      <set-payload value="1" doc:name="Set Payload" />
      <object-to-string-transformer doc:name="Object to String" />
</flow>

That’s it; you’re done. You can see the entry in your logs like this:

mulebasicsFlow took 1856ms to process event [0-28146111-c518-11e6-8d66-083e8eb45efa

This looks fine, but what if you want to more information with customized format? Let’s look into the second option.

Option 2: Using Custom Logging Interceptor

Instead of using timer-interceptor, we can also write our own custom interceptor and can evaluate the processing time of flow. To write a custom logging interceptor, we need to extend AbstractEnvelopeInterceptor and override it’s methods. There are three methods that AbstractEnvelopeInterceptor provides: “before,” “after,” “last.” We need to put our logic in “last” method; it executes at the end of the flow.

public class CustomLoggingInterceptor extends AbstractEnvelopeInterceptor {
 private static org.apache.commons.logging.Log logger = LogFactory.getLog(CustomLoggingInterceptor.class);

@Override
 public MuleEvent last(MuleEvent event, ProcessingTime time, long startTime, boolean exceptionWasThrown)
 throws MuleException {
 try {
     long endTime = System.currentTimeMillis();
     logger.info(
 "**************************************************************************************************"
 + System.getProperty("line.separator") + " | Flow: " + event.getFlowConstruct().getName()
 + " | Procesing Time:" + (endTime - startTime) + " ms" + System.getProperty("line.separator")
 + "**************************************************************************************************");
     return event;
} catch (Exception e) {
 e.printStackTrace();
}
return event;

To inject this custom logging interceptor, we need to put this line into our flow at the beginning (just after the source component like timer-interceptor as above).

<custom-interceptor
 class="com.mulebasics.interceptors.CustomLoggingInterceptor" />

That's it. Now you can see your customized message with processing time in your logs.