Skip to main content

I am finding that ShortestPathFinder in FME Desktop 2019.1.0 gets exponentially slower as I increase the number of "From-To" lines, whereas I would expect it to get linearly slower (i.e. twice as many From-To lines, twice the time) as each path calculation should be independent. Can someone explain why this would be and how I can avoid it?

To give some context, I am running ShortestPathFinder over a (road) network with simple 2-point "From-To" lines whose vertices have already been snapped to the (road) network. There are (up to) 120,000 from-to lines, with a network of 280,000 edges (as output by a LineOnLineOverlayer to split all lines at intersections). For ShortestPathFinder I am using default settings, other than turning off snapping (reducing iterations from 10000 to 1000 made little difference). fStrangely, setting "Re-order From-To Line" to "No" hides all the other optimization settings - a bug?]

The final output results are all exactly as I would expect, but it takes about a day to run (on an a fairly new Intel i5 HP Elitebook laptop with 16GB RAM). If I limit the number of From-To lines, it runs much faster. I have tried reworking the workbench to put the ShortestPathFinder in a Custom transformer to run on "moderate" parallel processing, hence 8 processor threads and also to limit it to groups of exactly 2000 from-to lines each. Although this maxes out the CPUs, this does not appear to run a lot faster. However, because the timing of each group is reported separately it very clearly demonstrates it getting slower - the following is an edit of the logfile to pull out the lines indicating successive group session durations. (I could understand the first 3 or 4 running faster as they are probably getting a bigger slice of the computer non-CPU resources):

13:20:44|0>  Duration: 1 minute 49.2 seconds.
13:21:50|1>  Duration: 2 minutes 53.4 seconds.
13:25:34|2>  Duration: 6 minutes 36.7 seconds.
13:26:34|3>  Duration: 7 minutes 34.3 seconds.
13:27:54|7>  Duration: 8 minutes 42.5 seconds.
13:28:14|5>  Duration: 9 minutes 9.1 seconds.
13:28:30|6>  Duration: 9 minutes 21.6 seconds.
13:28:33|4>  Duration: 9 minutes 31.3 seconds.
13:32:13|8>  Duration: 10 minutes 59.7 seconds
13:35:37|9>  Duration: 13 minutes 31.0 seconds
13:41:06|10> Duration: 15 minutes 17.6 seconds
13:47:38|11> Duration: 20 minutes 49.8 seconds
13:54:24|12> Duration: 26 minutes 16.3 seconds
13:59:03|13> Duration: 30 minutes 34.1 seconds
14:00:37|14> Duration: 32 minutes 6.1 seconds.
14:03:38|15> Duration: 35 minutes 3.2 seconds.
14:10:05|16> Duration: 37 minutes 36.4 seconds
14:16:19|17> Duration: 40 minutes 29.0 seconds
14:24:35|18> Duration: 43 minutes 14.4 seconds
14:34:04|19> Duration: 46 minutes 5.2 seconds.
14:42:22|20> Duration: 47 minutes 37.8 seconds
14:48:19|21> Duration: 48 minutes 46.5 seconds
14:52:22|22> Duration: 51 minutes 25.9 seconds
15:00:08|23> Duration: 56 minutes 8.9 seconds.
15:10:25|24> Duration: 59 minutes 35.7 seconds.
15:18:45|25> Duration: 1 hour 2 minutes 7.9 seconds.

Note: I have also tried splitting it across WorkspaceRunner (as suggested in one of the blogs), but this was extremely slow with passing each From-To line to the WorkspaceRunner. I may try reworking that to get the workspace in the runner to read their own groups of from-to lines from a file. But that's a bit of a distraction... I can't see why the original single-thread version is running exponentially slower.

Your suggestions appreciated!

Hi @richardt

Can I get you to check a couple of things when you run this? I'm just wondering what the task manager tells you the memory usage is, and whether the log file reports any messages about "reorganizing memory resources" or something like that.

In fact it would help to see this part of the log file:

System Status: 86.20 GB of disk space available in the FME temporary folder
System Status: 128.00 TB of virtual memory available
Operating System: Microsoft Windows Server 10 Server 4.0 64-bit  (Build 14393)
FME Platform: WIN64
Locale: en_US
Code Page: 1252  (ANSI - Latin I)
FME Configuration: Process limit is 16.00 GB of physical memory
FME Configuration: Start freeing memory when process usage exceeds 48.00 GB of virtual memory
FME Configuration: Stop freeing memory when process usage is below 36.00 GB of virtual memory

I'm just making a few guesses at first, but I'm wondering about the memory usage and availability, and if we have a memory leak in there (which a continually increasing memory use in the Task Manager may indicate).

The other thing I'd suggest is to make sure caching is turned off, since it's only for debugging purposes, not for production (I'd say 100,000+ links is definitely 'production').

The Parallel Processing and WorkspaceRunner options, should make a difference, but only to the extent that it's able to do 7-8 calculations simultaneously. If the underlying workspace is having problems, I doubt they would help (plus when the network is this large there's a lot of overhead to each process).

The other possibility is that the logging is going a bit 'wonky'. It can be hard to interpret sometimes. What you could do is put a breakpoint onto the connection going into the ShortestPathFinder:From-To port (right-click the connection and Add Breakpoint). Turn on Run > Stop at Breakpoints and run the workspace.

When the first feature hits the ShortestPathFinder the workspace should pause and a Feature Inspection window open up. Clicking the Next Breakpoint button on the Feature Inspection window and noting how much time it actually takes to process that feature should help determine if the log is actually telling the truth, and each feature is taking exponentially longer than the previous.

I hope that helps, or at least gets us started on a solution. I'm trying to process a lot of features on a network as a test myself. Although my network isn't as large, I'm working up to testing 140,000 From-To lines and I haven't seen any issues so far. 35,000 lines took 3' 25" and 70,000 lines took 6' 50", so exactly double. 

Regards

Mark


@mark2atsafe - thanks for your rapid response. I've also had a response from Mark Stoakes @ Safe on this and will try to package up suitable data and workbench this morning for you (both) to try out: do you have a direct email/message I can contact you on for download details?

Re your questions:

  • I have avoided running in Feature Caching mode.
  • Looking at task manager, when I was running with a single thread it never seemed to be using more than just over 2GB of memory (total=16GB). With 8 threads, my total memory usage was about 11GB.
  • As I have now broken the task up into groups which I see logged separately (and which I see visually outputting to the next stage of my workbench in bursts) I am fairly confident that it isn't a logging problem.
  • System data as requested:
System Status: 122.03 GB of disk space available in the FME temporary folder (C:\Users\THOM8626\AppData\Local\Temp)
System Status: 128.00 TB of virtual memory available
Operating System: Microsoft Windows 10 64-bit  (Build 18362)
FME Platform: WIN64
Locale: en_GB
Code Page: 1252  (ANSI - Latin I)
FME Configuration: Process limit is 15.38 GB of physical memory
FME Configuration: Start freeing memory when process usage exceeds 46.15 GB of virtual memory
FME Configuration: Stop freeing memory when process usage is below 34.61 GB of virtual memory

The range of different memory messages shown here (I can't see a way to attach full log in a response), with ShortestPathFinder sub-process 0 being the first of 23 (this is a grouped 8-thread run):

0>   START - ProcessID: 17132, peak process memory usage: 30200 kB, current process memory usage: 30100 kB
0>   FME Configuration: Command line arguments are `C:\Program Files\FME 2019.1.0.0\fmeworker' `C:\Users\THOM8626\AppData\Local\Temp\childProcMap1582649868908_9252.fme' `-WORKER_CAPABILITY' `15L1107U57L95U7' `LOG_FILENAME' `C:\NetCreate\fme\NetCreate_ffs\NetCreate_0.log' `-LOG_PREPEND_ID' `0' `--SOURCE_PORT_OUT' `65420' `--SOURCE_PORT_IN' `65419'
0>   FME Configuration: Connection Storage: 'C:\Users\THOM8626\AppData\Roaming\Safe Software\FME\'
0>   System Status: 121.92 GB of disk space available in the FME temporary folder (C:\Users\THOM8626\AppData\Local\Temp)
0>   System Status: 128.00 TB of virtual memory available
0>   FME Configuration: Process limit is 15.38 GB of physical memory
0>   FME Configuration: Start freeing memory when process usage exceeds 46.15 GB of virtual memory
0>   FME Configuration: Stop freeing memory when process usage is below 34.61 GB of virtual memory

(Lots of messages of the form..)
0>   ShortestPathFinderMultiCore_ShortestPathFinder (NetworkFactory): Processed 13000 of 2364628 result
0>   ResourceManager: Optimizing Memory Usage.  Please wait...

0>   ShortestPathFinderMultiCore_ShortestPathFinder (NetworkFactory): Processed 1846000 of 2364628 result
WARN  |0>   Failed to free sufficient memory to reach the process usage limit

0>   FME Session Duration: 11 minutes 59.1 seconds. (CPU: 417.0s user, 54.2s system)
0>   END - ProcessID: 17132, peak process memory usage: 820788 kB, current process memory usage: 52788 kB

FME Session Duration: 7 hours 19 minutes 56.5 seconds. (CPU: 755.3s user, 91.8s system)
END - ProcessID: 9252, peak process memory usage: 1060492 kB, current process memory usage: 254772 kB

Richard


@richardt A couple of things. The ShortestPathFinder appeared to be exponentially slower because the from-to vectors were sorted form shortest to longest. So the shortest shortest paths were being determined first and then the longer ones last - which take more time in a complex network.

But the ShortestPathFinder is still slow for a large number of from-to vectors.

In FME 2021 (beta) ShortestPathFinder has been updated with several changes:

  • We have changed the underlying algorithm to A*. A simple discussion comparing algorithms here 
  • added multi-threading - this will use all CPUs and consume more memory
  • added an optimization for Attribute Accumulation - if you do NOT check Generate List if you don't need the lists then ShortestPathFinder is smarter
  • added an optimization for single node from-to vectors, i.e. if all the vectors terminate at a common node - which is your case

Example performance gain for about 4000 vectors from 170secs to about 15secs


Reply