Teneo Developers

Time-profiling a Solution

Occasionally it is useful to time-profile the runtime execution of a solution - this means finding out which part of the processing of (usually) a particular input is causing delays.

The fact that there is a delay may be noticed whilst testing in Tryout or a published solution - or, in solutions where this has been set up, the overall processing times could be being tracked in Inquire - however, for the sake of this article let’s assume a delay has been discovered.

Time stamping

Firstly, we will need to be able to reliably and simply track the time taken in processing particular parts of the solution. This is done by recording the time at which the engine executes a particular script.

This can be achieved by adding the following lineat several points in the solution: println "timestamp " + LocalDateTime.now(). Then this data can be extracted and compared.

However, it would be simpler to have all the timing information in one place instead of having to extract all the “timestamp” lines - plus, the most interesting piece of information is actually the time lapse between timestamps.

TimeProfile class

In order to simplify this process we can introduce a class to handle the following:

  1. Collect the time data in one place
  2. Output the duration between time stamps in a single string
  3. Clear profile

Class definition

These functions will be added to the following class defined in the global “Solution loaded” script:


1class TimeProfile {
2  private static Object profile = [];

The profile object is a simple list to store the timestamps.

Collect time stamps

Recording a timestamp requires the stamp methodl; this will record the system time in nanoseconds along with an identifying string (passed into the method).


1public static void stamp(String action) {
2  profile.add(['action':action, 'timestamp':System.nanoTime()])

This can then be used as such, with a recognizable label:



Output Time Since Start

Next we want to output the time stamps:

  • In a single place
  • As offsets from the previous timestamp

The following method loops through comparing each timestamp with the first (“start”) timestamp. This gives an idea of when the system reached each step in the processing.


1public static String output() {
2  // Get the first timestamp as a start point
3  def start = profile.first()
4  def outputString = "${start.action} - start"
5  long startstamp = start.timestamp
7  // Add each stamp to the output - comparing the time to the start point
8  profile.drop(1).each { stamp ->
9    outputString += "${System.lineSeparator()}${stamp.action} @ ${java.time.Duration.ofNanos(stamp.timestamp - startstamp).toMillis()}ms"
10  }
12  // Empty the collection for next transaction
13  profile.clear()
14  return outputString


  1. Stamps In a basic solution, add timestamps to the end of all Global Scripts with the name of the script as the action parameter, e.g.:
  • Pre-processing script: TimeProfile.stamp("Pre processing")
  • Pre-matching script: TimeProfile.stamp("Pre matching")
  1. Output Then at the end of the Post-processing, stamp and print the time profile:


1TimeProfile.stamp("Post processing")
2println TimeProfile.output()

The result will be similar to this (notice the time is since start - and therefore always increasing for each timestamp):


103/02/2020 17:12:34 [Println]: Begin Dialog - start
2New Session @ 12ms
3Pre-processing @ 17ms
4Pre-matching @ 334ms
5Global On top @ 409ms
6Global On drop @ 415ms
7Post-processing @ 733ms

Output Durations

The above Output method will show when each stamp occurred compared with the first. In some cases, it can be simpler to spot a delay by logging the duration of each step, i.e. show when each stamp occurred compared to the previous stamp.

This can be achieved with a change to the output method to keep track of the previous stamp and use that in the comparison:


1long prevstamp = start.timestamp
3// Add each stamp to the output - comparing the time to the start point
4profile.drop(1).each { stamp ->
5  outputString += "${System.lineSeparator()}${stamp.action} @ ${java.time.Duration.ofNanos(stamp.timestamp - prevstamp).toMillis()}ms"
6  prevstamp = stamp.timestamp

The result will then be the same format - but the values will represent time passed between each stamp (notice the times do not always increase):


103/02/2020 17:29:57 [Println]: Begin Dialog - start
2New Session @ 9ms
3Pre-processing @ 3ms
4Pre-matching @ 174ms
5Global On top @ 53ms
6Global On drop @ 9ms
7Post-processing @ 278ms


The likelihood is that more detail will be needed to track down any delay! This is then a process of adding more timestamps between existing timestamps where the durations are longer than expected.

For example, where “Pre-matching” time stamp is showing as being where much of the time is taken:

  • The delay is between the end of “Pre processing” and the end of “Pre matching”
  • Between the end of Pre processing and the end of Pre matching is:
    • Input Processing
    • Global Pre-Listeners
    • Pre-Matching Script
      • the time stamp is at the end of the script - so the execution of the script itself is included.

Add more timestamps

  • in each of the executed listeners
  • at the start of Pre-matching (to time the Pre-matching script)

From this information the particular listener or script which is causing the delay can be discovered. Then adding further time stamps inside the listener or script can narrow down further exactly which functionality is delaying the execution.

Full TimeProfile Class


1class TimeProfile {
2	private static Object profile = [];
4	public static void stamp(String action) {
5		profile.add(['action':action, 'timestamp':System.nanoTime()])
6	}
8	public static String output() {
9		def start = profile.first()
10		def outputString = "${start.action} - start"
11		long startstamp = start.timestamp
13		profile.drop(1).each { stamp ->
14			outputString += "${System.lineSeparator()}${stamp.action} @ ${java.time.Duration.ofNanos(stamp.timestamp - startstamp).toMillis()}ms"
15		}
17		profile.clear()
18		return outputString
19	}