Refreshing of metadata takes >20 mins to complete

[Bhushan Puri]

Issue

Refreshing of metadata (single file or a folder from left pane) takes 5-20 mins to complete. A few more details:

• This only happens with one sandbox (CS102)
• First observed: 22nd Oct

Steps to reproduce

• Open a Salesforce project in Intellij
• Open any file (cmd+shift+O)
• Refresh that file (cmd+shift+opt+R)
• Status on the bottom says “Pending“ and the refresh completes in 5-20 mins

Attempts to resolve

• Deleted and re-created the project - No impact
• Removed and re-added the connection - No impact

Impact

Huge blocker for us as it makes development very slow and frustrating. Since we are in the middle of development cycle, almost impossible to move to another sandbox. Also, very difficult to refresh this sandbox (in an anticipation that the new instance will not be CS102)

‌

[Scott Wells]

The primary reason for this would be long Salesforce metadata API queues for that particular org. This is the most likely cause. To be 100% sure I'd need to see a log for the retrieval with debug logging enabled for metadata retrieval. What I'd expect to see if that's that case is that it submits the job to the server and polls for its completion for a very long time, likely with the job in a queue/pending state.

Let's start there. However, I also see something potentially problematic in your log. Are you storing your projects under OneDrive? If so, you'll need to move them outside of any cloud drive solution as that creates severe locking contention on the project files between the IDE and the cloud drive service.

[Bhushan Puri]

Hey @scott wells , thanks for your quick response. I added the Metadata Retrieval Debug Logging and refreshed a single class. Attached are the logs (in the original ticket, as I could not upload that in this comment)

I find it quite interesting that OneDrive could be a trouble maker for us. I have all my projects in OneDrive and have been like this for over 2 years and this is the first time, I am witnessing such long times for the retrieval.

[Scott Wells]

Thanks for the log. It confirms that all of the time is spent waiting for Salesforce to process the retrieval request:

2020-10-26 15:21:36,621 [262615301]  DEBUG - lder.ForceComMetadataRetriever - Submitted retrieve request with async process ID 09S1j0000015BilEAE 
2020-10-26 15:21:36,621 [262615301]  DEBUG - lder.ForceComMetadataRetriever - Polling the status of the retrieve request. 
2020-10-26 15:21:36,815 [262615495]  DEBUG - lder.ForceComMetadataRetriever - Status: Pending 
2020-10-26 15:21:36,815 [262615495]  DEBUG - lder.ForceComMetadataRetriever - Retrieve request is still processing. 
2020-10-26 15:21:36,815 [262615495]  DEBUG - .VariableLengthPollingInterval - AbstractForceComMetadataRetriever.retrieve: Using polling interval 1000 ms for polling iteration 1. 
2020-10-26 15:21:37,821 [262616501]  DEBUG - lder.ForceComMetadataRetriever - Polling the status of the retrieve request. 
2020-10-26 15:21:37,904 [262616584]  DEBUG - lder.ForceComMetadataRetriever - Status: Pending 
2020-10-26 15:21:37,904 [262616584]  DEBUG - lder.ForceComMetadataRetriever - Retrieve request is still processing. 
2020-10-26 15:21:37,904 [262616584]  DEBUG - .VariableLengthPollingInterval - AbstractForceComMetadataRetriever.retrieve: Using polling interval 1000 ms for polling iteration 2. 
2020-10-26 15:21:38,904 [262617584]  DEBUG - lder.ForceComMetadataRetriever - Polling the status of the retrieve request. 
2020-10-26 15:21:38,976 [262617656]  DEBUG - lder.ForceComMetadataRetriever - Status: Pending 
2020-10-26 15:21:38,976 [262617656]  DEBUG - lder.ForceComMetadataRetriever - Retrieve request is still processing. 
...
2020-10-26 15:25:46,527 [262865207]  DEBUG - .VariableLengthPollingInterval - AbstractForceComMetadataRetriever.retrieve: Using polling interval 5000 ms for polling iteration 66. 
2020-10-26 15:25:51,533 [262870213]  DEBUG - lder.ForceComMetadataRetriever - Polling the status of the retrieve request. 
2020-10-26 15:25:51,736 [262870416]  DEBUG - lder.ForceComMetadataRetriever - Status: Pending 
2020-10-26 15:25:51,736 [262870416]  DEBUG - lder.ForceComMetadataRetriever - Retrieve request is still processing. 
2020-10-26 15:25:51,736 [262870416]  DEBUG - .VariableLengthPollingInterval - AbstractForceComMetadataRetriever.retrieve: Using polling interval 5000 ms for polling iteration 67. 
2020-10-26 15:25:56,738 [262875418]  DEBUG - lder.ForceComMetadataRetriever - Polling the status of the retrieve request. 
2020-10-26 15:25:56,933 [262875613]  DEBUG - lder.ForceComMetadataRetriever - Status: Succeeded 
2020-10-26 15:25:56,933 [262875613]  DEBUG - lder.ForceComMetadataRetriever - Retrieve complete. 
2020-10-26 15:25:57,452 [262876132]  DEBUG - lder.ForceComMetadataRetriever - Retrieved an archive of size 4324 bytes. 

As you can see, after submission the job was in a pending state until the final seconds after which the requested retrieval payload was returned. Unfortunately there's nothing in IC that can be changed for this as it's 100% in the Salesforce servers/queues. You would need to log a support case with Salesforce and can include the specific retrieval job IDs emitted into these logs as examples of these long retrieval times.

[Scott Wells]

Confirmed to be Salesforce queueing.

[Bhushan Puri]

Very clear. Thanks a lot for looking into this.