Low performance on retrieve/deploy after configuring SFDX

[Gabriela Tudor]

After migrating from MDAPI to Salesforce DX, the connection with the org is very slow when trying to retrieve/deploy changes. It takes several minutes in order to load files from server.

In some cases, retrieving is not working at all.

It also happened that the Refresh Metadata option has disappeared from the context menu, as you can see in the screenshot below.

‌

[Scott Wells]

Hi. This could very well just be the CLI, though let's be certain. Please enable debug logging for Salesforce DX, metadata deployment, and metadata retrieval, reproduce this behavior, and either attach your idea.log* file(s) or email them to [e-mail] for review.

Regarding the Refresh button disappearing from the retrieval window, it's because this is set up as a scratch org project and the refresh action conflicts with the pull metadata action because it affects metadata files in-place. Are you wanting to work with this project as a source-tracked scratch org?

[Dirk van de Lindt]

@Scott Wells: thank you for your quick response!

[Scott Wells]

Hi. Just following up here as I've never seen any diagnostic logs. Anything new to share? Is this still a problem for you?

[Gabriela Tudor]

Hi @Scott Wells. We tried to reproduce this issue few times, but it worked normal. Today we managed to reproduce it and I have attached two files: idea.log (this is the log for the Retrieve metadata operation) and ideaRefresh.log (this is the log for the Refresh metadata operation). Thank you!

[Scott Wells]

Hi. Thanks for the logs. While I don't see anything 100% conclusive, I do see some potential red flags. For one thing, it looks like this IDE install may not be in a good state, at least based on numerous log entries like the following:

2021-09-29 12:28:40,108 [43105732]   WARN - llij.ide.plugins.PluginManager - Plugin "GRAS Syntax" is incompatible (since build 193.6494 > IC-193.5662.53)
2021-09-29 12:28:40,108 [43105732]   WARN - llij.ide.plugins.PluginManager - Plugin "CVS" is incompatible (since build 193.6911 > IC-193.5662.53)
2021-09-29 12:28:40,108 [43105732]   WARN - llij.ide.plugins.PluginManager - Plugin "Subversion" is incompatible (since build 193.7288 > IC-193.5662.53)
2021-09-29 12:28:40,108 [43105732]   WARN - llij.ide.plugins.PluginManager - Plugin "Mercurial" is incompatible (since build 193.6015 > IC-193.5662.53)
2021-09-29 12:28:40,108 [43105732]   WARN - llij.ide.plugins.PluginManager - Plugin "ChangeReminder" is incompatible (since build 193.6911 > IC-193.5662.53)
...

One thing I've noticed is that repeated in-place upgrades of the base IDE can leave things in a questionable state that can be resolved by a simple base IDE reinstall. I would recommend that you do a full uninstall/reinstall of the JetBrains IDE. You won't lose your configuration as long as you don't check the option to remove configuration files when you do the uninstall. When reinstalling, I would recommend that you use 2021.1.3 even though it's not the latest. While IC2 supports 2021.2, there have been issues with it. It seems like they're mostly addressed with the latest patch (2021.2.2 and the latest IC2), but since the goal here is going to be to resolve the issues you're having, I think starting with a known quantity would be a good idea.

I also see connection timeout issues in your log when communicating with the Salesforce servers, e.g.:

2021-09-29 12:34:20,494 [43446118]   WARN - xf.phase.PhaseInterceptorChain - Interceptor for {http://soap.sforce.com/2006/04/metadata}MetadataService#{http://soap.sforce.com/2006/04/metadata}listMetadata has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
    at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67)
    ...
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.lambda$process$0(SourceFile:255)
    at com.illuminatedcloud.client.ForceComApiClient.runWithClient(SourceFile:226)
    at com.illuminatedcloud.client.ForceComApiClient.runWithClient(SourceFile:341)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.process(SourceFile:250)
    at com.illuminatedcloud.intellij.configCache.FilePropertiesCache$2.process(SourceFile:229)
    at com.illuminatedcloud.util.ParallelBatchProcessorExecutor.lambda$execute$0(SourceFile:65)
    ...
Caused by: javax.net.ssl.SSLException: SSLException invoking https://mijnpostnl--retaildev.my.salesforce.com/services/Soap/m/48.0/00D5E000000A5xWUAS: Read timed out
    ...
    at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:1402)
    at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1386)
    at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
    at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673)
    at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
    ... 18 more

While that particular one isn't in the deploy or retrieve logic, it does indicate that there may be issues communicating with your Salesforce org. Do you know if your machine is connected to a restricted network? If it is, you might need to configure the IDE accordingly. Please see the topics on Configuring Network Access in the user guide.

Let's start there and see how things look.

[Scott Wells]

I'm going to resolve this given that I haven't heard about it for a while now, and it sounds like the behavior was correct toward the end of this discussion. If you do see it again, please reopen and provide the requested diagnostic info.

[Gabriela Tudor]

Hi, I came back with other logs because someone else has reported the same issue. After reinstalling the JetBrains IDE, the Refresh button it’s working again. But the metadata retrieval still takes long and after it has finished, there was no metadata retrieved actually. Thanks and sorry for the late reply.

[Scott Wells]

Thank you for the log. Okay, I've seen this reported by one other person. It seems to due to a regression in the JetBrains plugin SDK several releases back for which I had to implement a workaround based on guidance from JetBrains. And it appears that workaround may sometimes be extremely slow, though I'm not sure what triggers that behavior. I'll include some additional debug logging in this week's new build (likely released tomorrow morning) to help confirm this hypothesis. Once your team members update to that new version, please provide another log that will hopefully narrow it down further. I'll also see whether there's anything else I can do with this required workaround to get the performance back in line with expected.

[Gabriela Tudor]

Thank you for your quick reply, I will send the logs after we update to the latest version.

[Scott Wells]

Hopefully good news...I think I've implemented a workaround for the performance issues. I'll be including that change in the new official build as well, so I'll be interested to know whether it does or does not address the issue for you and for your team.

[Scott Wells]

These changes have been delivered in 2.1.9.4. Please let me know if they help (or hurt, though hopefully not!), and if they don't help, please provide a new log for review.

[Micu Bianca Andreea]

Hello! Yesterday I updated Illuminated cloud version to 2.1.9.4. The first retrieve I made was very fast, with only one file. The second one had 4 files but it took around 10 minutes. The outcome of both retrievals was: retrieve complete - no components were retrieved. I went to commit tab in intellij and refreshed it and after that I could saw my files. Today I also updated CLI and it seems to work better, with an average time of retrieval and the outcome was that I have successfully retrieved files. Thank you very much for your guidance and for the quick fix. I hope none of the issues will come back. In case it does, I will provide again the logs (actually, I have one log generated from yesterday, when I retrieved multiple files and Gabriela can attach it for you if it’s needed). Again, thank you for your fix! I will keep an eye on it to see if any issue will happen again.

[Scott Wells]

Hi, Micu. Just so I understand, with the latest version of IC2 and the latest version of the CLI, you're seeing proper behavior--retrieved files are showing up without the need for an explicit refresh--and better/expected retrieval performance, correct? If so, please keep me posted if that changes. If not and you're still seeing issues, please provide logs for instances of those issues so that I can investigate.

[Micu Bianca Andreea]

Hello, Scott! On Friday after updating IC2 and CLI, there are moments when it works fine, with an acceptable loading time, but when I try to retrieve multiple files, maybe LWC components, it takes so much time, 30 minutes last time for 4 LWC. @Alina attached the log for you to have a look on that. As timing in the log: at 16:01 I wanted to retrieve the files and at 16:28 if I remember correctly, the retrieval was completed. Please, if you could have a look on that, would be great. Thank you!

[Scott Wells]

Yes, I can see the following in the log:

2021-10-29 16:01:17,996 [19991604]  DEBUG - .ForceComSfdxMetadataRetriever - Collecting retrieved files under /private/var/folders/6f/5hg4m4f51s904n69hwh_nskm0000gn/T/postnl_commercial-BPXDEV-retrieve2/tmp. 
...
2021-10-29 16:28:08,305 [21601913]  DEBUG - .ForceComSfdxMetadataRetriever - Found 13 files under /private/var/folders/6f/5hg4m4f51s904n69hwh_nskm0000gn/T/postnl_commercial-BPXDEV-retrieve2/tmp. 

Okay, so it definitely looks like this is not resolved yet. JetBrains actually had another suggestion that I'll implement today. What I'd like to do is post a build with that suggestion implemented here for your team to try. I'll let you know when it's ready and how to use it.

[Scott Wells]

Micu and Alina, I've attached a custom build that's the same as 2.1.9.4 but with two recommendations from JetBrains implemented. Please download the attached archive--but don't extract it--and install it using Settings/Preferences > Plugins > Install plugin from disk (under the gear drop-down menu). Then please try to reproduce the retrieval performance issue.

If it does recur, JetBrains has asked for a CPU profiling snapshot of the retrieval operation. If you have a (relatively?) reliable method of reproducing this behavior, just before performing the retrieve use Help > Diagnostic Tools > Start CPU Usage Profiling, then perform the retrieve, and when that finally completes, you can use Help > Diagnostic Tools > Start CPU Usage Profiling which will create a snapshot .zip archive which I'd like for you to attach for review. That file will only contain performance metrics, so there shouldn't be any sensitive information in it.

Please let me know your findings after installing the attached build.

[Scott Wells]

Moving back to an open state since we're still working through the issue.

[Scott Wells]

Hi, just checking in to see if you'd had a chance to try the attached build and, if so, whether it had helped with the retrieve performance issue.

[Scott Wells]

New prospective fix (same as in the previously-attached build) delivered in 2.1.9.5. Please let me know whether it resolves the issue for you after updating. If not, please reopen this issue with new logs from that build.

[Micu Bianca Andreea]

Hello Scott! Sorry for not getting back to you with an update, but those days were very busy and I didn’t have the time needed to configure my Intellij. I am sorry for the delay.

I updated my Illuminated Cloud and it seems that everything runs smooth at the moment, the retrieval was fast and complete, the files were retrieved in the correct folder. Thank you very much for the support! I hope this issue won’t happen again and in case it does, I will come back with the logs. But.. fingers crossed! Thank you one more time for your help!

[Scott Wells]

No issues on the delayed response. I certainly understand that you all have plenty of other things going on. I'm glad to hear that the latest build seems to be helping, though! If you do see retrieval issues--whether performance (that's not attributable to the server queues) or functional--please let me know and I'll take another look.

[Arun Ganeshamoorthy]

I am facing this issue for last 1 week and have upgraded the versions to latest IntelliJ 2022.1.3 and IC2 2.2.2.7 versions. One Apex Class is not retrieved even after 20 Mins.

[Scott Wells]

Arun, this is almost certainly due to server-side queueing in your Salesforce org as IC2 just creates a deployment or retrieval job as appropriate and polls the server for completion. You can confirm this by enabling debug logging for Metadata Deployment and/or Metadata Retrieval and the next time you see this behavior, grab your idea.log file and you'll likely see repeated polling of the job status. I'm happy to look at the log if you want to attach it here so I can explain what is happening. Unfortunately that type of behavior is not under IC2's control and, assuming that's what's happening, you would need to file a support case with Salesforce. Let's confirm the behavior first, though.

[Arun Ganeshamoorthy]

  <div class="preview-container wiki-content"><!-- loaded via ajax --></div>
  <div class="mask"></div>
</div>

</div> </form>

[Scott Wells]

Thank you. Yes, that's exactly what's happening. Here's the relevant log extract (with the middle part represented by ...):

2022-07-14 20:59:49,284 [  74267]   FINE - #c.i.i.b.ForceComMetadataRetriever - Polling the status of the retrieve request.
2022-07-14 20:59:49,402 [  74385]   FINE - #c.i.i.b.ForceComMetadataRetriever - Status: Pending
2022-07-14 20:59:49,402 [  74385]   FINE - #c.i.i.b.ForceComMetadataRetriever - Retrieve request is still processing.
2022-07-14 20:59:49,403 [  74386]   FINE - #c.i.u.VariableLengthPollingInterval - ForceComMetadataRetriever.retrieve: Using polling interval 1000 ms for polling iteration 2.
2022-07-14 20:59:50,412 [  75395]   FINE - #c.i.i.b.ForceComMetadataRetriever - Polling the status of the retrieve request.
2022-07-14 20:59:50,893 [  75876]   FINE - #c.i.i.b.ForceComMetadataRetriever - Status: Pending
2022-07-14 20:59:50,893 [  75876]   FINE - #c.i.i.b.ForceComMetadataRetriever - Retrieve request is still processing.
2022-07-14 20:59:50,894 [  75877]   FINE - #c.i.u.VariableLengthPollingInterval - ForceComMetadataRetriever.retrieve: Using polling interval 1000 ms for polling iteration 3.
2022-07-14 20:59:51,901 [  76884]   FINE - #c.i.i.b.ForceComMetadataRetriever - Polling the status of the retrieve request.
2022-07-14 20:59:52,016 [  76999]   FINE - #c.i.i.b.ForceComMetadataRetriever - Status: Pending
2022-07-14 20:59:52,017 [  77000]   FINE - #c.i.i.b.ForceComMetadataRetriever - Retrieve request is still processing.
2022-07-14 20:59:52,017 [  77000]   FINE - #c.i.u.VariableLengthPollingInterval - ForceComMetadataRetriever.retrieve: Using polling interval 1000 ms for polling iteration 4.
...
2022-07-14 21:03:31,550 [ 296533]   FINE - #c.i.u.VariableLengthPollingInterval - ForceComMetadataRetriever.retrieve: Using polling interval 5000 ms for polling iteration 59.
2022-07-14 21:03:36,557 [ 301540]   FINE - #c.i.i.b.ForceComMetadataRetriever - Polling the status of the retrieve request.
2022-07-14 21:03:36,873 [ 301856]   FINE - #c.i.i.b.ForceComMetadataRetriever - Status: Pending
2022-07-14 21:03:36,873 [ 301856]   FINE - #c.i.i.b.ForceComMetadataRetriever - Retrieve request is still processing.
2022-07-14 21:03:36,874 [ 301857]   FINE - #c.i.u.VariableLengthPollingInterval - ForceComMetadataRetriever.retrieve: Using polling interval 5000 ms for polling iteration 60.
2022-07-14 21:03:41,879 [ 306862]   FINE - #c.i.i.b.ForceComMetadataRetriever - Polling the status of the retrieve request.
2022-07-14 21:03:42,179 [ 307162]   FINE - #c.i.i.b.ForceComMetadataRetriever - Status: Succeeded
2022-07-14 21:03:42,180 [ 307163]   FINE - #c.i.i.b.ForceComMetadataRetriever - Retrieve complete.

As you can see, all of the time is spent polling the Salesforce org for retrieval job completion with the job in Pending (i.e., queued) state most of the time.

You should log a support case with Salesforce. You can include that subset of the IC2 log to show the job states since they're reported directly by the Salesforce APIs.

[Arun Ganeshamoorthy]

Thanks Scott will do