deployed Batch runs very slow as scheduled task

Hello community!

I have 7 Batches (created via Batch deploy), that read spatial data from an oracle 10 database into SQLite. The biggest user takes, when batch is started manually, about 18 minutes. When this batch is started using windows scheduler, it takes up to 3 hours! Same for all the others.

I'm using FME 2013 SP1 Oracle Edition on Windows Server 2012.

neither the oracle server nor the fme server is under heavy load. (1-5% cpu).

scheduled task are started as same user which starts manually the batches.

(admin, highest privileges). Is there an option to tell each task its priority?

is there a problem when batchfiles and tclfiles are located on desktop?

(workspace are located in user\\documents\\my fme workspaces)

would be thankful for any advice.

best regards, chris.

Page 1 / 1

Hi Chris,

you might want to compare the log files from the scheduled run and the manual execution. The timestamps ought to give you an indication of where the time is spent. That would be a good first step, anyway.

David

Hey David, thx for your answer!

I did that already, and all i could see was, that when scheduled,

fme reads feature sources much slower compared to manually started.

see following cutout of one "manually started batch":

2013-04-24 11:18:11| 11.8| 0.0|INFORM|Creating FdoFeatureClass 'Default:GA_V_DSP_PIPE_TBL'

2013-04-24 11:18:12| 12.0| 0.2|INFORM|Reading source feature # 15000

2013-04-24 11:18:18| 13.9| 2.0|INFORM|Reading source feature # 17500

2013-04-24 11:18:24| 15.8| 1.9|INFORM|Reading source feature # 20000

2013-04-24 11:18:30| 17.8| 2.0|INFORM|Reading source feature # 22500

2013-04-24 11:18:36| 19.7| 1.8|INFORM|Reading source feature # 25000

2013-04-24 11:18:39| 20.7| 1.0|INFORM|ORACLE Reader: Executing SQL Statement `SELECT "GA_V_DSP_PIPE"."FID", "GA_V_DSP_PIPE"."FID_ATTR", "GA_V_DSP_PIPE"."ID_FUNCTION", "GA_V_DSP_PIPE"."COLOR_RGB", "GA_V_DSP_PIPE"."PRESS_NARRATIVE", "GA_V_DSP_PIPE"."ID_DISPOSITION_STATE", "GA_V_DSP_PIPE"."ID_ACCURACY", "GA_V_DSP_PIPE"."DATUM", "GA_V_DSP_PIPE"."DIAMETER_INSIDE", "GA_V_DSP_PIPE"."DIAMETER_OUTSIDE", "GA_V_DSP_PIPE"."DIAMETER_NOMINAL", "GA_V_DSP_PIPE"."GEOM" FROM "GA_V_DSP_PIPE"' to obtain features for feature type `GA_V_DSP_PIPE'

2013-04-24 11:18:39| 20.7| 0.0|INFORM|Creating FdoFeatureClass 'Default:GA_V_DSP_PIPE'

2013-04-24 11:18:43| 21.7| 0.9|INFORM|Reading source feature # 27500

2013-04-24 11:18:49| 23.7| 2.1|INFORM|Reading source feature # 30000

2013-04-24 11:18:56| 25.9| 2.2|INFORM|Reading source feature # 32500

2013-04-24 11:19:02| 27.8| 1.9|INFORM|Reading source feature # 35000

2013-04-24 11:19:08| 30.0| 2.1|INFORM|Reading source feature # 37500

2013-04-24 11:19:15| 31.9| 2.0|INFORM|Reading source feature # 40000

2013-04-24 11:19:21| 34.0| 2.1|INFORM|Reading source feature # 42500

2013-04-24 11:26:02| 153.9| 0.0|INFORM|Translation was SUCCESSFUL with 20 warning(s) (202635 feature(s) output)

2013-04-24 11:26:02| 153.9| 0.0|INFORM|FME Session Duration: 8 minutes 37.6 seconds. (CPU: 94.1s user, 59.7s system)

2013-04-24 11:26:02| 153.9| 0.0|INFORM|END - ProcessID: 3748, peak process memory usage: 100876 kB, current process memory usage: 83580 kB

And now the cutout of the same batch, started via scheduler:

2013-04-24 17:17:02| 2.2| 0.0|INFORM|Creating FdoFeatureClass 'Default:GA_V_DSP_PIPE_TBL'

2013-04-24 17:17:18| 2.2| 0.0|INFORM|Reading source feature # 15000

2013-04-24 17:20:09| 2.3| 0.1|INFORM|Reading source feature # 17500

2013-04-24 17:22:51| 2.4| 0.1|INFORM|Reading source feature # 20000

2013-04-24 17:25:32| 2.4| 0.1|INFORM|Reading source feature # 22500

2013-04-24 17:28:15| 2.6| 0.1|INFORM|Reading source feature # 25000

2013-04-24 17:29:30| 2.6| 0.0|INFORM|ORACLE Reader: Executing SQL Statement `SELECT "GA_V_DSP_PIPE"."FID", "GA_V_DSP_PIPE"."FID_ATTR", "GA_V_DSP_PIPE"."ID_FUNCTION", "GA_V_DSP_PIPE"."COLOR_RGB", "GA_V_DSP_PIPE"."PRESS_NARRATIVE", "GA_V_DSP_PIPE"."ID_DISPOSITION_STATE", "GA_V_DSP_PIPE"."ID_ACCURACY", "GA_V_DSP_PIPE"."DATUM", "GA_V_DSP_PIPE"."DIAMETER_INSIDE", "GA_V_DSP_PIPE"."DIAMETER_OUTSIDE", "GA_V_DSP_PIPE"."DIAMETER_NOMINAL", "GA_V_DSP_PIPE"."GEOM" FROM "GA_V_DSP_PIPE"' to obtain features for feature type `GA_V_DSP_PIPE'

2013-04-24 17:29:30| 2.6| 0.0|INFORM|Creating FdoFeatureClass 'Default:GA_V_DSP_PIPE'

2013-04-24 17:30:57| 2.7| 0.1|INFORM|Reading source feature # 27500

2013-04-24 17:33:38| 2.9| 0.2|INFORM|Reading source feature # 30000

2013-04-24 17:36:19| 3.1| 0.2|INFORM|Reading source feature # 32500

2013-04-24 17:39:00| 3.2| 0.2|INFORM|Reading source feature # 35000

2013-04-24 17:41:41| 3.5| 0.2|INFORM|Reading source feature # 37500

2013-04-24 17:45:20| 3.8| 0.4|INFORM|Reading source feature # 40000

2013-04-24 17:48:45| 4.2| 0.4|INFORM|Reading source feature # 42500

2013-04-24 21:16:07| 12.3| 0.0|INFORM|Translation was SUCCESSFUL with 20 warning(s) (202635 feature(s) output)

2013-04-24 21:16:07| 12.3| 0.0|INFORM|FME Session Duration: 4 hours 15 minutes 52.8 seconds. (CPU: 9.4s user, 2.8s system)

2013-04-24 21:16:07| 12.3| 0.0|INFORM|END - ProcessID: 2720, peak process memory usage: 101896 kB, current process memory usage: 83572 kB

Hi,

It is possible that you need to adjust an additional parameter for the scheduled task, as they might run with a lower than normal memory priority on some Windows versions (this is not the same as the process priority).

Take a look at the answer to the related question here. It might be what you're looking for.

Please let us know if it solves the problem.

David

Hi,

Another option would be to use this software, (prio) to allocate a higher taskng priority to the job.

Hope this helps

Hi Chris,

As a matter of interest I looked at your log and saw:

2013-04-24 17:17:18| 2.2| 0.0|INFORM|Reading source feature # 15000

2013-04-24 17:20:09| 2.3| 0.1|INFORM|Reading source feature # 17500

There you have a step that takes nearly 3 minutes (17:17:18 - 17:20:09) but the FME processing time is only 0.1 seconds (3rd column). So I think that whatever the slowdown is, it is not related to the FME engine, as such.

But is it related to reading data? It's hard to tell from the log what exactly is going on at any one point. Although that steps says "Reading" it could also be doing transformation (if there is any) and even writing.

The only way to be sure would be to put a FeatureHolder transformer after the reader. Then transformation/writing won't start until after the reading is done. If you try this and the numbers improve for that section then you can tell the slowdown is not in reading. That might help diagnose the problem.

Anyway, you said that the machines aren't under a heavy load so I can't imagine why the priority would make such a difference (if there were a hundred other processes I could understand it). The system CPU time being logged is negligable too and the peak memory usage doesn't look that high, so I'm baffled as to why the system would be slower.

Besides that I suppose there is database response and network traffic. Is there a way to log queries in the database to see how long they take? I'd be interested to know if the queries are taking longer somehow. I somehow see that as being more likely than network slowdowns.

What about temporary disk space etc? Can you post the top part of the logs too, to compare the two sections? To see if the machine specs/memory use is being handled differently?

Hope this is of some use

Mark

Thank you all for your answers!

David was right, assuming lower priorities using task scheduler.

as default, when a process is manually started, it runs in realtime (priority = 0).

when using task scheduler, processes are started with priority = 7. In my case, this caused the fme worker to read very slow.

With the import/export method highlighted by David, it worked now.

Same processing time like manually started.

THANK YOU GUYS FOR YOUR SUPPORT!

Reply

Community Stats

Reply

Community Stats

Sign up

An FME Account is required to contribute

Login to the community

An FME Account is required to contribute

Scanning file for viruses.

This file cannot be downloaded