If the Robot takes too long… Profiling Robot Framework

1 Comment

Tests that you typically create with the Robot Framework (e.g. User Acceptance Tests) tend to run a little longer than e.g. unit tests. It’s common that UATs run in hours and not in minutes. Even if you are able to move the test execution into the night it’s painful. Even parallizing test execution works only on the symptomes.

Let’s face it: From time to time it comes handy being able to determine where the Robot looses time. Time for Profiling!

The default output.xml log file contains basically all needed data. Each executed keyword has it’s own tag. Those tags have nested status elements noting the start and end time of the keyword execution. So all what’s missing are some tools for processing and analyzing those data…

Robot Framework’s time2csv.py

One tool is already part of the Robot Framework but it’s only included in the source code distribution. The python script “times2csv.py” calculates the execution time of each keyword and shows the results within the keyword call hierarchie. The data is written into a CSV file that can later be viewed and analyzed within a spread sheet, e.g. Excel.

Example output of time2csv

Example output of times2csv

This type of analysis works very well if you already know about the bottlenecks in your test suite and want to dig a little deeper to find some reasons. But if you have no clue yet what to look at you will be lost in data. (In one typical project the analysis had ~2.3 million rows with the largest file at around 900,000 rows…)

Profiling Robot Framework with robot_profiler.py

So what do you do if you have no clue where or what to look at? Or if you assume that your tests have a “time leak” – keywords that are just a little bit slow and that are called many many times… For this situation you need a different analysis style: the execution time summed up per keyword and the average execution time per keyword.

For this purpose I created a little Python script. It is available on GitHub.

The script recognizes the following command line parameters:

usage: robot_profiler.py [-h] [-e ENCODING] [-s SEPARATOR] [-l LOCALE]
                         input_file_name [output_file_name]

positional arguments:
  input_file_name       The output.xml file to read from.
  output_file_name      The file to write the profiler data to.

optional arguments:
  -h, --help            show this help message and exit
  -e ENCODING, --encoding ENCODING
                        Encoding for output file.
  -s SEPARATOR, --separator SEPARATOR
                        Separator used in output file.
  -l LOCALE, --locale LOCALE
                        Locale used for number formatting.

If no output file name is given the name (and path) of the input file name is taken with .csv as the new extension.

Parameters -e, -s, and -l are optional. They can be used to set the file encoding, the field separator and the localization of the number format. The default values for these parameters are chosen as sensible as possible and create a csv file ready to be used with Excel (a rather typical use case I suppose…): it uses cp1252 as encoding (Windows standard), semicolon as field separator (Excel does not recognize comma as separator of a csv file – for whatever reason…). If you need a TSV file (tab separated values) you can use -s \t. The localization option uses no explicit default value – it uses the plattform’s default locale. Please note that valid values for -l might be plattform depending. E.g. the code for “German” is de_DE on Linux but German on Windows…

When using this scipt in real life projects I suggest using Python instead of Jython. Jython seems to be quite wasteful in terms of memory consumption. Even if it doesn’t crash with some error message it’ll take you hours to get results. If you don’t want to install Python just for this purpose I recommend using PortablePython.

The script creates an output file ready to be opened in MS Excel by double clicking. Beside the (fully qualified) keyword identifier it shows the number of occurrences (calls), the total keyword execution time, and the average keyword execution time.

Example output of robot_profiler.py

Example output of robot_profiler.py

When looking for bottlenecks I prefer loading the output into a spreadsheet, filtering for an average runtime of 1 sec or longer and sorting the result by the average runtime column. Usually this should lead to some good starting points for more in depth analysis.

Happy Testing 🙂




Your email address will not be published. Required fields are marked *