Deployment dialog taking extremely long time to generate package.

Issue #1519 resolved
Justin Julicher created an issue

Have just installed 2.1.0.0

Ran Deploy All Metadata

Selected all my classes & triggers.

Click deploy.

Dialog disappears and it appears nothing is running however, after a little while the logs start showing:

Found one. Deleting it. 
2020-01-28 10:18:26,989 [4663508]  DEBUG - der.ForceComToolingApiDeployer - Creating a new metadata container with name IC-DEVJJ-JUSTIN@JUSTIN-XPS-15-95 
2020-01-28 10:18:27,393 [4663912]  DEBUG - der.ForceComToolingApiDeployer - Populating the metadata container. 
2020-01-28 10:18:27,393 [4663912]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_Quality_Score_full_Feedback 
2020-01-28 10:18:28,014 [4664533]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_TimeEntriesCustomController 
2020-01-28 10:18:28,630 [4665149]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CreateEditSegmentForHearing 
2020-01-28 10:18:29,242 [4665761]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSTurnCheckAudioTimeTypedTo 
2020-01-28 10:18:29,651 [4666170]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_AUMock_DeleteFileByIdForever 
2020-01-28 10:18:30,266 [4666785]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CustomEditButtonForCTSegment 
2020-01-28 10:18:30,660 [4667179]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSCopyOrderDetailsToHearing 
2020-01-28 10:18:31,290 [4667809]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_TranscriptEstimatorController 
2020-01-28 10:18:31,732 [4668251]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_UKInternalOrderFormController 
2020-01-28 10:18:32,314 [4668833]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSCopyInstructionsToHearings 
2020-01-28 10:18:33,260 [4669779]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class JurisdictionTurnaroundSelectorTest 
2020-01-28 10:18:33,747 [4670266]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_BatchPopulateCTAndMIinHearing 
2020-01-28 10:18:34,270 [4670789]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSUpdateLognoteEntryDateTime 
2020-01-28 10:18:34,652 [4671171]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_OverrideHearingViewController 
2020-01-28 10:18:35,181 [4671700]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSOrderDetailExportController 
2020-01-28 10:18:35,571 [4672090]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class TimeTrackerApprovalNotificationTest 
2020-01-28 10:18:35,999 [4672518]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_CRSPreventingRBTimesOverlapping 
2020-01-28 10:18:36,614 [4673133]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_Hearing_UpdateInvoicingContract 
2020-01-28 10:18:37,231 [4673750]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class CreateInvoiceCreditForHearingControllerT 
2020-01-28 10:18:37,611 [4674130]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Ida_Transcript_Invoice_Pdf_Controller 

Notice the 400-600 ms per file to add the class files in. As we have hundreds this is taking forever.

Comments (22)

  1. Justin Julicher reporter

    I’m also not getting any dialog box popping up showing any kind of status.

    Could this be related to the latest update of Webstorm. I also just updated to 2019.3.2 maybe if I revert it’ll be ok. I’ll give that a go.

  2. Justin Julicher reporter
    • marked as minor
    • edited description

    Weird ok so invalidated caches and restarted and it has resolved the issue temporarily.

    it seemed to have lost it’s ‘connection’ to the iDE and couldn’t open a dialog.

    Will keep you posted if it happens again.

  3. Justin Julicher reporter

    Ok so dialog goes ok now but it’s getting stuck on the

    Checking for missing metadata.

    This usually only takes a second or two to complete then continues on but has been stuck for minutes now.

    Log files don’t show much just:

    2020-01-28 10:38:29,118 [ 457229]  DEBUG - der.ForceComToolingApiDeployer - Looking for any missing metadata before deploying with the Tooling API. 
    2020-01-28 10:38:29,608 [ 457719]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 146 ms 
    2020-01-28 10:38:38,827 [ 466938]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 156 ms 
    2020-01-28 10:39:00,802 [ 488913]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 138 ms 
    2020-01-28 10:39:43,725 [ 531836]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 119 ms 
    2020-01-28 10:40:37,886 [ 585997]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 144 ms 
    2020-01-28 10:40:38,176 [ 586287]   INFO - rationStore.ComponentStoreImpl - Saving Project (name=Cortex-GitFlow, containerState=ACTIVE, componentStore=/home/justin/WebstormProjects/Cortex-GitFlow) IlluminatedCloudWorkspaceSettings took 276 ms 
    2020-01-28 10:40:40,149 [ 588260]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 2428 ms 
    2020-01-28 10:40:59,121 [ 607232]   INFO - rationStore.ComponentStoreImpl - Saving Module: 'Cortex-GitFlow'FacetManager took 124 ms 
    

    Any ideas?

  4. Scott Wells repo owner

    Sorry for the delayed response. This came in just as I had left for dinner with the family. I'm glad that you were able to get past the original issue. I wasn't able to reproduce it so I was getting a little worried.

    The one with Check for missing metadata actually does make a bit more sense depending on how many files you're deploying. That only kicks in when you're deploying via the Tooling API. I just looked at the implementation and it does look like it runs a query against the server for each Apex class/trigger and each Visualforce page/component in the deployment request. I certainly can/should batch that so that it's the minimum number of queries required to get the required info. My guess is that that particular API is slow to respond in your org at present but normally runs more quickly. Hopefully that reverts to better performance soon, but I'll look into batching it appropriately for larger requests. It's not surprising that it's the way it is now because the Tooling API was originally anticipated as being used for small payloads such as a single Apex class/trigger or Visualforce page/component and not large requests. Nonetheless, it should be optimized.

    If that part continues to be slow, I recommend disabling the Tooling API temporarily to see if that helps. Please let me know either way.

  5. Scott Wells repo owner

    FYI, I'm also seeing Check for missing metadata running slowly for bulk payloads:

    2020-01-27 19:25:30,248 [ 395393]  DEBUG - der.ForceComToolingApiDeployer - Looking for any missing metadata before deploying with the Tooling API. 
    2020-01-27 19:25:39,776 [ 404921]  DEBUG - der.ForceComToolingApiDeployer - Looking for an existing metadata container with name IC-DEMO-SCOTT@SCOTTSURFACELAPTOP. 
    

    That's 9.5 seconds for a little over 100 objects. I'll look at optimizing that tomorrow just in case the API used for that is going to start running slowly now, e.g., Salesforce has implemented some type of service protection for it.

    I'm also seeing it take a bit more time to load the bodies of the deployed files into memory so they can be added to the payload. It's not taking 400 ms per-file as in your original example, but I'll see if I can do that in parallel to speed it up.

  6. Justin Julicher reporter

    Ok yeah that fixed it - sorry if I disturbed your dinner with the family!

    So basically don’t use the tooling api for apex - are there any reasons why we should use the tooling api?

    thanks for the quick reply.

  7. Scott Wells repo owner

    No bother at all! We had a nice dinner...I just didn't want to leave you hanging on what looked like a potentially serious issue.

    Actually in general you should let IC use the Tooling API whenever it can because it's quite a bit more efficient for onesy-twosy deployments of the supported metadata types that happen when you're actively editing Apex source, etc.

    Like I said, I'll see what I can do to optimize these two areas and get things back to where using the Tooling API is a no-brainer. I'll use this issue to report progress and resolution.

  8. Justin Julicher reporter

    Ok great.

    What about if you added an option to use tooling API in the deployment dialog box or prompt the user for large deployments to use the metadata API instead? i.e. when it’s more than say 10 files?

  9. Scott Wells repo owner

    I did just notice that every request against the Tooling API is staying in QUEUED status for a bit which is unusual:

    2020-01-27 19:42:54,853 [ 105302]  DEBUG - der.ForceComToolingApiDeployer - Creating a container async request for metadata container 1dc2E000001lLRfQAM with checkOnly = false. 
    2020-01-27 19:42:54,984 [ 105433]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:42:55,058 [ 105507]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:42:55,058 [ 105507]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 1. 
    2020-01-27 19:42:56,058 [ 106507]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:42:56,168 [ 106617]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:42:56,169 [ 106618]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 2. 
    2020-01-27 19:42:57,169 [ 107618]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:42:57,240 [ 107689]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:42:57,241 [ 107690]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 3. 
    2020-01-27 19:42:58,242 [ 108691]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:42:58,312 [ 108761]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:42:58,312 [ 108761]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 4. 
    2020-01-27 19:42:59,313 [ 109762]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:42:59,388 [ 109837]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:42:59,389 [ 109838]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 5. 
    2020-01-27 19:43:00,390 [ 110839]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:00,462 [ 110911]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:00,462 [ 110911]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 6. 
    2020-01-27 19:43:01,462 [ 111911]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:01,536 [ 111985]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:01,537 [ 111986]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 7. 
    2020-01-27 19:43:02,537 [ 112986]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:02,614 [ 113063]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:02,614 [ 113063]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 8. 
    2020-01-27 19:43:03,614 [ 114063]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:03,682 [ 114131]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:03,682 [ 114131]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 9. 
    2020-01-27 19:43:04,682 [ 115131]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:04,754 [ 115203]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:04,754 [ 115203]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 10. 
    2020-01-27 19:43:05,755 [ 116204]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:05,832 [ 116281]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-27 19:43:05,832 [ 116281]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 2000 ms for polling iteration 11. 
    2020-01-27 19:43:07,834 [ 118283]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-27 19:43:08,006 [ 118455]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = FAILED. 
    2020-01-27 19:43:08,006 [ 118455]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest is complete. 
    

    Must be something going on there.

    I've already optimized adding the file bodies for request and that part looks good. I'll optimize the missing metadata queries tomorrow. Even when the Tooling API starts behaving better, those will be nice optimizations.

  10. Scott Wells repo owner

    Regarding "And possibly an option to not run the missing metadata check?", I can't do that. You can't (reliably) create these types of metadata via the Tooling API, so IC needs to know if a deployment request that's otherwise going to use the Tooling API would result in an attempt to create metadata so that it can instead use the Metadata API. The equivalent of that requested option is to disable the Tooling API and always use the Metadata API.

  11. Justin Julicher reporter

    Ahh I see. perfect.

    By the way the I can already notice the difference in the latest IC. I haven’t had a freeze from loading the SFDX connections and the smart completion is making my life easier! Keep up the great work!

    cheers

  12. Scott Wells repo owner

    Justin, if you want to live on the bleeding edge a bit, install this build which has both optimizations that I mentioned. The one thing it definitely doesn't have yet is logic to break up the batched queries to a maximum of 20K characters if the names of classes requested for deployment would cause it to exceed that limit.

    I'm curious to know what performance difference upon re-enabling the Tooling API and performing the same types of deployments that were running slowly for you earlier.

    Totally fine if you'd prefer to stay on the official build right now, but since I had a first stab at this I thought I'd ask for an external data point.

    And glad to hear the new build is otherwise working well for you!

  13. Justin Julicher reporter

    Scott,

    It went past the checking for missing metadata pretty quickly and completed a deploy of 642 classes & triggers in 3 mins 27s. I’d say that’s a pretty good success.

    cheers!

  14. Scott Wells repo owner

    That certainly sounds like an improvement. If you have one handy, I'd love to see a debug log to see where that time is being spent. My guess is that most of it is in the actual deployment which, unfortunately, is out of my direct control. However, the log should show other long poles that might be candidates for optimization...or at least show me the quantifiable effects of the changes I've made.

  15. Justin Julicher reporter

    Ok, so the same deploy using the metadata API only took 2m 27s so about 30% faster at this stage. So having the option to not use the tooling api for large deploys would be good.

    I’ll upload the logs now.

  16. Scott Wells repo owner

    Thanks, Justin. Here's what I see in the logs....

    Bulk loading the details used to detect missing metadata is MUCH faster now (~500 ms):

    2020-01-28 16:10:09,666 [7402234]  DEBUG - der.ForceComToolingApiDeployer - Loading details for requested files. 
    2020-01-28 16:10:09,668 [7402236]  DEBUG - der.ForceComToolingApiDeployer - Loading details for 560 Apex classes. 
    2020-01-28 16:10:10,280 [7402848]   WARN - x.cache.CachedStatusCalculator - Hash mismatch between count and status: RevListCount[value=1,status=SUCCESS,top=86355fed2db93488bbf28a7c3c30e52db0f563ca] ahead, RevListCount[value=0,status=SUCCESS,top=<null>] behind, status=SUCCESS <> RepoStatus[localHash=86355fed2db93488bbf28a7c3c30e52db0f563ca,localBranch=refs/heads/AndrewsTestBranch,remote=RepoStatusRemote[remoteTrackingBranch=refs/remotes/origin/AndrewsTestBranch,parentBranch=refs/remotes/origin/AndrewsTestBranch,parentHash=a4bac12c53b15e4bcbc36d72810882f5695b99a8]] 
    2020-01-28 16:10:10,307 [7402875]   INFO - ta.index.VcsLogPersistentIndex - Indexing 1 commits in Cortex-GitFlow 
    2020-01-28 16:10:10,333 [7402901]   INFO - ta.index.VcsLogPersistentIndex - 25ms for indexing 1 new commits out of 1 in Cortex-GitFlow 
    2020-01-28 16:10:13,899 [7406467]  DEBUG - der.ForceComToolingApiDeployer -   Found 560 matching records. 
    2020-01-28 16:10:13,899 [7406467]  DEBUG - der.ForceComToolingApiDeployer - Loading details for 82 Apex triggers. 
    2020-01-28 16:10:14,561 [7407129]  DEBUG - der.ForceComToolingApiDeployer -   Found 82 matching records. 
    

    As a result, checking for missing metadata is close to instantaneous:

    2020-01-28 16:10:14,561 [7407129]  DEBUG - der.ForceComToolingApiDeployer - Looking for any missing metadata before deploying with the Tooling API. 
    2020-01-28 16:10:14,568 [7407136]  DEBUG - der.ForceComToolingApiDeployer - Looking for an existing metadata container with name IC-DEVJJ-JUSTIN@JUSTIN-XPS-15-95. 
    

    So that was a long-running operation for you before, and now it's ~0.5 secs total.

    The other thing that took a while was loading the actual file bodies so they could be added to the metadata container. That was taking 400-600 ms/file originally, though it seems like that sped up quite a bit after a cache rebuild. Now it takes a negligible amount of time (~300 ms)

    2020-01-28 16:10:16,352 [7408920]  DEBUG - der.ForceComToolingApiDeployer - Populating the metadata container. 
    2020-01-28 16:10:16,353 [7408921]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_Quality_Score_full_Feedback 
    ...
    2020-01-28 16:10:16,376 [7408944]  DEBUG - der.ForceComToolingApiDeployer -   Adding Apex class Test_AuscriptFormController 
    2020-01-28 16:10:16,615 [7409183]  DEBUG - der.ForceComToolingApiDeployer - Adding members to the metadata container. 
    

    So that optimization looks sound as well.

    Then I see that all of the time is going into just polling a QUEUED state while waiting for Salesforce to perform the actual deployment:

    2020-01-28 16:11:17,680 [7470248]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-28 16:11:18,277 [7470845]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = QUEUED. 
    2020-01-28 16:11:18,277 [7470845]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 1000 ms for polling iteration 1. 
    ...
    2020-01-28 16:15:03,959 [7696527]  DEBUG - .VariableLengthPollingInterval - ForceComToolingApiDeployer.runContainerAsyncRequest: Using polling interval 5000 ms for polling iteration 51. 
    2020-01-28 16:15:08,959 [7701527]  DEBUG - der.ForceComToolingApiDeployer - Polling the status of the ContainerAsyncRequest. 
    2020-01-28 16:15:14,812 [7707380]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest status = COMPLETED. 
    2020-01-28 16:15:14,812 [7707380]  DEBUG - der.ForceComToolingApiDeployer -   ContainerAsyncRequest is complete. 
    2020-01-28 16:15:14,812 [7707380]  DEBUG - der.ForceComToolingApiDeployer - Compiled all metadata container members in 237767 ms. 
    2020-01-28 16:15:14,812 [7707380]  DEBUG - der.ForceComToolingApiDeployer - ContainerAsyncRequest state = COMPLETED 
    

    As you can see, that took ~4 minutes. That's REALLY unsual for the Tooling API. In general the Metadata API is quite a bit slower for the same deployment payload. In fact, that's why the Tooling API exists...to support Tooling-oriented deployment use cases without getting bogged down in the same deployment queues used for sandbox refreshes, changesets, etc.

    I'll let Salesforce know that we're both seeing long times in queue in the Tooling API. My guess is that once they fix whatever is going on, you'll want to use the Tooling API over the Metadata API whenever you can. The current observed behavior is anomalous. The optimizations I've added here (and they're production-ready for the next build) will just make things even faster from IC.

  17. Justin Julicher reporter

    In regards to the optimization for SOQL - Just remember that the new limit for SOQL queries is 100k.

    Salesforce Spring ’20 Release Notes

    SOQL

    Salesforce Object Query Language (SOQL) includes changes to limits and calls

    Changed Limits

    Use longer SOQL queriesThe maximum length of SOQL statements has been increased from 20,000 to 100,000.Use more relationships in queriesThe maximum number of child-to-parent relationships in a query has been increased from 35 to 55.

  18. Scott Wells repo owner

    Good to know. I'll make sure to change the batching logic to take that into account as part of my Spring '20 update.

  19. Log in to comment