Log Timings

The timestamps in FME logs are invaluable for assessing performance.

Remember, the structure of the log is this:

Absolute Time| Cumulative Time| Time for Operation| Message Type| Message Content

Time for Operation is the amount of time spent on that step of the translation, and Cumulative Time is the sum of those operations.

Although cumulative time is the amount of time the FME process has spent translating or transforming data, it does NOT include the amount of time spent waiting for other processes to do their work.

For example, examine this section of log timings:

2018-02-10 14:43:06|  8.5| 0.0|
2018-02-10 14:43:13|  8.8| 0.3|
2018-02-10 14:46:29| 18.0| 9.1|
2018-02-10 14:49:29| 25.8| 7.9|

The difference between the start absolute time (14:43) and the finish absolute time (14:49) is over six minutes. However, FME is only reporting 25.8 seconds of processing time!

The “lost” time is down to external processes that FME was waiting on.

For example, maybe the message content would look like this:

2018-02-10 14:43:06|  8.5| 0.0| INFORM| Preparing SQL query
2018-02-10 14:43:13|  8.8| 0.3| INFORM| Sending SQL query
2018-02-10 14:46:29| 18.0| 9.1| INFORM| Received initial database response
2018-02-10 14:49:29| 25.8| 7.9| INFORM| Received data from database query

Now we can see that it was a database query that FME was waiting for. The more the query was not well-formed or the database not well-structured, the longer the time difference would be.

Similarly, reading/writing data from/to a disk can account for missing time.