Performance Tuning FME: Post-Mortem Performance Tuning

Introduction

Analyzing the results of a process in order to assess or improve future performance is called post-mortem debugging. In FME, the key result of a process is the log file.
Therefore, before being able to tune a workspace, it's vital to understand how to read an FME log file. Without this knowledge, a user will often jump to incorrect conclusions about a translation and start looking for performance issues in the wrong places. For other performance tuning tips & tricks, see Performance Tuning FME.

Log Timestamps

When trying to speed up a translation, it is always beneficial to check the timings noted in the log file to determine exactly where the time was being spent. Timings are always written to the log file, but only optionally written to the log window.
Tip: Check that Tools > FME Options > Translation > Log Settings > Log Timestamp Information is checked. This will cause timestamps to appear in the FME Workbench log window.
​​​​​​​
 

Interpreting Log Timestamps

A log timestamp always shows three columns:

• An absolute datetime stamp (2020-04-22 14:43:13)
• A total elapsed time for the translation (8.8 seconds)
• An elapsed time since the last log message (0.3 seconds)

Tip: Elapsed Time (measured in seconds) is actual FME Processing time. This may not be the same as the overall length of the process.
For example, here the elapsed time shows the process took over 6 minutes, but the Total field reports FME used only 25.8 seconds:

Absolute Time | Elapsed Time Total| Incremental Elapsed Time
2020-04-22 14:43:06| 8.5| 0.0|
2020-04-22 14:43:13| 8.8| 0.3|
2020-04-22 14:46:29| 18.0| 9.1|
2020-04-22 14:49:29| 25.8| 7.9|

See How FME logs processing time, for more information.
 

FME Session Duration

At the very end of your log file you'll see:

INFORM|FME Session Duration: 1 minute 27.2 seconds. (CPU: 13.7s user, 0.9s system)

The duration tells us how long the translation took (which should match the difference between the first absolute timestamp in the log, and the last absolute timestamp.
The CPU time will approximate the last "Elapsed Time Total" time in the log timings. It tells us how much CPU time was occupied by the FME process.
Tip: The difference between the session duration and CPU times is an indication that there are aspects of the translation outside of FME's control: slow database queries, network latency, or slow HTTP requests.
 

Key Stage Performance

A typical FME translation has a number of key stages, often reading, transformation, and writing. A preliminary assessment of performance involves timing each of these key stages.
However, because FME processes features in a mix of ways (feature-based, group-based, and bulk mode), it is difficult to assess these stages from a single translation. For example, FME starts to transform data before it has finished reading it.
The log message Emptying Factory Pipeline generally means reading data is finished:

2020-02-03 11:37:47| 342.7| 0.5|INFORM|Emptying factory pipeline

Here it took 342.7 seconds (about 6 minutes) to read the source data. But, as you now know, this may include time spent processing the features within the workspace. Disabling all but the readers gave this result:

2020-02-03 14:44:43| 66.5| 0.3|INFORM|Emptying factory pipeline

Only one minute instead of six. This tells us that 80% of the time was spent processing the data, and only 20% reading it. In this case, the user thought the reading was the bottleneck, but this shows it was the transformation.
Tip: To measure the performance of key stages, run the workspace with everything but readers disabled. Then run it again with just writers disabled. With the log timings from these runs (and the original run), you should be able to calculate just how long FME spends reading, writing, and transforming data, and this will show where to concentrate your performance efforts.