Deployment takes around 2 minutes

[Car IO]

Any deployment apart from static resources takes a very long time, I've enabled some log in IDE, and can see this step taking quite a long time: 2019-04-05 19:44:12,113 [ 147953] INFO - ij.builder.ForceComBuilderUtil - Enumerated metadata for connection App Dev in 1 m 42 s 143 ms.

I've attached full log, let me know if you need any more details.

[Scott Wells]

HI. I'm not seeing a full log attached. Can you please provide that (here or email) so I can take a look?

[Scott Wells]

Thanks. Do you mind ensuring that all of the following are set up for debug logging:

#com.illuminatedcloud.intellij.builder.IlluminatedCloudSaveAllAction
#com.illuminatedcloud.intellij.builder.ForceComBuilder
#com.illuminatedcloud.intellij.builder.ForceComBuilderUtil
#com.illuminatedcloud.intellij.builder.ForceComMetadataApiDeployer
#com.illuminatedcloud.intellij.builder.ForceComSfdxDeployer
#com.illuminatedcloud.intellij.builder.ForceComToolingApiDeployer
#com.illuminatedcloud.intellij.builder.ForceComBuildFailureAnnotator
#com.illuminatedcloud.util.VariableLengthPollingInterval

then reproducing the issue and sending an updated log? That should provide considerably more insight into what's happening in that 1m42s span.

[Car IO]

Hi Scott, added those line to IDE log, hope it helps.

[Scott Wells]

That does help. It makes it look like the call to Salesforce to enumerate Apex classes is taking a very long time. I'd like to be sure about that. Can you add these as well:

#com.illuminatedcloud.client.ForceComApiClient
#com.illuminatedcloud.client.ForceComApiClient!trace

then restart the IDE completely and reproduce the issue? Note that these logs will include the details of every SOAP request/response pair including your login credentials. Do not post the raw log file here as a result. What would like to see, though, is the portion of the log in this range:

2019-04-05 20:08:03,528 [  23023]  DEBUG - ij.builder.ForceComBuilderUtil - Enumerating metadata for connection App Dev. 
...
2019-04-05 20:10:16,975 [ 156470]   INFO - ij.builder.ForceComBuilderUtil - Enumerated metadata for connection App Dev in 2 m 13 s 447 ms. 

Once you've provided that portion of the log, you can remove these two new entries for debug logging and restart the IDE to keep it from logging details at this level. Thanks!

[Car IO]

Here are logs between those items, minus sensitive information

[Scott Wells]

Thanks. Do you mind editing that comment to add three consecutive backticks on separate lines before and after the log extract to make them format as pre-formatted blocks?

[Car IO]

attached as file, should be formatted there

[Scott Wells]

I'm attaching a build that's exactly the same as the current official build but with more debug logging in that lost ~2 mins to see exactly where it's going. Download the archive and, without extracting it, install it using Settings/Preferences>Plugins>Install Plugin from Disk (under the gear drop-down in recent IDE versions). Restart the IDE and reproduce the issue with all of the debug logging enabled except for the lines for ForceComApiClient. The critical one is ForceComBuilderUtil. Reproduce the issue and provide the latest log. It should have a very detailed breakdown of how the time is being spent. Then I can see if there's anything I can do to minimize it.

[Scott Wells]

Thanks. That shows it:

2019-04-05 22:28:42,041 [  31647]  DEBUG - ij.builder.ForceComBuilderUtil - Listing metadata for the following types: ApexClass 
2019-04-05 22:29:56,935 [ 106541]  DEBUG - ij.builder.ForceComBuilderUtil - Added 590 file properties. 
...
2019-04-05 22:29:56,935 [ 106541]   INFO - ij.builder.ForceComBuilderUtil - Enumerated metadata for connection App Dev in 1 m 14 s 898 ms. 

One metadata API call, MetadataApi.listMetadata('ApexClass'), is taking pretty much all of the time. If you have the Force Migration Tool (ant toolkit) installed, you can try to reproduce this outside of Illuminated Cloud to see if the timing is the same. If it is, you'll need to log a support case with Salesforce to see if they can figure out why this call is taking so long. If it runs much faster, I'll need to see what's different between the call that I'm making in Illuminated Cloud and the one being made by ant.

[Car IO]

Tried with ant, it took 21 seconds.

[Car IO]

tried 3 more times, took 14, 8 and 10 sec.

[Scott Wells]

Okay, that's actually wonderful. That should put it fully under my control. Let me instrument with a bit more debug logging and have you measure times for me again. That overhead must be somewhere. I'll let you know when a new build is available for you.

[Scott Wells]

New build attached with more timing-related debug logging. Please reproduce and provide a new debug log when you get a chance. I have a suspicion about what might be happening, and I'm hoping that the log will support it.

[Scott Wells]

Okay, here's where the time is going:

2019-04-07 10:29:32,512 [  21901]  DEBUG - ij.builder.ForceComBuilderUtil - Listing metadata for the following types: ApexClass 
2019-04-07 10:29:32,513 [  21902]  DEBUG - ij.builder.ForceComBuilderUtil -   Before listMetadata() call. 
2019-04-07 10:31:08,755 [ 118144]  DEBUG - ij.builder.ForceComBuilderUtil -   After listMetadata() call. 
2019-04-07 10:31:08,755 [ 118144]  DEBUG - ij.builder.ForceComBuilderUtil - listMetadata() returned 4299 results. 

The only thing between "Before listMetadata() call" and "After listMetadata() call" is the actual call to the server. So now we need to figure out why that API call takes so long from IC and not from ant. Either the call itself is taking that long, or the deserialization of the 4.2K results into Java objects is taking up the time. Let's be 100% sure. Please re-add the following:

#com.illuminatedcloud.client.ForceComApiClient
#com.illuminatedcloud.client.ForceComApiClient!trace

restart the IDE, and reproduce the issue. Then what I'll care about is the same span that I clipped above, but now it will include the SOAP request and response. You can redact the request/response details. All I really care about are the timestamps in the log. We're either going to see that the request takes 1-2 minutes, or we're going to see that it takes 10 seconds as it does from ant, and then there's a long pause between receiving the response and the "After listMetadata() call" line.

Getting closer...thanks for continuing to provide this useful diagnostic info!

[Car IO]

Hi Scott, I think I've captured what you were interested in, SOAP request itself doesn't seem to be problem. It's strange that processing takes that long though, I've quite a powerful machine.

[Scott Wells]

Yes, thanks. This is certainly the smoking gun, so to speak:

2019-04-07 23:18:38,364 [  20299]  DEBUG - ij.builder.ForceComBuilderUtil -   Before listMetadata() call. 
2019-04-07 23:18:38,366 [  20301]   INFO - ervice.MetadataApi.MetadataApi - Outbound Message
2019-04-07 23:18:51,613 [  33548]   INFO - ervice.MetadataApi.MetadataApi - Inbound Message
??? WHAT'S HAPPENING HERE ???
2019-04-07 23:20:20,095 [ 122030]  DEBUG - ij.builder.ForceComBuilderUtil -   After listMetadata() call. 
2019-04-07 23:20:20,095 [ 122030]  DEBUG - ij.builder.ForceComBuilderUtil - listMetadata() returned 4299 results. 

There is literally nothing going on in the IC code in between "Inbound Message" and "After listMetadata() call", so it must be some inefficiency in the SOAP toolkit that I'm using, Apache CXF.

Coincidentally I recently integrated the latest-and-greatest build of that toolkit for a completely unrelated reason. I'm going to attach a build with that update as well just to see if it changes the timing. My guess is that it won't, but I figure that it's worth seeing if they've implemented some optimization for whatever is taking so long. That will also set the proper stage for me to discuss it with the maintainers of that library as I'm sure they'll want me to be using the latest version when helping troubleshoot.

[Scott Wells]

Here's a build with the CXF upgrade. My guess is that it won't make much of a difference, but just in case they've optimized that part quite a bit, let's get a new log with this build. At a minimum that will allow me to talk with the CXF team about this confident that it's occurring on the latest-and-greatest build.

[Car IO]

definitely not working, tried 2 deployments, first 2 min 15 sec and second 2 min 5 sec

[Scott Wells]

Okay. Not surprising but thanks for verifying.

I don't have access to an org with >4K Apex classes in it, but I did get timings against an org with >1K Apex classes (note that I had to enable conflict detection for the connection for it to need to call listMetadata()):

2019-04-07 15:41:04,338 [ 316607]  DEBUG - ij.builder.ForceComBuilderUtil - Listing metadata for the following types: ApexClass 
2019-04-07 15:41:04,341 [ 316610]  DEBUG - ij.builder.ForceComBuilderUtil -   Before listMetadata() call. 
2019-04-07 15:41:05,093 [ 317362]  DEBUG - ij.builder.ForceComBuilderUtil -   After listMetadata() call. 
2019-04-07 15:41:05,093 [ 317362]  DEBUG - ij.builder.ForceComBuilderUtil - listMetadata() returned 1072 results. 
2019-04-07 15:41:05,340 [ 317609]   INFO - ij.builder.ForceComBuilderUtil - Enumerated metadata for connection zm in 1 s 9 ms. 

Even if that were extrapolated out in a linear fashion, you'd be talking about 4.5 seconds and not 1-2 minutes. There must be something else contributing here. What is your IDE's allowed max heap size? Perhaps we should try bumping that up, though even that would surprise me since 4K small data transfer objects just shouldn't take up much space. Here's how you adjust the max heap size:

https://www.jetbrains.com/help/idea/tuning-the-ide.html

For what it's worth, I always set mine to at least 2048m (-Xmx2048m) and sometimes 3072m (-Xmx3072m). I recommend you try that and see if it changes anything. If it doesn't, I'll just need to work with the Apache CXF folks to see what might be going on. They may require me to get more logs for their library.

[Car IO]

this is what my vmoptions look right now: -Xms1024m -Xmx2048m -XX:MaxPermSize=1024m -XX:ReservedCodeCacheSize=512m -XX:+UseCompressedOops

I use webstorm

[Scott Wells]

Thanks. I've logged a case with the CXF folks. Let me see what I can find out. In the interim the only workaround would be to disable conflict detection because that's what's causing it to request this metadata from from the server (for timestamps). I don't know whether that's an option in this org, but certainly if it might result in data loss, please do not do so. Hopefully I'll have some new insights soon. I'll keep you posted here.

[Car IO]

unfortunately turning off conflict detection is not an option. is it possible to retrieve only classes that are being saved, for conflict detection, instead of all classes?

[Scott Wells]

Understood. I still haven't heard from the CXF folks. I'll keep pinging them and keep you posted.

[Car IO]

any update on this?

[Scott Wells]

Unfortunately no. I actually followed up recently and there has been no response. I'll see if I can hunt down someone who can provide an answer shortly. I sincerely apologize for the lack of traction on this. Unfortunately with the issue happening in a third-party library, it's not nearly as under my own control as I'd generally prefer. I'll let you know if I discover anything new.

[Car IO]

Is it possible to implement what I suggested? Retrieving only classes that are modified for conflict detection instead of retrieving all the classes. This could resolve this issue.

[Scott Wells]

I hate the use the same word, but unfortunately the call that's causing the issue here, listMetadata, is an all-or-nothing call for a given metadata type. There's no way to perform a selective query for the type of information provided by that call within a certain metadata type.

Honestly I think the best way for me to get to the bottom of this would be for me to be able to reproduce the issue in a debugger/profiler. Is there any chance that I could get access to this org? I'd be happy to sign a specifically-worded NDA regarding the metadata in that org if needed. Otherwise given that it's such an isolated/unique issue--and given that it seems to be happening in a third-party library--it's going to be very difficult to isolate/address it. Totally understood if that's not an option, but I figured it's worth asking since it's certainly the fastest path to resolution. If not, I'll need to think about next steps for this...

[Scott Wells]

Issue tracker grooming. If this is still an issue, please feel free to reopen, ideally with a concrete reproduction scenario.