Slow Deployment Times with IlluminatedCloud Compared to VSCode

[Kai-Fan Hsieh]

I've noticed that deployment is significantly slower with IlluminatedCloud compared to VSCode. For example, deploying an Apex class with VSCode usually takes 2-3 seconds. However, with IlluminatedCloud, it almost always takes more than a minute. Below is the breakdown of the time taken. Each developer has their own sandbox, so it's not a shared environment. What could be causing this delay, and how can the deployment process be made quicker?

1. Populating contents: 20 seconds
2. Comparing local and server metadata states: 50 seconds or more
3. Initializing local caches: 10 seconds
4. Deploying: 3 seconds

[Scott Wells]

Hi. Typically the only reason that a trivial IC2 deployment -- one that should only take a couple of seconds -- would take upwards of a minute would be server-side queueing. IC2 is calling the same APIs as the Salesforce CLI, and in many cases may even be using the Salesforce CLI itself.

Can you please enable debug logging for Metadata Deployment and Salesforce DX, reproduce this behavior, and either attach or email the resulting idea.log file(s) for review?

I'll be very curious to hear where that time is being spent as I'm not experiencing such slowness myself nor am I hearing about it from others, so my guess is that there's something causing this slowness, and hopefully a debug log will help show what it is.

[Kai-Fan Hsieh]

Hi Scott,

Please see attached log file. Thank you!

[Scott Wells]

Thanks. I see a few things in the provided log:

First, enumerating org metadata – which is performed for either incremental deployment (i.e., Deploy Modified Metadata) or for conflict detection if enabled for the connetion – is taking about 13 seconds:

2024-07-04 10:45:21,383 [91480280]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Checking for conflicts.
2024-07-04 10:45:34,509 [91493406]   INFO - #com.illuminatedcloud.intellij.metadata.configCache.FilePropertiesCache - Enumerated metadata for connection KAIDEV in 13 s 126 ms.

My guess is that this org contains a large amount of metadata, so unfortunately there’s not much I can do about that. IC2 already uses up to 25 parallel threads to make that as fast as possible given the limitations of the Salesforce APIs. Since it looks like conflict detection is enabled based on the log extract above, you can certainly temporarily disable conflict detection and use the Force Save action or deploy-on-save instead of the Deploy Modified Metadata action and that should reduce the overtime significantly.

Second, there is some queueing going on with these deployment requests, and while it isn’t much, it is contributing to the overall time:

2024-07-04 10:45:35,367 [91494264]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Creating a container async request for metadata container 1dc9p000000CebBAAS with checkOnly = false.
2024-07-04 10:45:35,526 [91494423]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest.
2024-07-04 10:45:35,592 [91494489]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED.
2024-07-04 10:45:35,594 [91494491]   FINE - #com.illuminatedcloud.intellij.util.VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 1.
...
2024-07-04 10:45:39,810 [91498707]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest.
2024-07-04 10:45:39,876 [91498773]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest status = COMPLETED.
2024-07-04 10:45:39,876 [91498773]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest is complete.
2024-07-04 10:45:39,877 [91498774]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Compiled all metadata container members in 4510 ms.

As you can see there, it took ~4.5 seconds to deploy using the Tooling API. That’s not bad, but typically for a single Apex class, it’s more in the 1-2 second range. I don’t know if this particular org is experiencing higher-than-average job queue lengths right now or if this is normal. You could also try disabling Tooling API-based deployment in the Illuminated Cloud | Configure Application | Validation and Deployment settings. Typically the Tooling API is faster than the Metadata API for the same operations, but I’ve seen situations in the past where queues were worse for the Tooling API than the Metadata API oddly.

In the provided log, I’m not seeing much more time than that. Unfortunately the log rolled so I can’t see the entire operation, but of the main part, it looks like the time range is 10:45:21 – 10:45:39 which is about 18 seconds, and the two operations shown above are 13 seconds and 4.5 seconds respectively, so almost all of that time.

If you’d like to provide another log, please remove com.illuminatedcloud.intellij.sfdx.forceignore.ForceIgnoreUtil from Debug Log Settings as it’s quite noisy in this case, reproduce the behavior again, and provide all idea*.log* files from that directory with timestamps from the duration of the entire deployment operation.

Note that it’s getting late in the evening my time, so I probably won’t get a chance to review a new log until tomorrow morning.

[Kai-Fan Hsieh]

Hi Scott, thank you very much for the investigation. You are right. The org is 12 years old and has huge amount of metadata. Please see the new log file with com.illuminatedcloud.intellij.sfdx.forceignore.ForceIgnoreUtil removed. Note that this time I enabled deploy-on-save but it still took about 90 seconds.

[Scott Wells]

Thank you for the new log. It does look like the majority of the time is still coming from conflict detection and server-side queueing:

Conflict detection

2024-07-04 18:44:18,526 [ 323684]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Checking for conflicts.
2024-07-04 18:45:26,867 [ 392025]   INFO - #com.illuminatedcloud.intellij.metadata.configCache.FilePropertiesCache - Enumerated metadata for connection KAIDEV in 1 m 8 s 341 ms.

Queueing

2024-07-04 18:45:35,253 [ 400411]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Creating a container async request for metadata container 1dc9p000000CfvRAAS with checkOnly = false.
2024-07-04 18:45:35,443 [ 400601]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest.
2024-07-04 18:45:35,552 [ 400710]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED.
2024-07-04 18:45:35,552 [ 400710]   FINE - #com.illuminatedcloud.intellij.util.VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 1.
...
2024-07-04 18:45:41,987 [ 407145]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest.
2024-07-04 18:45:42,050 [ 407208]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED.
2024-07-04 18:45:42,050 [ 407208]   FINE - #com.illuminatedcloud.intellij.util.VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 7.
2024-07-04 18:45:43,060 [ 408218]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest.
2024-07-04 18:45:43,124 [ 408282]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest status = COMPLETED.
2024-07-04 18:45:43,124 [ 408282]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   ContainerAsyncRequest is complete.
2024-07-04 18:45:43,124 [ 408282]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer - Compiled all metadata container members in 7871 ms.

The overall operation was from 18:44:18,247 – 18:45:43,124, so ~1m25s, and of that, conflict detection contributed 1m8s and the deployment job spent ~7s in queue before it even started processing.

I would recommend running the following additional tests so we can find your best configuration:

Disable conflict detection

First, just disable conflict detection for this connection. You mentioned that each developer has their own sandbox, but I’m assuming that conflict detection is enabled only to ensure that you aren’t overwriting your own changes made directly in the org? Otherwise you shouldn’t need conflict detection as that’s really primarily useful when multiple users are collaborating in the same org. Turn off conflict detection and try the exact same deployment, then attach that idea.log for review. My guess is that just this change will remove >1 minute from the overall operation.

Disable Tooling API-based deloyment

With conflict detection still disabled, disable Tooling API-based deployment in IC’s Validation and Deployment settings. Again, the Metadata API is generally slower than the Tooling API when the Tooling API is a valid option, but since we’re seeing upwards of 7 seconds spent in queue, let’s see if this specific org performs better via the Metadata API. Again, deploy the same file and attach a second (or in this case, fourth) idea.log file.

With both of those changes, deployment should be occuring in pretty much the exact same fashion as via the Salesforce CLI (which is what’s used by the VS Code extensions), so I would expect deployment times to be similar to elsewhere.

Let’s see what those logs tell us…

[Kai-Fan Hsieh]

This time I disabled conflict detection. Deployment time is deduced to 15 seconds. Please see the 2 logs files. One with tooling API and another one without it. Is it possible to make it quicker? 15 seconds is still a bit longer than vscode.

[Scott Wells]

Thanks. Those were very helpful, and I think I see the remaining extra time. For what it’s worth, here’s what I see in each log:

Tooling API

Total time: 06:52:23,954 - 06:52:41,157 = ~17 seconds
Deployment time: ~7.8 seconds
Other major time: ~7 seconds inferring a subscription from local files:

2024-07-05 06:52:25,612 [ 755102]   FINE - #com.illuminatedcloud.intellij.builder.ForceComBuilder -   Creating a metadata subscription based on locally-resident metadata files.
2024-07-05 06:52:32,791 [ 762281]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComToolingApiDeployer -   Adding Apex class ElevatedDAO_Test

Metadata API

Total time: 07:01:37,801 - 07:01:53,670 = ~18 seconds
Deployment time: ~7 seconds
Other major time: ~8 seconds inferring a subscription from local files:

2024-07-05 07:01:38,414 [1307904]   FINE - #com.illuminatedcloud.intellij.builder.ForceComBuilder -   Creating a metadata subscription based on locally-resident metadata files.
2024-07-05 07:01:46,486 [1315976]   FINE - #com.illuminatedcloud.intellij.builder.deploy.ForceComMetadataApiDeployer -   Using the following package.xml for deployment:

‌

If you change your metadata subscription from Local Files to Package.xml and have IC2 manage the package.xml file for you, all of that time spent inferring a metadata subscription from local files will go away. Local Files subscriptions are wonderful for projects with small or even moderate amounts of local metadata, but it seems like this project has a very large amount of local metadata which can cause these types of pauses.

Note that IC2 can help both create the package.xml file from your local project metadata files and can help keep it up-to-date as local project metadata files are added and removed over time. This user guide topic isn’t 100% up-to-date regarding available subscription options – I really need to update it – but the Validation and Deployment | Metadata subscription option descriptions should be accurate.

Also note that regardless of which API is used, there is non-trivial queueing for even a single Apex class, typically in the 6-7 second range. You’d orignally mentioned that a deployment via VS Code takes 2-3 seconds, but since it’s just using the Salesforce CLI which in turn is just using the Metadata API, I’m a bit confused as to how that could be the case. Are you definitely still seeing 2-3 second deployments via VS Code when you’re seeing the logs show 7-8 second deployments via the Tooling and Metadata APIs for the exact same file? If so, I’ll need to follow up with Salesforce and try to understand why/how such a disrepancy might exist.

‌

Anyway, the bottom line is that I believe with conflict detection disabled and the switch to a Package.xml metadata subscription, you should be seeing virtually identical times between IC2 and VS Code when deploying via deploy-on-save, Force Save, or Deploy All Metadata. None of those deployment actions need to query the org metadata state like conflict detection and Deploy Modified Metadata do, so they should just be raw API-based deployments of the file, subject to any required queueing occuring for that API in your org/instance at the time.

[Kai-Fan Hsieh]

‌

Hi Scott,

I have updated the metadata subscription from Local Files to Package.xml, and now the deployment time matches that of VS Code. Keep in mind that the 3-second deployment time for VS Code was just yesterday, and it can vary.

I have always worked on greenfield projects and never encountered these kinds of issues before. Recently, I transitioned to a brownfield project. The organization is 12 years old and has had hundreds of Salesforce developers work on it over the years, resulting in a massive amount of metadata.

Thank you very much for your help!

[Scott Wells]

Okay, that makes good sense. Note that in an org of that size, one thing that would definitely work well would be enabling it as a source-tracked sandbox. Then you would be able to tell IC2’s connection that it supports push and pull (if you were okay with that, of course), and you’d get incremental deployment and conflict detection simply by virtue of the CLI’s own source-tracking metadata. Unfortunately source-tracking is only available in scratch orgs and sandboxes in which that feature is enabled.

Anyway, thanks for providing the logs as they helped us to understand where that time was going and how to minimize/eliminate it when working against such an org. Unfortunately you don’t get access to all of IC2’s metadata features – at least not efficiently – when working against such and org, but since they can all be disabled, you can certainly get things working decently.

[Scott Wells]

Resolving this as we've solved the mystery with a little cooperative sleuthing.