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:
ArcGIS Server logs:
Python script info:
General remarks:
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)
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.
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.
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.
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.
Any update for this print slow issue. We have similar issue. Kindly provide any solution.