A Simple way to log time durations in WSO2 ESB

In this post I will explain a simple mechanism to log a time duration in WSO2 ESB. Already there is a great and powerful way of getting statistics of WSO2 ESB which is capable of providing runtime statistical information from sequences, endpoints, proxies and view it through the ESB management console. This will help you to analyze response times, counts and many more performance related options very effectively.

But lets assume, for debugging purposes (or any other purpose) you need a quick and simple way of measuring time durations. For example imagine that you have a proxy service which calls to a back end and returns the response from the back end. Lets say you need to get a rough idea on the time taken to call the back end and get the response. This kind of a scenario can be simply achieved by the use of property mediator, script mediator and a log mediator.

There is a Synapse Message Context Property which can retrieve the current time is milliseconds (i.e. the difference, measured in milliseconds, between the current time and midnight, January 1, 1970 UTC). We can set this value to a property (at the desired point of the message flow) and access it when ever we need.

For example, following is how to set the time to the property 'TIME' and log it later;

<property name="TIME" expression="get-property('SYSTEM_TIME')" scope="default" type="LONG"/>
...
<log>
 <property name="Time : " expression="get-property('TIME')"/>
</log>
...

Like wise we can store the current system time in milliseconds, at desired points in the message flow into different properties. After that we can use a Script mediator to read these values and perform the required calculations.

For example if we have set two time values in propeties 'TIME_1' and 'TIME_2' we can get the difference between those as follows;

<script language="js">
 var time1 = mc.getProperty("TIME_1");
 var time2 = mc.getProperty("TIME_2");
 var timeTaken = time2 - time1;
 print("Time Duration :  " + timeTaken + " ms ");
 mc.setProperty("RESPONSE_TIME", timeTaken);
</script>

Also we can set the result to another property (mc.setProperty("RESPONSE_TIME", timeTaken);) which can be used in the message flow (for example to log the time with the Log mediator).

Therefore this will provide a simple mechanism to log a time in WSO2 ESB. A sample proxy with this kind of a scenario is as follows;

<proxy xmlns="http://ws.apache.org/ns/synapse"
       name="SampleTimeProxy"
       transports="https,http"
       statistics="disable"
       trace="disable"
       startOnLoad="true">
   <target>
      <inSequence>
         <property name="TIME_1"
                   expression="get-property('SYSTEM_TIME')"
                   scope="default"
                   type="LONG"/>
      </inSequence>
      <outSequence>
         <send/>
         <property name="TIME_2"
                   expression="get-property('SYSTEM_TIME')"
                   scope="default"
                   type="LONG"/>
         <script language="js">
              var time1 = mc.getProperty("TIME_1");
              var time2 = mc.getProperty("TIME_2");
              var timeTaken = time2 - time1;
              print("--------------  " + timeTaken + " ms  -----------------");
              mc.setProperty("RESPONSE_TIME", timeTaken);
         </script>
         <log>
            <property name="Time Duration in ms: " expression="get-property('RESPONSE_TIME')"/>
         </log>
      </outSequence>
      <endpoint>
         <address uri="http://localhost:8080/axis2/services/SimpleStockQuoteService"/>
      </endpoint>
   </target>
   <publishWSDL uri="http://localhost:8080/axis2/services/SimpleStockQuoteService?wsdl"/>
   <description/>
</proxy>

Hope this will be helpfull...!