Analyzing and understanding the performance of your robots

Introduction

When you are doing a migration project, you often feel the need for speed, requiring you to write robot code that is as efficient as possible. In order to gain insight into which parts of your code take up the largest chunk of the total running time, additional profiling code can be included in a project. This page provides a ready-to-use example of a bit of profiling code that allows you to log and analyze the time spent on one or more function. This works as follows:

- Initialize profiling by calling initializeProfiling() with a list of tasks you want to profile

- For every task, enclose the task in startAction() and completeAction() calls

- When your robot finishes, call analyzeActions() to get the average, median and total time spent on all tasks you have defined.

The code snipped below does all these things, and is fairly self-explanatory. At the bottom of the page you will find another snippet that uses the functions in an example robot.

A ready-made code snippet to compute average, median and total time spent in a task

use System, Date, Collection, Math;

////////////////////
/// EXAMPLE CODE ///
////////////////////

// INIT
var settings = { "profileRobotPerformance" : true };
if (settings.profileRobotPerformance) { initializeProfiling(["uploadFile", "uploadFolder", "initializeRobot", "overhead"]); }

// PERFORM ACTIONS INSIDE startAction() and completeAction() CALLS, LIKE THIS:
if (settings.profileRobotPerformance) { startAction("uploadFile"); }
if (settings.profileRobotPerformance) { completeAction("uploadFile"); }

// GET ANALYSIS RESULTS
if (settings.profileRobotPerformance) { analyzeActions(); }

/////////////////////////////////
/// ROBOT PROFILING FUNCTIONS ///
/////////////////////////////////

function startAction(action) {
    settings.robotProfiling[action][] = {"start" : Date.now(), "complete" : ""};
}
 
function completeAction(action) {
    settings.robotProfiling[action][Collection.length(settings.robotProfiling[action])-1]["complete"] = Date.now();
}
 
function initializeProfiling(actions) {
     settings.robotProfiling = {};
     foreach (action in actions) {
          settings.robotProfiling[action] = {};
     }
}
 
function analyzeActions() {
     foreach (key, action in settings.robotProfiling) {
          if (action != {}) {
               var deltas = [];
               var total = 0;
               foreach (entry in action) {
                    var delta = Date.diff(entry.start, entry.complete);
                    delta = delta.totalMillis;
                    deltas[] = delta * 0.001;
                    total = total + delta * 0.001;
               }
               var avg = total / Collection.length(deltas);
               var median = deltas[Math.round((Collection.length(deltas)-1) / 2)];
               System.print(key :: " average: ":: avg :: " seconds per action\n"::key :: " median: ":: median :: " seconds per action\n"::"total time spent on action "::key:: " is "::total::" seconds");
          }
     }
}

Example Output

What if you have to calculate 24 factorial and the 420th number in the Fibonacci sequence for your project, but your code is running slow? Save the above profiling code as "profiling.xill", and you can include and use it as shown below. 

use System;

include profiling;

initializeProfiling(["fibonacci", "factorial"]);
var runs = "";
var nFib = 24;
var nFac = 420;

runs = 20;
System.print("Computing fibonacci("::nFib::") = "::fibonacci(nFib)::" "::runs::" times...");
while (runs --> 0) {
     startAction("fibonacci");
     fibonacci(nFib);
     completeAction("fibonacci");
}

runs = 20;
System.print("Computing factorial("::nFac::") = "::factorial(nFac)::" "::runs::" times...");
while (runs --> 0) {
     startAction("factorial");
     factorial(nFac);
     completeAction("factorial");
}

analyzeActions();

//

function fibonacci(n) {
     if (n < 1) { return(0); }
     if (n == 1) { return(1); }
     else { return(fibonacci(n-1) + fibonacci(n-2)); }
}

function factorial(n) {
     if (n < 1) { return(1); }
     else { return(factorial(n-1)*n); }
}

The snipped above will calculate both numbers, and will give something like this as output in the console:

Computing fibonacci(24) = 46368 20 times...

Computing factorial(420) = 1179832395293178259148587778443982767423908163629667689799210969550884231351169347804766799500510294050388349696532084729374087533384204019322892961178819464698121263533012685335273004294789382652477324465427001701326230145911466316029644714371748823861128004214806081770714277374544632880180009063325310867611466814559562175609414340177417478580290981292661586700768075544788360242053436899439186009859147147653878644064667799709427693731208035920284052203131022083688425805265631534978481761954009800546844281261649619610291306374918025956972209823833523561696079181976208783662818235613615149296343931089295234402130043253489826928097199211074340929916161625854705227595565090740962113793308742649598603963747960941063835474664306971892700806057422478626083960243385932102946293048920279760860198799159782580284293120000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 20 times...

fibonacci average: 0.19474999999999995 seconds per action
fibonacci median: 0.19 seconds per action
total time spent on action fibonacci is 3.894999999999999 seconds

factorial average: 7.500000000000003E-4 seconds per action
factorial median: 0.0 seconds per action
total time spent on action factorial is 0.015000000000000006 seconds

Wow, fibonacci() is a lot slower than factorial()! Now we know which function call costs the most time, and gives the biggest gain if we can optimize it somehow. Clearly, we should be careful when doing recursion with a high branching factor... Of course your memoized Haskell function might have a slight speed advantage over this Xill implementation, but that's beyond the scope of this tutorial ;)