Print geoprocessing service runs very slow on the first run

BogdanMorosanu1 · ‎02-14-2018

Hello,

I’ve developed a custom print service for ArcGIS Server using a very similar approach to this one. When this service is called for the first time in a day, it times out or it requires 20-30 mins to complete. After this happens, everything seems to be back to normal and the service runs in approx. 2-3 mins. I would much appreciate any thoughts of why this is happening or how it can be fixed.

Please find details below:

ArcGIS Servers (10.4.1) geoprocessing service config:

Execution mode: Asynchronous
Minimum/ Maximum number of instances per machine: 1/4
The maximum time a client can use a service: 1800 secs
The maximum time a client will wait to get a service: 400 secs
The maximum time an idle instance can be kept running: 1800 secs
Run instances of this configuration: In a separate process for each instance (high isolation)
Recycle this configuration every: 24 hours, Starting at: 00:00

ArcGIS Server logs:

Processing request took longer than the usage timeout for service ../Print.GPServer'. Server request timed out. Check that the usage timeout is appropriately configured for such requests.

Python script info:

Imports: arcpy, os, uuid, json
A template which has all the layers (approx. 80) of the web map is being used to compare the legend entries with the ones from the web app. The main purpose of it is to use the symbology of the template, not the one used by the web app. The template references Feature Classes stored in Oracle.

General remarks:

If I capture the JSON string sent to the server by the print widget and run it locally in ArcMap, it always completes in less than 2 minutes
I think it is related with the service being recycled each night at 00:00 which is why the first run takes so long

NB:

I would be interested to know if there is another option rather than just increasing the time a client can use this service (I’ve got 30 mins already)

JonathanQuinn · ‎02-14-2018

It'd be interesting to know what part is taking so long. If you were to add print statements throughout the script, (arcpy.AddMessage()), and turn on Info messages, perhaps you'd be able to tell if the SOC is simply taking a long time to initialize or there's a step within the script somewhere that takes a long time to complete.

BogdanMorosanu1 · ‎02-21-2018

Hi Jonathan,

The logs are below. Info section describes the arcpy function called by my script. The required time by each function is printed in the next logged line.
It looks like every function called by my script is slower in the first run, especially ConvertWebMapToMapDocument (24 mins compared to 22 seconds)

Start Time: Tue Feb 20 10:46:09 2018
Running script PARprintPP...
Time: 10:46:25.351000; Duration from last logged action: 0:00:00.002000; Info: My first line of code...
Time: 10:46:25.364000; Duration from last logged action: 0:00:00.001000; Info: GetParameterAsText...
Time: 10:46:25.377000; Duration from last logged action: 0:00:00.001000; Info: ConvertWebMapToMapDocument...
Time: 11:10:39.084000; Duration from last logged action: 0:24:13.699000; Info: ListDataFrames...
Time: 11:10:39.149000; Duration from last logged action: 0:00:00; Info: ListDataFrames...
Time: 11:10:39.194000; Duration from last logged action: 0:00:00.025000; Info: ListLayers to collect info...
Time: 11:10:39.439000; Duration from last logged action: 0:00:00.227000; Info: MoveLayer...
Time: 11:12:27.515000; Duration from last logged action: 0:01:48.058000; Info: ListLayoutElements...
Time: 11:12:27.955000; Duration from last logged action: 0:00:00.425000; Info: ListLayers to apply changes...
Time: 11:12:28.291000; Duration from last logged action: 0:00:00.323000; Info: listLegendItemLayers...
Time: 11:12:32.671000; Duration from last logged action: 0:00:04.366000; Info: ExportToPDF...
Time: 11:15:42.012000; Duration from last logged action: 0:03:09.329000; Info: Clean up...
Time: 11:15:42.040000; Duration from last logged action: 0:00:00.013000; Info: Last line of code...
Completed script PARprintPP...
Succeeded at Tue Feb 20 11:15:44 2018 (Elapsed Time: 29 minutes 34 seconds)
Succeeded at Tue Feb 20 11:15:44 2018 (Elapsed Time: 29 minutes 34 seconds)
----------------------------------------------------------------------------------------------------------

Start Time: Tue Feb 20 11:42:54 2018
Running script PARprintPP
Time: 11:43:09.747000; Duration from last logged action: 0:00:00.001000; Info: My first line of code...
Time: 11:43:09.760000; Duration from last logged action: 0:00:00; Info: GetParameterAsText...
Time: 11:43:09.772000; Duration from last logged action: 0:00:00; Info: ConvertWebMapToMapDocument...
Time: 11:43:32.735000; Duration from last logged action: 0:00:22.950000; Info: ListDataFrames...
Time: 11:43:32.747000; Duration from last logged action: 0:00:00; Info: ListDataFrames...
Time: 11:43:32.778000; Duration from last logged action: 0:00:00.021000; Info: ListLayers to collect info...
Time: 11:43:32.968000; Duration from last logged action: 0:00:00.179000; Info: MoveLayer...
Time: 11:43:34.909000; Duration from last logged action: 0:00:01.930000; Info: ListLayoutElements...
Time: 11:43:35.341000; Duration from last logged action: 0:00:00.420000; Info: ListLayers to apply changes...
Time: 11:43:35.667000; Duration from last logged action: 0:00:00.313000; Info: listLegendItemLayers...
Time: 11:43:40.001000; Duration from last logged action: 0:00:04.317000; Info: ExportToPDF...
Time: 11:45:07.315000; Duration from last logged action: 0:01:27.306000; Info: Clean up...
Time: 11:45:07.341000; Duration from last logged action: 0:00:00.012000; Info: Last line of code...
Completed script PARprintPP...
Succeeded at Tue Feb 20 11:45:10 2018 (Elapsed Time: 2 minutes 16 seconds)
Succeeded at Tue Feb 20 11:45:10 2018 (Elapsed Time: 2 minutes 16 seconds)

Remark:
If I change the recycle time interval for my geoprocessing service to 1 hour and test it after the recycle process has been completed I get normal timings which suggests that the slow performance has to be related with something else, something that happens over the night with ArcGIS Server and/or the server where is being hosted.

JonathanQuinn · ‎02-27-2018

If you were to take Server out of it and just run a script that executes the ConvertWebMapToMapDocument function using the Server's included python, does it work? Test this in the same manner you're running the GP service, right in the morning.

BogdanMorosanu1 · ‎03-02-2018

Hi Jonathan.

Please find below my results. The first thing I did was to run my script on my machine (locally using a web map as JSON string prepared beforehand) with good results (1min 7sec). Then I ran the same test like last time (using the web map): two consecutive runs with similar results as my previous tests (54 mins for first run and 54 secs for second run).

Local run-----------------------------------------------------------------------
Start Time: Fri Mar 02 09:25:08 2018
Running script PARprintPP...
Time: 09:25:09.182000; Duration from last: 0:00:00; Info: My first line of code...
Time: 09:25:09.182000; Duration from last: 0:00:00; Info: GetParameterAsText...
Time: 09:25:09.182000; Duration from last: 0:00:00; Info: ConvertWebMapToMapDocument...
Time: 09:25:55.732000; Duration from last: 0:00:46.535000; Info: ListDataFrames...
Time: 09:25:55.732000; Duration from last: 0:00:00; Info: ListDataFrames...
Time: 09:25:55.732000; Duration from last: 0:00:00; Info: ListLayers to collect info...
Time: 09:25:55.794000; Duration from last: 0:00:00.062000; Info: MoveLayer...
Time: 09:25:55.982000; Duration from last: 0:00:00.188000; Info: ListLayoutElements...
Time: 09:25:55.997000; Duration from last: 0:00:00.015000; Info: ListLayers to apply changes...
Time: 09:25:56.075000; Duration from last: 0:00:00.078000; Info: listLegendItemLayers...
Time: 09:25:57.339000; Duration from last: 0:00:01.264000; Info: ListLayoutElements...
Time: 09:25:57.386000; Duration from last: 0:00:00.047000; Info: ExportToPNG...
Time: 09:26:15.762000; Duration from last: 0:00:18.376000; Info: Clean up...
Time: 09:26:15.762000; Duration from last: 0:00:00; Info: Last line of code...
Completed script PARprintPP...
Succeeded at Fri Mar 02 09:26:16 2018 (Elapsed Time: 1 minutes 7 seconds)

First Web run-----------------------------------------------------------------------
Start Time: Fri Mar 02 11:10:10 2018
Running script PARprintPP...
Time: 11:10:10.934000; Duration from last: 0:00:00.002000; Info: My first line of code...
Time: 11:10:10.937000; Duration from last: 0:00:00; Info: GetParameterAsText...
Time: 11:10:10.941000; Duration from last: 0:00:00.001000; Info: ConvertWebMapToMapDocument...
Time: 12:03:03.146000; Duration from last: 0:52:52.205000; Info: ListDataFrames...
Time: 12:03:03.152000; Duration from last: 0:00:00; Info: ListDataFrames...
Time: 12:03:03.174000; Duration from last: 0:00:00.019000; Info: ListLayers to collect info...
Time: 12:03:03.354000; Duration from last: 0:00:00.176000; Info: MoveLayer...
Time: 12:03:05.770000; Duration from last: 0:00:02.412000; Info: ListLayoutElements...
Time: 12:03:06.215000; Duration from last: 0:00:00.441000; Info: ListLayers to apply changes...
Time: 12:03:06.599000; Duration from last: 0:00:00.379000; Info: listLegendItemLayers...
Time: 12:03:10.864000; Duration from last: 0:00:04.260000; Info: ListLayoutElements...
Time: 12:03:10.916000; Duration from last: 0:00:00.047000; Info: ExportToPNG...
Time: 12:04:33.508000; Duration from last: 0:01:22.590000; Info: Clean up...
Time: 12:04:33.525000; Duration from last: 0:00:00.012000; Info: Last line of code...
Completed script PARprintPP...
Succeeded at Fri Mar 02 12:04:39 2018 (Elapsed Time: 54 minutes 29 seconds)

Second Web run-----------------------------------------------------------------------
Start Time: Fri Mar 02 12:54:46 2018"
Running script PARprintPP..."
Time: 12:54:47.011000; Duration from last: 0:00:00.001000; Info: My first line of code..."
Time: 12:54:47.014000; Duration from last: 0:00:00; Info: GetParameterAsText..."
Time: 12:54:47.018000; Duration from last: 0:00:00.001000; Info: ConvertWebMapToMapDocument..."
Time: 12:55:23.646000; Duration from last: 0:00:36.627000; Info: ListDataFrames..."
Time: 12:55:23.652000; Duration from last: 0:00:00; Info: ListDataFrames..."
Time: 12:55:23.673000; Duration from last: 0:00:00.018000; Info: ListLayers to collect info..."
Time: 12:55:23.852000; Duration from last: 0:00:00.175000; Info: MoveLayer..."
Time: 12:55:26.108000; Duration from last: 0:00:02.253000; Info: ListLayoutElements..."
Time: 12:55:26.536000; Duration from last: 0:00:00.424000; Info: ListLayers to apply changes..."
Time: 12:55:26.846000; Duration from last: 0:00:00.307000; Info: listLegendItemLayers..."
Time: 12:55:30.950000; Duration from last: 0:00:04.100000; Info: ListLayoutElements..."
Time: 12:55:30.994000; Duration from last: 0:00:00.040000; Info: ExportToPNG..."
Time: 12:55:38.124000; Duration from last: 0:00:07.127000; Info: Clean up..."
Time: 12:55:38.145000; Duration from last: 0:00:00.017000; Info: Last line of code..."
Completed script PARprintPP..."
Succeeded at Fri Mar 02 12:55:41 2018 (Elapsed Time: 54.63 seconds)"

Below is a diagram of how our ESRI infrastructure is configured. GIS011 is configured to run geoprocessing services. This is where my geoprocessing service is hosted but the print tool will call map services hosted on all servers (GIS014, GIS010, GIS011). The Web Map App is hosted on GIS012.

I also looked into this thread. Find below my configs on GIS012:

Advanced settings on ArcGISWebAdaptorAppPool:

All others:

Remark:

A restart on all the above servers will not trigger a slow run of my geoprocessing service.

balajiVaddadi · ‎05-07-2023

Any update for this print slow issue. We have similar issue. Kindly provide any solution.