DataWeave Delight: Measure Function Duration With time And duration Functions

To measure the time it takes to execute a function in DataWeave we can use the time and duration functions from the module dw::util::Timer. Both functions take a zero argument function that needs to be executed as argument (() -> T). But the output of the functions is different. The time function returns a TimeMeasurement object that has a result key containing the result of the function we passed as argument. We also get a start key that has the date and time value when the function gets executed. And finally we have the end key that stores the date and time value when the function is finished. To calculate the total duration time of the function we could use the start and end keys, but when we want the duration time we can better use the duration function. The duration function returns a DurationMeasurement object with also a key result that has the output of the function that is executed. The other key is time and contains the time it took for the function to be executed in milliseconds.

In the following example we use both timer functions together with the wait function. The wait function will wait for the given number of milliseconds before returning a value.

Source

%dw 2.0

import wait from dw::Runtime
import duration, time from dw::util::Timer

output application/json
---
{ 
    // time function returns a new object with
    // keys start, end and result.
    // Keys start and end contain the start and end datetime 
    // before and after the function is executed.
    // The result key has the value of the function.
    time: time(() -> 42 wait 1000),

    // duration function returns a new object with
    // keys time and result.
    // Key duration has the total duration for the
    // function execution in milliseconds.
    // The result key has the value of the function.
    duration: duration(() -> 42 wait 1000)
}

Output

{
  "time": {
    "start": "2022-06-14T04:39:21.582958Z",
    "result": 42,
    "end": "2022-06-14T04:39:22.583079Z"
  },
  "duration": {
    "time": 1000,
    "result": 42
  }
}

Applying the time or duration function in our code is intrusive as the result object is different from the result of our function we want to measure. We can write a helper function that uses the time or duration function, logs the output of the functions using log function and finally still returns the value from our input function by selecting the result key.

In the next example we create the wrapTime and wrapDuration functions that can be used to log the output of the time and duration functions and still return the result of the input function. This way we can introduce timing of function duration in a less intrusive way.

Source

%dw 2.0

import wait from dw::Runtime
import duration, time from dw::util::Timer

fun answer() = 42 wait 400

// We still want the original result from the answer function,
// but also log the output of the time function.
// We pass the output of the time function to the log function that
// will log the output and then return the output value. 
// And finally use the result key from the time function
// to get output from the answer function.
fun wrapTime(f) = log("Time", time(f)).result

// We still want the original result from the answer function,
// but also log the output of the duration function.
// We pass the output of the time function to the log function that
// will log the output and then return the output value. 
// And finally use the result key from the duration function output
// to get output from the answer function.    
fun wrapDuration(f) = log("Duration", duration(f)).result

output application/json
---
{ 
    // Simple invocation of the function answer to get the result.
    result: answer(),

    // Use wrapTime function to still get result, but also log time output.
    resultTimer: wrapTime(() -> answer()),

    // Use wrapDuration function to still get result, but also log duration output.
    resultDuration: wrapDuration(() -> answer())
} 

Output

{
  "result": 42,
  "resultTimer": 42,
  "resultDuration": 42
}

Log output

Time - { start: |2022-06-14T04:52:29.287724Z|, result: 42, end: |2022-06-14T04:52:29.687875Z| }
Duration - { time: 400, result: 42 }

Written with DataWeave 2.4.