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:

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

Class definition

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

java

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

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).

java

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

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

java

1TimeProfile.stamp("Pre-processing")
2

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.

java

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
6
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  }
11
12  // Empty the collection for next transaction
13  profile.clear()
14  return outputString
15}
16

Example

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")

Output Then at the end of the Post-processing, stamp and print the time profile:

java

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

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

output

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
8

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:

java

1long prevstamp = start.timestamp
2
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
7}
8

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):

output

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
8

Debugging

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

java

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