Pycharm 2019.1.3 IDE is very slow while using Illuminated Cloud

[Shmuel Sochet]

• Mainly occurs while trying to Commit, Push or Pull
• I know this isn’t the intended IDE, however I pretty much have not had issues using Pycharm until now
• Our team of four already use Pycharm for our development and being able to use IC with Pycharm is very helpful
• I’m using JAVA 8 since IC doesn’t work with the bundled Java 11.

[Scott Wells]

Hi, Shmuel. Even though Pycharm isn't supported in a first-class manner, there's no reason that it should work differently from WebStorm. Let me review the logs and see if I can find anything obvious. I may need additional logs from you to get to the bottom of this. I'll let you know.

[Scott Wells]

Two things:

1. You say "mainly occurs while trying to commit, push or pull". If you said "push or pull" I'd think you meant SFDX push/pull, but since you also said "commit", are you talking about Git operations?
2. If you do mean during SFDX push/pull operations, do you mind enabling debug logging for Salesforce DX as documented at http://www.illuminatedcloud.com/support/debuglogging, then reproduce the behavior, and then attach that idea.log for review. I'd like to see where the time is being spent.

Thanks!

[Shmuel Sochet]

• Yes I meant Git Commit, SFDX Push/Pull. I attached logs with debug enabled.
• Glad to know Pycharm should work the same, although does the latest Webstorm come bundled with JDK 11. IC definitely did not work with 11, I had to switch the Boot JDK to 8

[Scott Wells]

Thanks for the logs. I'll take a look shortly. IC doesn't currently work with JDK 11 anywhere because it unbundles some of the libs that are used by IC for communicating with the server, in particular JAX-WS. I have a test build that bundles those libs with IC itself and hope to release it soon so that JDK 11 will work fine.

I'll let you know what I find.

[Shmuel Sochet]

Thank you.

Great news about the bundled libs. Scott, you’re always one step ahead.

[Scott Wells]

So unfortunately the logs don't seem to reflect the experience you appear to be having. Since adding the debug logging config, I see one SFDX push and one SFDX pull, and they both seem to be quite fast:

Push (~4 secs)

2019-07-05 10:53:19,973 [71621030]   INFO - j.builder.ForceComSfdxDeployer - Using the sfdx CLI to push changes for module 'project' to scratch org 'new' with force=false, background=false. 
2019-07-05 10:53:19,987 [71621044]  DEBUG - atedcloud.util.CommandLineUtil - Running command line: 'C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u [e-mail] --json' from working directory: 'C:\projects\comp\sf-intake'. 
2019-07-05 10:53:19,992 [71621049]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 1. 
2019-07-05 10:53:20,992 [71622049]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 2. 
2019-07-05 10:53:21,992 [71623049]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 3. 
2019-07-05 10:53:22,993 [71624050]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 4. 
2019-07-05 10:53:23,993 [71625050]  DEBUG - atedcloud.util.CommandLineUtil - Returning command-line response: CommandLineResponse{exitCode=0, output='{  "status": 0,  "result": {    "pushedSource": []  }}', error=''} 
2019-07-05 10:53:23,993 [71625050]   INFO - j.builder.ForceComSfdxDeployer - Push completed in 4 s 6 ms. 
2019-07-05 10:53:23,997 [71625054]  DEBUG - j.builder.ForceComSfdxDeployer - Received push response:
{
  "status": 0,
  "successResponse": {
    "status": 0,
    "result": {
      "pushedSource": []
    }
  }
} 
2019-07-05 10:53:23,997 [71625054]  DEBUG - j.builder.ForceComSfdxDeployer - Checking for conflicts. 
2019-07-05 10:53:23,997 [71625054]  DEBUG - j.builder.ForceComSfdxDeployer - Push appears to have succeeded. Adding details. 
2019-07-05 10:53:23,997 [71625054]   INFO - .IlluminatedCloudExceptionUtil - All files are up-to-date. 
2019-07-05 10:53:23,998 [71625055]   INFO - .IlluminatedCloudExceptionUtil - Push details:
{
  "successes": [],
  "failures": [],
  "numSuccesses": 0,
  "numFailures": 0
} 

Pull (~3 secs)

2019-07-05 10:53:29,086 [71630143]   INFO - .builder.ForceComSfdxRetriever - Using the sfdx CLI to pull changes for module 'sf-intake' from scratch org 'new' with force=false. 
2019-07-05 10:53:29,087 [71630144]  DEBUG - atedcloud.util.CommandLineUtil - Running command line: 'C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:pull -u [e-mail] --json' from working directory: 'C:\projects\sps\sf-intake'. 
2019-07-05 10:53:29,091 [71630148]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:pull -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 1. 
2019-07-05 10:53:30,092 [71631149]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:pull -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 2. 
2019-07-05 10:53:31,092 [71632149]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:pull -u [e-mail] --json: Using polling interval 1000 ms for polling iteration 3. 
2019-07-05 10:53:32,092 [71633149]  DEBUG - atedcloud.util.CommandLineUtil - Returning command-line response: CommandLineResponse{exitCode=0, output='{  "status": 0,  "result": {    "pulledSource": []  }}', error=''} 
2019-07-05 10:53:32,093 [71633150]   INFO - .builder.ForceComSfdxRetriever - Pull completed in 3 s 7 ms. 
2019-07-05 10:53:32,094 [71633151]  DEBUG - .builder.ForceComSfdxRetriever - Received pull response:
{
  "status": 0,
  "successResponse": {
    "status": 0,
    "result": {
      "pulledSource": []
    }
  }
} 
2019-07-05 10:53:32,094 [71633151]  DEBUG - .builder.ForceComSfdxRetriever - Checking for conflicts. 
2019-07-05 10:53:32,094 [71633151]  DEBUG - .builder.ForceComSfdxRetriever - Adding details. 
2019-07-05 10:53:32,094 [71633151]  DEBUG - .builder.ForceComSfdxRetriever - Refreshing the virtual file system before comparison. 
2019-07-05 10:53:32,141 [71633198]   INFO - .IlluminatedCloudExceptionUtil - All files are up-to-date. 
2019-07-05 10:53:32,141 [71633198]   INFO - .IlluminatedCloudExceptionUtil - Pull details:
{
  "successes": [],
  "failures": [],
  "numSuccesses": 0,
  "numFailures": 0
} 

I do see a large number of these in your logs:

2019-07-05 10:53:32,752 [71633809]   WARN - nresolvableReferenceInspection - Received dead references from ApexSimpleRefExpressionImpl(SIMPLE_REF_EXPRESSION) 

I'm not sure why those are occurring, but there are two things you can try to see if that's related to the slowness:

1. Rebuild caches and indices using Illuminated Cloud>Configure Project>Rebuild Caches and Indices. Allow the project to close and reopen afterward. If statements like those are still logged, something else is going on that I'll need to investigate.
2. If that continues to be an issue in the log, and the slowness is still present, you can disable that code inspection under Preferences/Settings>Editor>Inspections, then in the tree uncheck Salesforce>Unresolvable reference. Let's see if that changes anything.

If those don't help, I'll likely need for you to gather some profiling info. Please let me know the results.

[Shmuel Sochet]

The Push and Pull itself where quick. It was from pressing the button until the window pops up that there is definitely a lag.

Thank you. I’ll try these suggestions.

[Scott Wells]

Hi, Shmuel. Any update on this? FYI, I've implemented first-class support for PyCharm (and PhpStorm/RubyMine) in addition to IntelliJ IDEA and WebStorm. I've not seen this behavior during my own testing, so I'm curious as to whether the aforementioned suggestions resolved it for you.

[Shmuel Sochet]

I’m really sorry Scott, I was not able to test out your suggestions. Many things came up at once and I have not had a second to test it out. For now it’s not terrible so I have just been managing with the lag. When I get a moment I’ll let you know what happens. You really set the bar high for response times, I can’t compete. Thank you for all your help, you’ve been incredible. And a huge thank you for first-class support this is amazing news.

[Shmuel Sochet]

I just tried Rebuilding Caches and I don’t see nresolvableReferenceInspection in my logs but the lag still persists. Maybe I’ll upgrade to the new IC version and still if the lag still exists.

[Scott Wells]

No problem on the timing. It's all on your schedule. Let me know whether updating the plugin helps or not. Assuming it doesn't, I'll need to think about how to gather other diagnostic info that will help since the logs don't seem to reflect this behavior.

[Shmuel Sochet]

Hi, Scott. I apologize for the very delayed response. Updating the plugin unfortunately did not help.

[Scott Wells]

No problem. Sorry to hear that the problem is still present. Did you try disabling the Unresolvable Reference code inspection? You can do so by unchecking it here:

[Shmuel Sochet]

I just tried that now and I’m sorry it didn’t help.

[Scott Wells]

I'm kind of glad it wasn't that. That means it's likely something at a lower level. Okay, so are you still on 2019.1.3? If so, can you try two more things? First, please update to the latest which is 2019.2.2 (I think) and see if that makes a difference. If it doesn't, please install IntelliJ IDEA Community Edition, install IC2 into that, open the same project, and see if you see the same behavior. I'm trying to isolate this to a specific IDE or IDE version or something specific to this project.

[Shmuel Sochet]

Updating Pycharm (2019.2.2) seems to have helped somewhat with the general lag (moving the cursor and switching between file tabs). However the main issue was not resolved. I would like to better explain what the exact issue I’m referring to is.

When clicking the Push Metadata icon it takes a while for the Pushing dialog to display. The icon is highlighted after pushing (see below) but it can take several seconds for the dialog to show (I counted around 9 seconds once, usually 3-4). As you mentioned previously the pushing itself may be quick but the UI/IDE is not responding quickly.

The same occurs for clicking on other buttons on that Toolbar (Main Toolbar). Like Git Push/Pull…

‌

‌

I tried on the latest version of ItelliJ (2019.2.2) as well and I’m still getting the same results.

‌

[Scott Wells]

Thanks for the explanation. In my second response above I describe how to enable debug logging. It might even still be enabled, but if not, please enable it for metadata deployment. Then please reproduce this behavior by performing a push and attach the resulting log so I can see where the time is going.

[Shmuel Sochet]

Sure here you go

2019-09-20 10:54:40,029 [1421329]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 4222 ms 
2019-09-20 10:54:40,029 [1421329]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 4259 ms 
2019-09-20 10:55:03,944 [1445244]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 3770 ms 
2019-09-20 10:55:03,944 [1445244]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 3807 ms 
2019-09-20 10:55:03,948 [1445248]  DEBUG - j.builder.ForceComSfdxDeployer - Pushing 'sf-intake' to 'email_groups' 
2019-09-20 10:55:04,009 [1445309]   INFO - j.builder.ForceComSfdxDeployer - Using the sfdx CLI to push changes for module 'sf-intake' to scratch org 'email_groups' with force=false, background=false. 
2019-09-20 10:55:04,012 [1445312]  DEBUG - atedcloud.util.CommandLineUtil - Running command line: 'C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json' from working directory: 'C:\projects\sps\sf-intake'. 
2019-09-20 10:55:04,019 [1445319]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json: Using polling interval 1000 ms for polling iteration 1. 
2019-09-20 10:55:05,019 [1446319]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json: Using polling interval 1000 ms for polling iteration 2. 
2019-09-20 10:55:06,020 [1447320]  DEBUG - atedcloud.util.CommandLineUtil - Returning command-line response: CommandLineResponse{exitCode=1, output='{  "status": 1,  "name": "NoOrgFound",  "message": "No org configuration found for name --json",  "exitCode": 1,  "commandName": "SourcePushCommand",  "stack": "NoOrgFound: No org configuration found for name --json\n    at Function.create (C:\\Users\\shmuels\\AppData\\Local\\sfdx\\client\\7.14.0-bd96f098e0\\node_modules\\salesforce-alm\\node_modules\\@salesforce\\core\\lib\\sfdxError.js:141:16)\n    at AuthInfo.initAuthOptions (C:\\Users\\shmuels\\AppData\\Local\\sfdx\\client\\7.14.0-bd96f098e0\\node_modules\\salesforce-alm\\node_modules\\@salesforce\\core\\lib\\authInfo.js:509:53)",  "warnings": [    "The error message \"NoOrgFound\" has been deprecated and will be removed in v46 or later.  It will become \"NamedOrgNotFound\"."  ]}', error=''} 
2019-09-20 10:55:06,020 [1447320]   INFO - j.builder.ForceComSfdxDeployer - Push completed in 2 s 11 ms. 
2019-09-20 10:55:06,020 [1447320]  DEBUG - j.builder.ForceComSfdxDeployer - Received push response:
{
  "status": 1,
  "failureResponse": {
    "status": 1,
    "message": "No org configuration found for name --json",
    "name": "NoOrgFound",
    "result": [],
    "partialSuccess": []
  }
} 
2019-09-20 10:55:06,020 [1447320]  DEBUG - j.builder.ForceComSfdxDeployer - Checking for conflicts. 
2019-09-20 10:55:06,020 [1447320]  DEBUG - j.builder.ForceComSfdxDeployer - Push appears to have failed. Adding details. 
2019-09-20 10:55:06,020 [1447320]  DEBUG - j.builder.ForceComSfdxDeployer -   Adding push failure as 'NoOrgFound - No org configuration found for name --json'. 
2019-09-20 10:55:06,020 [1447320]   INFO - .IlluminatedCloudExceptionUtil - Pushed 0/1 components to email_groups in 2 s 11 ms with status 1. 
2019-09-20 10:55:06,020 [1447320]   INFO - .IlluminatedCloudExceptionUtil - Push details:
{
  "successes": [],
  "failures": [
    "NoOrgFound - No org configuration found for name --json"
  ],
  "numSuccesses": 0,
  "numFailures": 1
} 

‌

[Scott Wells]

Thanks. So I can see 23 seconds gone right at the beginning before IC actually does anything:

2019-09-20 10:54:40,029 [1421329]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 4222 ms 
2019-09-20 10:54:40,029 [1421329]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 4259 ms 
2019-09-20 10:55:03,944 [1445244]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 3770 ms 

You said the same thing happens when you perform Git operations? What happens if you disable the Illuminated Cloud 2 plugin and try the same Git operations? Do you see the same delays or no?

[Shmuel Sochet]

This is without IC disabled. It’s definitely much quicker. Barely a delay.

‌

2019-09-20 11:06:05,471 [  57985]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeProjectCodeStyleConfiguration took 15 ms, RunManager took 219 ms 
2019-09-20 11:06:14,582 [  67096]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 189 ms 
2019-09-20 11:06:14,583 [  67097]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 257 ms 

‌

[Scott Wells]

That actually quite useful. I see a very similar gap in time, albeit 9 seconds in this case vs. 23 in the other. It's still a much longer period of time than it should be. Can you re-enable IC and repeat this same Git operation so I can have a better apples-to-apples comparison? If the time gaps are similar/identical, the issue is unlikely IC and likely something else.

[Shmuel Sochet]

With IC enabled

‌

2019-09-20 11:20:09,025 [  43194]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 4691 ms 
2019-09-20 11:20:13,266 [  47435]   INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 9102 ms 
2019-09-20 11:20:19,321 [  53490]   INFO - rationStore.ComponentStoreImpl - Saving Project 'C:\projects\sps\sf-intake' sf-intakeRunManager took 3623 ms 

‌

[Scott Wells]

Ah...I think I know what might be happening. How large is your .iml file?

[Shmuel Sochet]

I think 1KB. Is that the file in .idea named <project_name>.iml?

[Scott Wells]

Yep. Darn...so here's what I'm thinking...and I think there may still be something to it. The IDE saves all files on key events such as starting a build (or in IC's case, deploying), the window losing focus, etc. I'm thinking that one of IC's config files has grown very large and it's making that save expensive. The main IC config file that grows large is the module file because it contains a full list of the org's metadata if you're using (or have ever used) a Selected subscription. Please sure the results of ls -l .idea. I'd like to see the file sizes.

[Shmuel Sochet]

‌

‌

‌

[Scott Wells]

Aha! I'm 99% sure it's that workspace.xml file that's doing this to you. That thing can also accumulate over time, and that's a 15MB file it's writing every single time. That's really only scratch stuff that can get re-established over time. Please exit the IDE completely, move that out of the way, e.g., mv workspace.xml old-workspace.xml, and re-open the IDE. I bet that resolves this for you.

[Shmuel Sochet]

Scott!!!! You’re incredible. This issue as cost me so much time and frustration. I cannot thank you enough for helping me get to the bottom of this. Now it doesn’t even run the RunManager or saveProjectsAndApp methods.

This info about workspace.xml is so helpful for whenever Jetbrains IDEs get slow. I will file it away for the future.

Here is the output now for IC Push Metadata. (The Git commit command doesn’t even produce any log line now.)

It’s so clean and pleasant to code now. It makes sense why everything was slow since any time I move the cursor or switched file tabs or opened any settings it tried to save this massive file.

Thank you, thank you, thank you!

Have an amazing weekend.

‌

2019-09-20 11:46:12,042 [1606211]  DEBUG - j.builder.ForceComSfdxDeployer - Pushing 'sf-intake' to 'email_groups' 
2019-09-20 11:46:12,099 [1606268]   INFO - j.builder.ForceComSfdxDeployer - Using the sfdx CLI to push changes for module 'sf-intake' to scratch org 'email_groups' with force=false, background=false. 
2019-09-20 11:46:12,101 [1606270]  DEBUG - atedcloud.util.CommandLineUtil - Running command line: 'C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json' from working directory: 'C:\projects\sps\sf-intake'. 
2019-09-20 11:46:12,107 [1606276]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json: Using polling interval 1000 ms for polling iteration 1. 
2019-09-20 11:46:13,107 [1607276]  DEBUG - .VariableLengthPollingInterval - C:/Program Files/Salesforce CLI/bin/sfdx.cmd force:source:push -u  --json: Using polling interval 1000 ms for polling iteration 2. 
2019-09-20 11:46:14,107 [1608276]  DEBUG - atedcloud.util.CommandLineUtil - Returning command-line response: CommandLineResponse{exitCode=1, output='{  "status": 1,  "name": "NoOrgFound",  "message": "No org configuration found for name --json",  "exitCode": 1,  "commandName": "SourcePushCommand",  "stack": "NoOrgFound: No org configuration found for name --json\n    at Function.create (C:\\Users\\shmuels\\AppData\\Local\\sfdx\\client\\7.14.0-bd96f098e0\\node_modules\\salesforce-alm\\node_modules\\@salesforce\\core\\lib\\sfdxError.js:141:16)\n    at AuthInfo.initAuthOptions (C:\\Users\\shmuels\\AppData\\Local\\sfdx\\client\\7.14.0-bd96f098e0\\node_modules\\salesforce-alm\\node_modules\\@salesforce\\core\\lib\\authInfo.js:509:53)",  "warnings": [    "The error message \"NoOrgFound\" has been deprecated and will be removed in v46 or later.  It will become \"NamedOrgNotFound\"."  ]}', error=''} 
2019-09-20 11:46:14,107 [1608276]   INFO - j.builder.ForceComSfdxDeployer - Push completed in 2 s 8 ms. 
2019-09-20 11:46:14,107 [1608276]  DEBUG - j.builder.ForceComSfdxDeployer - Received push response:
{
  "status": 1,
  "failureResponse": {
    "status": 1,
    "message": "No org configuration found for name --json",
    "name": "NoOrgFound",
    "result": [],
    "partialSuccess": []
  }
} 
2019-09-20 11:46:14,107 [1608276]  DEBUG - j.builder.ForceComSfdxDeployer - Checking for conflicts. 
2019-09-20 11:46:14,107 [1608276]  DEBUG - j.builder.ForceComSfdxDeployer - Push appears to have failed. Adding details. 
2019-09-20 11:46:14,107 [1608276]  DEBUG - j.builder.ForceComSfdxDeployer -   Adding push failure as 'NoOrgFound - No org configuration found for name --json'. 
2019-09-20 11:46:14,107 [1608276]   INFO - .IlluminatedCloudExceptionUtil - Pushed 0/1 components to email_groups in 2 s 8 ms with status 1. 
2019-09-20 11:46:14,107 [1608276]   INFO - .IlluminatedCloudExceptionUtil - Push details:
{
  "successes": [],
  "failures": [
    "NoOrgFound - No org configuration found for name --json"
  ],
  "numSuccesses": 0,
  "numFailures": 1
} 

‌

[Scott Wells]

Oh man...I'm SO glad we got to the bottom of this! Thank you so much for you patience and assistance working through it as well. I know it's been frustrating and that's the last thing I ever want for a user.

Have a great weekend as well!

[Scott Wells]

Oh, one other thing I see in that log...it appears that it's trying to push to an org with no connection--or at least no username or alias. You might need to reconfigure the connection for that project. Let me know if you can't figure out how to do that.

[Shmuel Sochet]

You’re welcome.

Thank you. I should be fine with re-configuring.

[Scott Wells]

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