Using Mule Notifications to Calculate Total Execution Time of a Mule Component

In this article, I will show you how to use the Mule Notifications functionality of Mule 3.x to calculate the total execution time of a Sub-Flow, HTTP Request Connector, Script Component, and the Transform Message (Dataweave). For more details regarding this functionality, you can check the documentation https://docs.mulesoft.com/mule-user-guide/v/3.9/mule-server-notifications.

Mule Configuration: In this configuration, I'm creating a bean for my custom listener class and referencing it to my Notification Configuration. Also note that the event MESSAGE-PROCESSOR allows the notification to be sent before and after a Mule component is invoked.

    <spring:beans>
      <spring:bean name="muleComponentProcessListener" 
       class="com.custom.mule.notification.listener.MuleComponentProcessListener"/>         
    </spring:beans>
    <notifications>
      <notification event="MESSAGE-PROCESSOR"/>
      <notification-listener ref="muleComponentProcessListener"/>
    </notifications>

Listener Class: This custom class will serve as the listener class of the Mule notification. It simply calculates the total execution time of the above Mule components.

package com.custom.mule.notification.listener;

import java.util.HashMap;

import org.apache.log4j.Logger;
import org.mule.api.context.notification.MessageProcessorNotificationListener;
import org.mule.api.processor.MessageProcessor;
import org.mule.context.notification.MessageProcessorNotification;
import org.mule.module.http.internal.request.DefaultHttpRequester;
import org.mule.processor.chain.SubflowInterceptingChainLifecycleWrapper;

public class MuleComponentProcessListener implements MessageProcessorNotificationListener<MessageProcessorNotification> {
private Logger log = Logger.getLogger(getClass().getName());
private long startTime =0;
private HashMap<String,Long> componentStartTimeHolder = new HashMap<String,Long>();

@Override
public void onNotification(MessageProcessorNotification notification) {
    MessageProcessor process = notification.getProcessor();
    String className = process.getClass().getSimpleName();
    boolean isOutbound = process instanceof DefaultHttpRequester;

    if(className.equalsIgnoreCase("DefaultHttpRequester") && isOutbound){        
    try{    
    DefaultHttpRequester def = (DefaultHttpRequester)process;
    if (notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_PRE_INVOKE){
     startTime = System.currentTimeMillis();
}
 if(notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_POST_INVOKE){ 
     long executionTime = System.currentTimeMillis() - startTime;
     log.warn("HTTP Request Call To : "+ def.getHost()+ " "+ def.getPath()+ " took " + executionTime + "ms response time.");
}
    }catch(Exception e){}
    } else if (className.equalsIgnoreCase("SubflowInterceptingChainLifecycleWrapper")){
    SubflowInterceptingChainLifecycleWrapper subFlow = (SubflowInterceptingChainLifecycleWrapper) process;
    if (notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_PRE_INVOKE){
     startTime = System.currentTimeMillis();
     componentStartTimeHolder.put(subFlow.getSubFlowName(), startTime);
}
if(notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_POST_INVOKE){ 
     long executionTime = System.currentTimeMillis() - (long)componentStartTimeHolder.get(subFlow.getSubFlowName());
     log.warn("Sub-flow Processing Time: "+ subFlow.getSubFlowName() + " took " + executionTime + "ms response time.");
}
    }  else if (className.equalsIgnoreCase("WeaveMessageProcessor")){
    if (notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_PRE_INVOKE){
     startTime = System.currentTimeMillis();
     componentStartTimeHolder.put(process.toString(), startTime);
}
if(notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_POST_INVOKE){ 
     long executionTime = System.currentTimeMillis() - (long)componentStartTimeHolder.get(process.toString());
     log.warn("Dataweave Processing Time: "+ process.toString() + " took " + executionTime + "ms response time.");
}
    } else if (className.equalsIgnoreCase("ScriptTransformer")){
    if (notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_PRE_INVOKE){
     startTime = System.currentTimeMillis();
     componentStartTimeHolder.put(process.toString(), startTime);
}
if(notification.getAction() ==  MessageProcessorNotification.MESSAGE_PROCESSOR_POST_INVOKE){ 
     long executionTime = System.currentTimeMillis() - (long)componentStartTimeHolder.get(process.toString());
     log.warn("ScriptTransformer Processing Time: "+ process.toString() + " took " + executionTime + "ms response time.");
}
    }

}

}

TESTING:

Thanks for reading, and let me know your thoughts or any questions you might have in the comments section.