Cli: Glacial performance of package generation in force:source:deploy

[daveespo]

Summary

We are attempting to migrate our large project repository (3000 metadata files) to source format and use force:source:deploy to continue to deploy to our fleet of UAT, QA and Packager orgs (none of which are scratch orgs) after the conversion. Historically, we use the Ant migration tool and a deploy takes about 3 minutes. We're now finding that force:source:deploy of the same project takes 15-17 minutes. 10-12 of those minutes are spent entirely client side building the Zip file that gets sent up to the MDAPI for deployment

I see my CPU pegged for the entire 10 minutes (a single CPU on a quad core machine) with no indication of progress

Note: This ticket is not about incremental deployments of only changed source files -- this is about deploying the entire project as part of a CI build pipeline.

Steps To Reproduce:

• Convert a large MDAPI project with about 3000 metadata components (classes, VF pages, static resources, SObjects, etc) to source format using force:mdapi:convert
• Try to deploy the converted source to a DE or EE org using force:source:deploy
• Expected: the duration of the deployment should be identical to the duration of using the Force.com Migration Tool (ant) to do a deployment
• Actual: The deployment takes 5x as long. It takes 10-12 minutes to build the package for deployment to the MDAPI

27783668 bytes written to C:\Users\esposito\AppData\Local\Temp\sdx_sourceDeploy_1568206314980.zip using 3087.629ms
Deploying C:\Users\esposito\AppData\Local\Temp\sdx_sourceDeploy_1568206314980.zip...

I tried gathering additional debug information using --verbose but this is the only thing written to the console of note. Is there a way I can troubleshoot further what's going on during this 10 minute black hole?

SFDX CLI Version(to find the version of the CLI engine run sfdx --version):

sfdx --version
sfdx-cli/7.20.1-d88ae4707c win32-x64 node-v10.15.3

SFDX plugin Version(to find the version of the CLI plugin run sfdx plugins --core)

sfdx plugins --core
@oclif/plugin-commands 1.2.2 (core)
@oclif/plugin-help 2.2.1 (core)
@oclif/plugin-not-found 1.2.2 (core)
@oclif/plugin-plugins 1.7.8 (core)
@oclif/plugin-update 1.3.9 (core)
@oclif/plugin-warn-if-update-available 1.7.0 (core)
@oclif/plugin-which 1.0.3 (core)
@salesforce/sfdx-trust 3.0.5 (core)
analytics 1.2.1 (core)
etcopydata 0.4.4
generator 1.1.1 (core)
salesforcedx 46.10.2
├─ force-language-services 46.14.0
└─ salesforce-alm 46.13.0

sfdx-cli 7.20.1 (core)

OS and version:
Windows 10 Pro

[daveespo]

I realize I neglected to put the actual command I'm running in the Repro steps so here it is:

sfdx force:source:deploy -p force-app --verbose --loglevel trace

And this is the relevant snippet of log output from sfdx.log .. some what redacted for safety

{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"keyChain","level":20,"msg":"platform: win32","time":"2019-09-11T15:32:15.532Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"AuthInfo","level":30,"msg":"Updated auth info for username: [email protected]","time":"2019-09-11T15:32:15.534Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"AuthInfo","level":30,"msg":"Returning fields for a connection using OAuth config.","time":"2019-09-11T15:32:15.536Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"level":10,"msg":"Setup child 'connection' logger instance","time":"2019-09-11T15:32:15.539Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"connection","level":20,"msg":"request: {\"method\":\"GET\",\"url\":\"https://sfptdev-zebu-dave-dev-ed.my.salesforce.com/services/data\",\"headers\":{\"content-type\":\"application/json\",\"user-agent\":\"sfdx toolbelt:\"}}","time":"2019-09-11T15:32:15.539Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"connection","level":20,"msg":"<request> method=GET, url=https://sfptdev-zebu-dave-dev-ed.my.salesforce.com/services/data","time":"2019-09-11T15:32:15.540Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"connection","level":20,"msg":"elappsed time : 440msec","time":"2019-09-11T15:32:15.981Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"connection","level":20,"msg":"<response> status=200, url=https://sfptdev-zebu-dave-dev-ed.my.salesforce.com/services/data","time":"2019-09-11T15:32:15.981Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"connection","level":20,"msg":"response for org versions: [object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]","time":"2019-09-11T15:32:15.986Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"SpawnedTelemetry","level":40,"msg":"Insights logging in enabled. This can be disabled by setting SFDX_DISABLE_INSIGHTS=true","time":"2019-09-11T15:45:57.974Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":6600,"log":"TelemetryReporter","level":40,"msg":"Insights logging in enabled. This can be disabled by setting SFDX_DISABLE_INSIGHTS=true","time":"2019-09-11T15:45:58.725Z","v":0}
{"name":"sfdx","hostname":"NEWYANKEEWORKSHOP","pid":32048,"log":"SourceDeployCommand","level":30,"msg":"[ { state: 'Add',\n    fullName: 'BoxOffice',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\BoxOffice.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'Box_Office_Manager',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\Box_Office_Manager.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'Development',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\Development.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'Marketing_Dept',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\Marketing_Dept.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'PatronManagerLightning',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\PatronManagerLightning.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'MyPackage',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\MyPackage.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'PMGR_MemberAdmission',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\PMGR_MemberAdmission.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'PMGR_Ticketing',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\PMGR_Ticketing.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'PMGR_TicketingAdmin',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\PMGR_TicketingAdmin.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'PMGR_TicketingSettings',\n    type: 'CustomApplication',\n    filePath:\n     'force-app\\\\main\\\\default\\\\applications\\\\PMGR_TicketingSettings.app-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionBenefitSelect\\\\admissionBenefitSelect.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelect.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionBenefitSelect\\\\admissionBenefitSelect.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelect.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionBenefitSelect\\\\admissionBenefitSelect.css',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelect.css',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionBenefitSelect\\\\admissionBenefitSelect.design',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelect.design',\n    height: 1 },\n  { state: 'Add',\n    fullName:\n     'admissionBenefitSelect\\\\admissionBenefitSelectController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelectController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionBenefitSelect\\\\admissionBenefitSelectHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionBenefitSelect\\\\admissionBenefitSelectHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuests.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuests.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuests.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuests.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuests.css',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuests.css',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuests.design',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuests.design',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuestsController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuestsController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionGuests\\\\admissionGuestsHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionGuests\\\\admissionGuestsHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistory.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistory.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistory.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistory.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistory.css',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistory.css',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistory.design',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistory.design',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistoryController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistoryController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'admissionHistory\\\\admissionHistoryHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\admissionHistory\\\\admissionHistoryHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactFormModal\\\\contactFormModal.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactFormModal\\\\contactFormModal.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactFormModal\\\\contactFormModal.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactFormModal\\\\contactFormModal.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactFormModal\\\\contactFormModalController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactFormModal\\\\contactFormModalController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactLookup\\\\contactLookup.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactLookup\\\\contactLookup.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactLookup\\\\contactLookup.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactLookup\\\\contactLookup.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactLookup\\\\contactLookup.design',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactLookup\\\\contactLookup.design',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactLookup\\\\contactLookupController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactLookup\\\\contactLookupController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactLookup\\\\contactLookupHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactLookup\\\\contactLookupHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactSavedEvent\\\\contactSavedEvent.evt',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactSavedEvent\\\\contactSavedEvent.evt',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'contactSavedEvent\\\\contactSavedEvent.evt',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\contactSavedEvent\\\\contactSavedEvent.evt-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'defaultTokens\\\\defaultTokens.tokens',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\defaultTokens\\\\defaultTokens.tokens',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'defaultTokens\\\\defaultTokens.tokens',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\defaultTokens\\\\defaultTokens.tokens-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'patronUtils\\\\patronUtils.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\patronUtils\\\\patronUtils.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'patronUtils\\\\patronUtils.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\patronUtils\\\\patronUtils.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'patronUtils\\\\patronUtilsController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\patronUtils\\\\patronUtilsController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'patronUtils\\\\patronUtilsHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\patronUtils\\\\patronUtilsHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_evt\\\\strike_evt.evt',\n    type: 'AuraDefinitionBundle',\n    filePath: 'force-app\\\\main\\\\default\\\\aura\\\\strike_evt\\\\strike_evt.evt',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_evt\\\\strike_evt.evt',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_evt\\\\strike_evt.evt-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookup.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookup.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookup.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookup.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookup.css',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookup.css',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookupController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookupController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookupHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookupHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_lookup\\\\strike_lookupRenderer.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_lookup\\\\strike_lookupRenderer.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_svg\\\\strike_svg.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath: 'force-app\\\\main\\\\default\\\\aura\\\\strike_svg\\\\strike_svg.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_svg\\\\strike_svg.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_svg\\\\strike_svg.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_svg\\\\strike_svgRenderer.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_svg\\\\strike_svgRenderer.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_tooltip\\\\strike_tooltip.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_tooltip\\\\strike_tooltip.cmp',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_tooltip\\\\strike_tooltip.cmp',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_tooltip\\\\strike_tooltip.cmp-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_tooltip\\\\strike_tooltip.css',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_tooltip\\\\strike_tooltip.css',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_tooltip\\\\strike_tooltipController.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_tooltip\\\\strike_tooltipController.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'strike_tooltip\\\\strike_tooltipHelper.js',\n    type: 'AuraDefinitionBundle',\n    filePath:\n     'force-app\\\\main\\\\default\\\\aura\\\\strike_tooltip\\\\strike_tooltipHelper.js',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AbstractTicketController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AbstractTicketController.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AbstractTicketController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AbstractTicketController.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AccessCodeControllerExt',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AccessCodeControllerExt.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AccessCodeControllerExt',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AccessCodeControllerExt.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AccessCodeListController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AccessCodeListController.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AccessCodeListController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AccessCodeListController.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'ActivityHistoryController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\ActivityHistoryController.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'ActivityHistoryController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\ActivityHistoryController.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AjaxTicketController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AjaxTicketController.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AjaxTicketController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AjaxTicketController.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'ApplicationMessage',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\ApplicationMessage.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'ApplicationMessage',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\ApplicationMessage.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AutomatedCommunication',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AutomatedCommunication.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AutomatedCommunication',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AutomatedCommunication.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AutomatedCommunicationInterface',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AutomatedCommunicationInterface.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'AutomatedCommunicationInterface',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\AutomatedCommunicationInterface.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchAccountAndContactRollups',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchAccountAndContactRollups.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchAccountAndContactRollups',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchAccountAndContactRollups.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchAutomatedCommunication',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchAutomatedCommunication.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchAutomatedCommunication',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchAutomatedCommunication.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreatePaymentTransactions',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreatePaymentTransactions.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreatePaymentTransactions',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreatePaymentTransactions.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreatePortalUsers',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreatePortalUsers.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreatePortalUsers',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreatePortalUsers.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreateSSSAs',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\BatchCreateSSSAs.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreateSSSAs',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreateSSSAs.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreateSubsJournalingData',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreateSubsJournalingData.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchCreateSubsJournalingData',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchCreateSubsJournalingData.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchExtractVenue',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\BatchExtractVenue.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchExtractVenue',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchExtractVenue.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchFeePatcher',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\BatchFeePatcher.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchFeePatcher',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchFeePatcher.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchMigrateFields',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\BatchMigrateFields.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchMigrateFields',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchMigrateFields.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchMigrateSubscriptions',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchMigrateSubscriptions.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchMigrateSubscriptions',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchMigrateSubscriptions.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchPrintController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchPrintController.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchPrintController',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchPrintController.cls-meta.xml',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchSetAmountsPaid',\n    type: 'ApexClass',\n    filePath: 'force-app\\\\main\\\\default\\\\classes\\\\BatchSetAmountsPaid.cls',\n    height: 1 },\n  { state: 'Add',\n    fullName: 'BatchSetAmountsPaid',\n    type: 'ApexClass',\n    filePath:\n     'force-app\\\\main\\\\default\\\\classes\\\\BatchSetAmountsPaid.cls-meta.xml',\n    height: 1 },\n  ... 9799 more items ]","time":"2019-09-11T15:46:01.211Z","v":0}

[daveespo]

Alright, I've done more debugging on this than I care to admit. I upgraded my CLI to the latest plugins so now I'm

@oclif/plugin-commands 1.2.3 (core)
@oclif/plugin-help 2.2.1 (core)
@oclif/plugin-not-found 1.2.3 (core)
@oclif/plugin-plugins 1.7.8 (core)
@oclif/plugin-update 1.3.9 (core)
@oclif/plugin-warn-if-update-available 1.7.0 (core)
@oclif/plugin-which 1.0.3 (core)
@salesforce/sfdx-trust 3.0.5 (core)
analytics 1.2.1 (core)
etcopydata 0.4.4
generator 1.1.1 (core)
salesforcedx 46.13.1
├─ force-language-services 46.18.0
└─ salesforce-alm 46.17.0

sfdx-cli 7.23.1 (core)

I cracked open the source code and have tracked this down to the implementation of _doLocalDelete in SourceDeployApi (salesforce-alm/dist/lib/source/sourceDeployApi.js)

I doctored up the method and the major tax is the call to PathUtils.cleanEmptyDirs

    async _doLocalDelete(ases) {
        l.error('Begin _doLocalDelete()');
        const a = Date.now();
        this.tmpBackupDeletions = await SourceUtil.createOutputDir('sourceDelete');
        ases.forEach((ase) => {
            l.error(ase.getKey());
            ase
                .getPendingDeletedWorkspaceElements()
                .forEach(we => fsExtra.copySync(we.getSourcePath(), path.join(this.tmpBackupDeletions, path.basename(we.getSourcePath()))));
            l.error('before commitDeletes()');
            ase.commitDeletes([]);
            l.error('after commitDeletes(); calling cleanEmptyDirs(' + path.dirname(ase.getMetadataFilePath()) + ')');
            PathUtils.cleanEmptyDirs(path.dirname(ase.getMetadataFilePath()));
            l.error('after cleanEmptyDirs');
        });
        l.error('_doLocalDelete total duration: ' + (Date.now() - a) + 'ms');
    }

cleanEmptyDirs is incredibly inefficient because it does a directory listing on the directory containing the metdata type (ex. classes, objects, staticresources, etc) to find empty subdirectories. For directories with a large number of metadata files (our staticresources directory has 1000 files in it), it lists the entire directory to find any subdirectories. As you can see by this debug output, it's taking over a second per metadata component. This adds up to 677 seconds or about 11 minutes in our project.

_doLocalDelete total duration: 677802ms

ERROR 2019-09-11T21:14:39.461Z:  StaticResource__pasadenaLayout
ERROR 2019-09-11T21:14:39.462Z:  before commitDeletes()
ERROR 2019-09-11T21:14:39.462Z:  after commitDeletes(); calling cleanEmptyDirs(C:\Users\esposito\Documents\PatronManager\patronticket-sfdx-3\force-app\main\default\staticresources)
ERROR 2019-09-11T21:14:40.502Z:  after cleanEmptyDirs
ERROR 2019-09-11T21:14:40.504Z:  StaticResource__pasadenaLayoutStyles
ERROR 2019-09-11T21:14:40.505Z:  before commitDeletes()
ERROR 2019-09-11T21:14:40.505Z:  after commitDeletes(); calling cleanEmptyDirs(C:\Users\esposito\Documents\PatronManager\patronticket-sfdx-3\force-app\main\default\staticresources)
ERROR 2019-09-11T21:14:41.523Z:  after cleanEmptyDirs
ERROR 2019-09-11T21:14:41.525Z:  StaticResource__PasadenaTicketTheme
ERROR 2019-09-11T21:14:41.526Z:  before commitDeletes()
ERROR 2019-09-11T21:14:41.527Z:  after commitDeletes(); calling cleanEmptyDirs(C:\Users\esposito\Documents\PatronManager\patronticket-sfdx-3\force-app\main\default\staticresources)
ERROR 2019-09-11T21:14:42.600Z:  after cleanEmptyDirs
ERROR 2019-09-11T21:14:42.602Z:  StaticResource__pasadenaV2Gallery
ERROR 2019-09-11T21:14:42.602Z:  before commitDeletes()
ERROR 2019-09-11T21:14:42.603Z:  after commitDeletes(); calling cleanEmptyDirs(C:\Users\esposito\Documents\PatronManager\patronticket-sfdx-3\force-app\main\default\staticresources)
ERROR 2019-09-11T21:14:43.606Z:  after cleanEmptyDirs

If I comment out the cleanEmptyDirs call, it reduces the _doLocalDelete to TWO POINT FIVE seconds:

_doLocalDelete total duration: 2570ms

This 11 minute tax is basically a blocker for our conversion to source format. Can a pair of engineer eyes take a look a this and see if there's a more efficient way to track the empty directory cleanup?

I experimented with moving the cleanEmptyDirs outside of the loop over the ASEs and that seems to be the magic trick

[jtomtran]

I experienced the same problem. Source conversion from MDAPI to DX source took 20-40 minutes on 100% CPU.

It gets worse when we convert over an existing populated DX source. For example, if we convert a MDAPI package to an empty DX project, it took 20 minutes. If we do the same conversion the 2nd time (this time the DX project is already populated with lots of metadata from the previous conversion), then it took 40 minutes. Seems like in the second run, it spent a significant amount of time to detect duplicates.

We have CI job that takes Prod metadata and convert to source format for backup and this is unsustainable the amount of time and CPU it takes.

Kudos to Dave for digging underneath the CLI. I could see where some of the time loss came from now. This is a blocker for us in adopting DX.

[clairebianchi]

@daveespo Thank you for digging into this so deeply. I am sorry that it taking such a long time for the convert. I will have someone on our side take a look.

[daveespo]

Just for further context: We're only seeing this performance problem on Windows -- on Linux and OSX, the duration of the _doLocalDelete is somewhere under a minute.

[tnoonan-salesforce]

Good catch I have a fix.

[jtomtran]

My performance issue is with Linux. @tnoonan-salesforce does the fix address Linux and also the fact that conversion from MDAPI to DX source is much slower the 2nd time ? (ie. due to duplication detection because conversion run in a DX project that already has source).

[tnoonan-salesforce]

On my mac without my fix a 3K item deploy took over 6 minutes. With my fix it was 2 minutes 27 seconds.

[tnoonan-salesforce]

The problem isn't OS-specific.

[daveespo]

@tnoonan-salesforce -- glad to hear there is a fix -- will this also improve the performance of force:source:push -- some of my team members have reported similar slowness pushing to scratch orgs

Also, is this fix testable by me today by pulling the pre-release channel into my SFDX CLI?

[daveespo]

Can I assume this was released to the production channel? I'm now seeing way better sfdx force:source:deploy times. The build of the zip file now takes about 48 seconds where it previously took 11 minutes!