+7I have a job running that takes 10 minutes and generates 19.000 rows in the log. The runtime is not the issue here, I'm just curious to out some numbers on time-spent.
What’s the best way to find out where the time is spent?
I suspect a few specific transformers, but since this is probably a common question I wonder what other people are doing.
Best answer by virtualcitymatt
So nobody really uses the logs for other than a little reading, optimizing and debugging?
I sort of expected all sorts of creative stuff with the logs, but maybe I’ll have to give it a try.
I this case the runtime is caused by a throttled sql-server behind a firewall, so there’s nothing special about it, but having a graph or a summary would be a great thing to show the client or the rest of the team.
I have in the past used FME to process the logfile and chuck it into excel in order to make some graphs. Mostly this was to compare stages in different environments. I’m sure others have sone something similar. But its sometimes very difficult to say how long a transformer took to process the data just form the log.
There is also the LogMessageStreamer which pulls the log into the workspace - this can be a nice way to filter for lines that you care about.
But yeah, mostly the log is used for debugging (at least by me)
+36
This is probably a good place to start. The whole series on performance tuning gives some great tips
+7
This is probably a good place to start. The whole series on performance tuning gives some great tips
I am looking for tools on how to analyze the log for useful info.
I am not gonna read log manually.
+44That seems excessively long for a 10-minute job. Can you perhaps send it to Safe (support.safe.com) and ask someone in support to look it over? I’d hope there are ways we could reduce the amount of logging.
+7That seems excessively long for a 10-minute job. Can you perhaps send it to Safe (support.safe.com) and ask someone in support to look it over? I’d hope there are ways we could reduce the amount of logging.
I'm sorry I wasn't clear. The runtime is not the problem. A long hard-to-use log just got me thinking how I could make good use of it.
+36That seems excessively long for a 10-minute job. Can you perhaps send it to Safe (support.safe.com) and ask someone in support to look it over? I’d hope there are ways we could reduce the amount of logging.
I'm sorry I wasn't clear. The runtime is not the problem. A long hard-to-use log just got me thinking how I could make good use of it.
Yeah, the log is often empty noise. Depending on what transformer/reader/writer you’r using you’ll get different messages.
Sometimes things get logged in a big chunk and it looks like this is where the slowdown is, however, if you change something later in the process all of a sudden that slow part then speeds up because it was just the flow of features that changed.
In general though I would usually compare Reading, Processing and Writing - disable parts of the workspace and compare. This isn’t always a robust approach though because FME can be clever and if it sees that data are not going anywhere it will just not perform those operations.
you can use this: https://support.safe.com/hc/en-us/articles/25407794017933-Performance-Tuning-FME#h_01HVKVKCNHGMC0RVMSEDHNK3WV which can profile how long FME uses each factory for, however, the result is also sometimes a little tricky to apply directly to the workspace. But it’s a great option if you what to know what’s happening under-the-hood.
Often the most useful piece of info in the log is the line
INFORM|FME Session Duration: 1 minute 27.2 seconds. (CPU: 13.7s user, 0.9s system)
This can give you a quick sense if it’s FME processing features which is taking the time or some kind of network bottleneck or external DB query which FME is waiting on. In the above you can see that there was only 13-14 seconds where FME was actually crunching number, the rest of the 1 min 27 was FME just waiting.
+50If there’s 19000 lines of logging I’d expect to see a lot of similar messages, can you check the log, see if that’s the case and then share it here?
Alternatively, if you see a lot of attribute names/values listed there, that’s also useful to know.
+7So nobody really uses the logs for other than a little reading, optimizing and debugging?
I sort of expected all sorts of creative stuff with the logs, but maybe I’ll have to give it a try.
I this case the runtime is caused by a throttled sql-server behind a firewall, so there’s nothing special about it, but having a graph or a summary would be a great thing to show the client or the rest of the team.
But in this case the interesting line is:
20283 2025-5-15 15:20:25 | FME Session Duration: 9 minutes 8 seconds. (CPU: 129.7s user, 15.4s system)
+36So nobody really uses the logs for other than a little reading, optimizing and debugging?
I sort of expected all sorts of creative stuff with the logs, but maybe I’ll have to give it a try.
I this case the runtime is caused by a throttled sql-server behind a firewall, so there’s nothing special about it, but having a graph or a summary would be a great thing to show the client or the rest of the team.
I have in the past used FME to process the logfile and chuck it into excel in order to make some graphs. Mostly this was to compare stages in different environments. I’m sure others have sone something similar. But its sometimes very difficult to say how long a transformer took to process the data just form the log.
There is also the LogMessageStreamer which pulls the log into the workspace - this can be a nice way to filter for lines that you care about.
But yeah, mostly the log is used for debugging (at least by me)
Enter your E-mail address. We'll send you an e-mail with instructions to reset your password.
