Long analysis on changes with large file in dependency graph

[CMLL]

Every time a change to a file in the project I'm working is detected it triggers a Analysis in background with a small number of items, around ~120. This sometimes finish quickly but other times it takes a long time to finish and seems to get stuck until I reload the window completely.

The trigger seems to happen regardless if the changes are saved or not in the file, just inserting a new line without any text is enough to trigger the analysis. This is a bit annoying since makes constantly burst a cpu usage that sometimes goes away but sometimes it gets stuck. Also I've noticed that most of the times when this quick analysis is running it affects the results of the language server in other parts of the file, sometimes they return but pretty slowly, other times they don't return at all.

I've enabled trace when this happens but I can't see any exception that hangs the analysis. Is there a configuration option to prevent the analysis to happen that often? Maybe so it gets triggered when a file is saved?

[jakebailey]

With trace logging enabled, do you see "reloading modules" in the language server logs? If you do, then the file watching may be the cause.

If not, then if the file you're editing is a dependency of other modules, then those will need to be reanalayzed, and would show in the bottom bar. It shouldn't get stuck, in any case.

I'm not aware of any mechanism we could use in the language server protocol that would let us only operate after a save. The editor feeds us file changes so that we always have the current document (otherwise we can't provide completion/hover/etc, because we won't have the correct view on the file, nor the analysis for that file that gives us the info to serve those requests).

[CMLL]

I don't see "reloading modules" in the logs with trace. After reload and letting the analysis complete it ends in this...

...
Analysis of models.core.maintenance_period (User) on depth 0 completed in 38.9106 ms.
Analysis of models.core.api_calls_counter (User) on depth 0 completed in 3.9136 ms.
Analysis of models.core.cloud_gcp (User) on depth 0 completed in 4.8119 ms.
Analysis of models.core.maintenance (User) on depth 0 completed in 36.3584 ms.
Analysis of models.core.cloud_aws (User) on depth 0 completed in 100.3609 ms.
Analysis complete: 4327 modules in 19862.5127 ms.
Analysis version 6575 of 5417 entries has been completed in 9767.1398 ms.
Forcing full garbage collection and heap compaction.

Adding an empty line triggers this...

Analysis of tasks.cloud(User) queued
Analysis version 6576 of 128 entries has started.
Analysis of models.core.contact_event (User) on depth 0 completed in 4.7921 ms.
Analysis of models.masterdb (User) on depth 0 completed in 1317.5093 ms.
Analysis of models.monitoring_policy.exceptions (User) on depth 0 completed in 4.907 ms.
Analysis of models.monitoring_policy.actions (User) on depth 0 completed in 5.4286 ms.
...

It continues for a long time but never gets to the completed message and the garbage collection one.

The times I see the burst analysis complete it reaches this log line...

Analysis complete: 64 modules in 3946.3452 ms.
Analysis version 5739 of 128 entries has been completed in 3939.2703 ms.

From your explanation I think is being triggered by the python extension sending a request for analysis on every change rather than a more spread out approach of sending file changes when the changes are saved. I'm using the insiders build of the python extension, I'm going to switch back to the main branch and test this again, but if that is right, then this issue would be better on the python extension repository.

Thanks @jakebailey

[MikhailArkhipov]

If changes were sent only on save, completions and tooltips would not work as you type of edit files between saves...

[jakebailey]

No, the extension isn't sending a request for an analysis, we're doing an analysis in response to the file being changed. The extension only hooks up the editor to the language server, it doesn't explicitly request any work.

Feasibly, we could debounce file changes and introduce some sort of delay before reanalyzing, but that'd mean that any future requests would get the wrong information.

[CMLL]

I see. Could there be a way to limit these bursts analysis in reach then? Perhaps making it only look in the modified file only, or only one dependency down? Right now adding an empty line to a file in a project (granted, is a pretty big project) triggers analysis of all these files, which I understand is needed for the right functioning of the LS but the constant bursting makes it pretty hard to use reliably.

Forcing full garbage collection and heap compaction.
Analysis of tasks.cloud(User) queued
Analysis version 5782 of 128 entries has started.
Analysis of models.core.contact_event (User) on depth 0 completed in 2.5525 ms.
Analysis of models.masterdb (User) on depth 0 completed in 1214.6711 ms.
Analysis of models.monitoring_policy.exceptions (User) on depth 0 completed in 1.9358 ms.
Analysis of models.monitoring_policy.actions (User) on depth 0 completed in 2.0436 ms.
Analysis of models.core.invitation (User) on depth 0 completed in 4.6629 ms.
Analysis of models.core.active_outage (User) on depth 0 completed in 6.6241 ms.
Analysis of models.core.scheduled_report (User) on depth 0 completed in 6.8823 ms.
Analysis of models.core.server_facts (User) on depth 0 completed in 8.825 ms.
Analysis of models.monitoring_policy.comparison_condition (User) on depth 0 completed in 15.6772 ms.
Analysis of models.core.cim_credential (User) on depth 0 completed in 8.8477 ms.
Analysis of models.core.ssh_credential (User) on depth 0 completed in 9.1488 ms.
Analysis of models.core.ssh_resource_script (User) on depth 0 completed in 9.1907 ms.
Analysis of models.core.pending_users (User) on depth 0 completed in 0.5278 ms.
Analysis of models.core.traceroute (User) on depth 0 completed in 13.0719 ms.
Analysis of models.core.scoreboard (User) on depth 0 completed in 3.1477 ms.
Analysis of models.core.event (User) on depth 0 completed in 15.5319 ms.
Analysis of models.core.sales_commission (User) on depth 0 completed in 3.797 ms.
Analysis of models.core.user_attribute (User) on depth 0 completed in 9.6421 ms.
Analysis of models.core.monitornode (User) on depth 0 completed in 34.9021 ms.
Analysis of models.core.cloud_azure (User) on depth 0 completed in 36.933 ms.
Analysis of models.core.connections (User) on depth 0 completed in 2.7733 ms.
Analysis of models.core.widget_queue_summary (User) on depth 0 completed in 2.8367 ms.
Analysis of models.core.blacklist (User) on depth 0 completed in 3.6457 ms.
Analysis of models.core.feature_highlight (User) on depth 0 completed in 5.4347 ms.
Analysis of models.core.kpi (User) on depth 0 completed in 6.2352 ms.
Analysis of models.core.network_service_discovery (User) on depth 0 completed in 10.9296 ms.
Analysis of models.core.metric_category (User) on depth 0 completed in 19.0213 ms.
Analysis of models.core.snmp_traps (User) on depth 0 completed in 20.6194 ms.
Analysis of models.core.global_announcement (User) on depth 0 completed in 4.4827 ms.
Analysis of models.core.sentry (User) on depth 0 completed in 11.1463 ms.
Analysis of models.core.appconfig (User) on depth 0 completed in 15.6476 ms.
Analysis of models.core.countermeasures (User) on depth 0 completed in 19.397 ms.
Analysis of models.core.email_lists (User) on depth 0 completed in 36.332 ms.
Analysis of models.core.copy_template (User) on depth 0 completed in 0.6444 ms.
Analysis of models.core.infra_map (User) on depth 0 completed in 1.5534 ms.
Analysis of models.core.snmp_port_discovery (User) on depth 0 completed in 44.8151 ms.
Analysis of models.core.onprem_connect (User) on depth 0 completed in 46.7808 ms.
Analysis of models.core.monitoring_policy (User) on depth 0 completed in 5.8532 ms.
Analysis of models.core.custom_incident_filter (User) on depth 0 completed in 47.3153 ms.
Analysis of models.core.vmware (User) on depth 0 completed in 1.7228 ms.
Analysis of models.tsdb.tsdb_base (User) on depth 0 completed in 3.3834 ms.
Analysis of models.core.filters (User) on depth 0 completed in 9.0955 ms.
Analysis of models.core.invoice (User) on depth 0 completed in 61.8226 ms.
Analysis of tasks.ops (User) on depth 0 completed in 21.2562 ms.
Analysis of models.monitoring_policy.ruleset_evaluator (User) on depth 0 completed in 6.2585 ms.
Analysis of models.core.widget_queue (User) on depth 0 completed in 6.5815 ms.
Analysis of models.core.saml_idp (User) on depth 0 completed in 10.0586 ms.
Analysis of models.monitoring_policy.policy_evaluator (User) on depth 0 completed in 6.3134 ms.
Analysis of models.core.availability (User) on depth 0 completed in 30.9626 ms.
Analysis of models.core.maintenance (User) on depth 0 completed in 50.749 ms.
Analysis of models.core.widget (User) on depth 0 completed in 53.7224 ms.
Analysis of models.core.dashboard (User) on depth 0 completed in 9.9745 ms.
Analysis of models.core.order (User) on depth 0 completed in 9.3927 ms.
Analysis of models.tsdb.tsdb_mysql (User) on depth 0 completed in 80.5731 ms.
Analysis of models.tsdb (User) on depth 0 completed in 0.3631 ms.
Analysis of tasks.celeryapp (User) on depth 0 completed in 7.5579 ms.
Analysis of tasks.monitoring_policy (User) on depth 0 completed in 0.8957 ms.
Analysis of tasks.cloud (User) on depth 0 completed in 17.0674 ms.
Analysis of models.core.server (User) on depth 0 completed in 439.6908 ms.
Analysis of models.core.maintenance_period (User) on depth 0 completed in 36.1654 ms.
Analysis of models.core.cloud (User) on depth 0 completed in 38.1387 ms.
Analysis of models.core.api_calls_counter (User) on depth 0 completed in 3.6842 ms.
Analysis of models.core.cloud_gcp (User) on depth 0 completed in 4.6792 ms.
Analysis of models.core.cloud_aws (User) on depth 0 completed in 99.4394 ms.
Analysis of models.core.contact_event (User) on depth 0 completed in 1.9494 ms.
Analysis of models.masterdb (User) on depth 0 completed in 1255.5011 ms.
Analysis of models.monitoring_policy.exceptions (User) on depth 0 completed in 4.634 ms.
Analysis of models.monitoring_policy.actions (User) on depth 0 completed in 4.9895 ms.
Analysis of models.core.active_outage (User) on depth 0 completed in 5.4479 ms.
Analysis of models.core.invitation (User) on depth 0 completed in 1.5422 ms.
Analysis of models.core.event (User) on depth 0 completed in 7.2572 ms.
Analysis of models.core.ssh_credential (User) on depth 0 completed in 3.2266 ms.
Analysis of models.core.scheduled_report (User) on depth 0 completed in 8.5979 ms.
Analysis of models.core.server_facts (User) on depth 0 completed in 7.4289 ms.
Analysis of models.monitoring_policy.comparison_condition (User) on depth 0 completed in 13.914 ms.
Analysis of models.core.traceroute (User) on depth 0 completed in 8.7157 ms.
Analysis of models.core.user_attribute (User) on depth 0 completed in 7.742 ms.
Analysis of models.core.pending_users (User) on depth 0 completed in 0.6749 ms.
Analysis of models.core.ssh_resource_script (User) on depth 0 completed in 3.9944 ms.
Analysis of models.core.cim_credential (User) on depth 0 completed in 5.6261 ms.
Analysis of models.core.scoreboard (User) on depth 0 completed in 3.5683 ms.
Analysis of models.core.sales_commission (User) on depth 0 completed in 7.6243 ms.
Analysis of models.core.metric_category (User) on depth 0 completed in 16.0362 ms.
Analysis of models.core.connections (User) on depth 0 completed in 0.8853 ms.
Analysis of models.core.widget_queue_summary (User) on depth 0 completed in 0.959 ms.
Analysis of models.core.monitornode (User) on depth 0 completed in 38.3346 ms.
Analysis of models.core.blacklist (User) on depth 0 completed in 5.5777 ms.
Analysis of models.core.kpi (User) on depth 0 completed in 6.2948 ms.
Analysis of models.core.feature_highlight (User) on depth 0 completed in 7.3039 ms.
Analysis of models.core.network_service_discovery (User) on depth 0 completed in 10.5252 ms.
Analysis of models.core.appconfig (User) on depth 0 completed in 3.9946 ms.
Analysis of models.core.custom_incident_filter (User) on depth 0 completed in 24.1092 ms.
Analysis of models.core.snmp_traps (User) on depth 0 completed in 24.7003 ms.
Analysis of models.core.snmp_port_discovery (User) on depth 0 completed in 27.1098 ms.
Analysis of models.core.onprem_connect (User) on depth 0 completed in 27.4449 ms.
Analysis of models.core.copy_template (User) on depth 0 completed in 11.2902 ms.
Analysis of models.core.infra_map (User) on depth 0 completed in 3.1438 ms.
Analysis of models.core.global_announcement (User) on depth 0 completed in 14.9955 ms.
Analysis of models.core.sentry (User) on depth 0 completed in 19.219 ms.
Analysis of models.core.vmware (User) on depth 0 completed in 4.9989 ms.
Analysis of models.core.cloud_azure (User) on depth 0 completed in 72.1949 ms.
Analysis of models.core.monitoring_policy (User) on depth 0 completed in 10.8237 ms.
Analysis of models.core.email_lists (User) on depth 0 completed in 22.58 ms.
Analysis of models.tsdb.tsdb_base (User) on depth 0 completed in 2.979 ms.
Analysis of models.core.countermeasures (User) on depth 0 completed in 26.5076 ms.
Analysis of models.core.invoice (User) on depth 0 completed in 60.1888 ms.
Analysis of models.core.filters (User) on depth 0 completed in 13.2104 ms.
Analysis of tasks.ops (User) on depth 0 completed in 19.086 ms.
Analysis of models.monitoring_policy.ruleset_evaluator (User) on depth 0 completed in 2.577 ms.
Analysis of models.core.widget_queue (User) on depth 0 completed in 4.2491 ms.
Analysis of models.monitoring_policy.policy_evaluator (User) on depth 0 completed in 11.53 ms.
Analysis of models.core.saml_idp (User) on depth 0 completed in 14.6498 ms.
Analysis of models.core.availability (User) on depth 0 completed in 24.4939 ms.
Analysis of models.core.maintenance (User) on depth 0 completed in 46.3375 ms.
Analysis of models.tsdb.tsdb_mysql (User) on depth 0 completed in 51.4913 ms.
Analysis of models.tsdb (User) on depth 0 completed in 0.4065 ms.
Analysis of tasks.celeryapp (User) on depth 0 completed in 6.4951 ms.
Analysis of tasks.monitoring_policy (User) on depth 0 completed in 0.9924 ms.
Analysis of tasks.cloud (User) on depth 0 completed in 6.5113 ms.
Analysis of models.core.widget (User) on depth 0 completed in 71.8702 ms.
Analysis of models.core.dashboard (User) on depth 0 completed in 8.8477 ms.
Analysis of models.core.order (User) on depth 0 completed in 10.4304 ms.
Analysis of models.core.server (User) on depth 0 completed in 464.5628 ms.
Analysis of models.core.cloud (User) on depth 0 completed in 41.9325 ms.
Analysis of models.core.api_calls_counter (User) on depth 0 completed in 2.6271 ms.
Analysis of models.core.cloud_gcp (User) on depth 0 completed in 9.6257 ms.
Analysis of models.core.maintenance_period (User) on depth 0 completed in 56.6216 ms.
Analysis of models.core.cloud_aws (User) on depth 0 completed in 106.7908 ms.
Analysis complete: 64 modules in 3934.1659 ms.
Analysis version 5782 of 128 entries has been completed in 3928.1441 ms.

[AlexanderSher]

How big is models.masterdb?

[CMLL]

Pretty big, 21,000 lines. And also imports from another >20 files in core.

Edit:
I just got this notification when working while one of the burst analysis got stuck. I've seen they happen before but they are rare, I usually reload the window before they happen and the analysis gets restarted. Usually the ram usage of the LS stays pretty stable.

[MikhailArkhipov]

Analysis only looks at modified files. Files analyzed previously are not re-processed - unless

• some of the open files depend on the changed one (closed files are not relevant).
• there are circular dependencies in which case yes, they can be re-analyzed.

[CMLL]

Thanks @MikhailArkhipov I think I may be hitting the second case of the 2 you mention. I went to a test file that depends masterdb and adding a empty line triggers an analysis of only that file.

Analysis of tests.unit.notifyengine3.test_notifications(User) queued
Analysis version 5680 of 1 entries has started.
Analysis of tests.unit.notifyengine3.test_notifications (User) on depth 0 completed in 1.9614 ms.
Analysis version 5680 of 1 entries has been completed in 2.1542 ms.
Analysis of tests.unit.notifyengine3.test_notifications(User) queued
Analysis version 5681 of 1 entries has started.
Analysis of tests.unit.notifyengine3.test_notifications (User) on depth 0 completed in 2.3661 ms.
Analysis version 5681 of 1 entries has been completed in 2.5529 ms.

But when I add a line in another file that also imports masterdb I get the big analysis I mentioned previously. Is that circular dependency analysis an expected outcome or is a bug/side effect? I did both tests with the masterdb file opened and closed.

[MikhailArkhipov]

masterdb can be opened or closed, does not matter. If you have file A opened and it imports B, B will be loaded regardless. Now, if A imports B and C imports B, and nothing in the open files tree of dependencies depends on C, C won't be analyzed unless it is opened.

Log above looks like circular dependencies. tests.unit.notifyengine3.test_notifications (User) is processed twice and that typically means something similar to "A imports B and B imports A" in which case single pass cannot figure out types so it has to go around twice. If three modules are involved in loops, there may be three passes. And so on.

Static analysis, as opposed to an interpreter, does not have luxury of ignoring circular dependencies until they are actually executed...

[CMLL]

The 3 lines of test_notifications (User) was actually each a single new empty line I added to the file, each change triggered a new analysis, but it didn't went over the to the masterdb as other files, which yes, leads me to believe that there is a circular one existing between those files and masterdb, since both them and test_notifications use masterdb but only some of them triggers an analysis of masterdb.

[bluebrown]

I see issue after issue getting closed and really defensive replied by the maintainer. On top of that this annoying survey pops up all the time. Sometimes I want to install this extension again just do the survey so that I can down rate it.

You are also asking about reproducible steps. Well, this one was on a fresh windows 10 install.
Its a corporate project so I cannot share the code. However, below you will find the pipefile. Yes I am using pipenv.

step 1. Fresh windows 10
step 2. pull project and run pipenv install
step 3. open vscode/any file.py and see it getting stuck analyzing 1800 items within 5 minutes.

` Pipfile
[[source]]
name = "pypi"
url = "https://pypi.org/simple"
verify_ssl = true

[dev-packages]
autopep8 = ""
pylint = ""

[packages]
asyncio = "==3.4.3"
pyodbc = "==4.0.27"
aioodbc = "==0.0.1"
aiohttp = "==3.5.4"
aiohttp-cors = ""
python-enginio = {git = "https://github.com/miguelgrinberg/python-engineio/",ref = "master"}
python-socketio = "==4.3"
aiolog = "==0.0.2"
aiocache = "==0.11.1"
msgpack = "==0.6.1"
pandas = "==0.25.0"
sqlalchemy = "==1.3.6"
pytest = ""
pytest-asyncio = "*"
requests = "==2.22.0"

[requires]
python_version = "3.7"
`

[CMLL]

I don't agree with your comment about they closing down issues and being defensive about issues, at least that's not my experience with the handful of issues I've opened. Static analysis is a pretty complicated problem to tackle and getting it work right requires a non trivial amount of work. And also this is a very much in development project, not close to public release so rough edges are expected.

That said, is your issue similar to the one I'm having? From your step 3, doesn't seem to be the case.

[bluebrown]

Ok, I am not quite sure if it's the same issue. At first glance it seemed related and I encountered already a few closed issues on "my issue". Sorry If this is wrong here, I get that its for free and actual its works pretty well, but this memory leak, related to background analysis, makes it unusable. In fact, it makes vscode for python a bit useless as there is no good alternative as it seems. I would go and fix it, but I am too weak.

[MikhailArkhipov]

Issues may or may not be related, but it is always better to open separate one. Otherwise fix for one issue may close the thread with several different issues. Different cases may be assigned to different people in different milestones depending on the schedule. If cases happen to be deemed the same, we'll duplicate one against the other.