Skip to content
This repository was archived by the owner on Apr 14, 2022. It is now read-only.

Add test generation script #436

Merged
merged 5 commits into from
Dec 4, 2018
Merged

Conversation

jakebailey
Copy link
Member

Closes #334.

The generated code uses a static class to share a server between tests (as every test is read-only). The >1200 tests run in just 16 seconds, as compared to spinning up a server per-test which makes the suite take over 30 minutes.

In order to simulate editor behavior, the test cases will filter the results from their completion results to limit them to entries which contain the preceding token. For example, completing after hello.wor will only use entries with insertText that contain wor, just like VSC.

Some tests may appear to be flaky at first glance. However, it's not due to the inter-test sharing of a server, but due to what seems to be actual race conditions in our analysis we should investigate or otherwise solve via the rewrite.

The script will infer the input/output location based on its location (src), so as long as the TestData is populated, it'll do the rest.

Formatted using black.

@AlexanderSher
Copy link
Contributor

Having all tests use one and the same instance of server will create a dependency between tests. Not a bad thing by itself (users run chunks of code), but since test running order isn't guaranteed, it would be a huge problem to track those issues. Why server initialization takes so much time?

@jakebailey
Copy link
Member Author

I'm not generating these tests so that we can generate them once and keep using them. They're more for sanity checks and comparison, such that someone can generate them, run the tests, and inspect them for possible bugs to report (see everything that links to #334). Honestly, I think it's valuable for these sorts of tests to not be deterministic, because it shows that we have problems with ordering affecting tests.

Creating a server per tests takes about a second. If I look at a test's log after running a single test (so one user), I see:

Debug Trace:
testhost Information: 0 : [00:00:00.1170548]: Created Microsoft.PythonTools.Interpreter.Ast.AstPythonInterpreter instance from Microsoft.PythonTools.Interpreter.Ast.AstPythonInterpreterFactory
testhost Information: 0 : [00:00:01.2513780] LOG: Opening document file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py
testhost Information: 0 : [00:00:01.2898612] LOG: Parsing document file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py
testhost Information: 0 : [00:00:01.3232392] LOG: Parse complete for file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py at version 0
testhost Information: 0 : [00:00:01.3239323] LOG: Analysis queued for file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py
testhost Information: 0 : [00:00:01.3289833] LOG: Waiting for parsing to complete.
testhost Information: 0 : [00:00:01.3295694] LOG: Parsing complete. Waiting for analysis entries to enqueue.
testhost Information: 0 : [00:00:01.3296705] LOG: Enqueue complete. Waiting for analysis to complete.
testhost Information: 0 : [00:00:01.4154594] LOG: Received new analysis for file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py
testhost Information: 0 : [00:00:01.4158216] LOG: Analysis complete for file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py at version 0
testhost Information: 0 : [00:00:01.4293316] LOG:  Waiting for analysis of file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py to complete.
testhost Information: 0 : [00:00:01.4304825] LOG: Analysis complete.
testhost Information: 0 : [00:00:01.4333158] LOG: Completions in file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py at (14, 23)
testhost Information: 0 : [00:00:01.4446124] LOG: No completions at (14, 23) in file:///C:/Users/jabaile/python-language-server/src/UnitTests/TestData/gen/completion/context.py

You can see that there's more than a second until the document actually gets opened. As for "why" it's slow, I have no idea other than to say that starting the server is generally slow. All of our tests are slow like this. I don't have a way to profile tests because we're using netcore.

@AlexanderSher
Copy link
Contributor

As for "why" it's slow, I have no idea other than to say that starting the server is generally slow

Single test can be slow because it creates a cache for modules, but the remaining tests should use that cache and run faster. What do you see in logs when several tests are executed?

@MikhailArkhipov
Copy link

Each time server starts it a) loads builtin types and b) inspects cache and libraries for scraping

@AlexanderSher
Copy link
Contributor

Ok, but if we have that data in cache, shouldn't we just load it instead of scraping those libraries again?

@MikhailArkhipov
Copy link

Yes, but all this takes time. builtins is a big module compared to a small amount of code in the test...

@jakebailey
Copy link
Member Author

I modified things to have every test spawn its own server, and each test takes anywhere between ~500 ms and 1 second, as compared to the first test taking 1 second and all subsequent tests taking a handful of milliseconds. All of the logs look the same as what I copied above, just with varying times until the document is opened.

@AlexanderSher
Copy link
Contributor

This isn't right. Loading from cache should be much faster. It looks like we either ignore cache in tests or can't find it.

@MikhailArkhipov
Copy link

No, I mean loading builtins as in LoadKnownTypesAsync

@AlexanderSher
Copy link
Contributor

I've found an interesting thing: https://github.com/Microsoft/python-language-server/blob/af7773157b4870fbd05babb144c6c2cfa3ce5bbb/src/Analysis/Engine/Impl/Interpreter/Ast/AstPythonInterpreterFactory.cs#L65:
CreationOptions.UseExistingCache is negated, which makes AstModuleCache.ReadCachedModule return null. @jakebailey , can you try to remove negation?

@jakebailey
Copy link
Member Author

For one specific test group (with one server per test), doing that lowers the test time from 1:23 to 0:55. In general, instead of a test taking anywhere from 500ms to a second, it's more like 250ms to a second.

Of course, this is nowhere near as fast as me just making the one server and reusing it, because everything happens exactly once and completion/hover is a fast call inward.

@AlexanderSher
Copy link
Contributor

Ok, what takes most of those 250ms is ModulePath.GetModulesInPath. With that list of modules in python directory cached, CreateAnalyzer takes less than 60 ms on my machine.

@jakebailey
Copy link
Member Author

What's the right path forward on this? I can see that with the new import system, the code @AlexanderSher mentioned was moved and is no longer negated, so I should be able to have cached data.

However, making one server per test is still as slow as it was the first time around. For ArraysTests, it's 1:37 to run all 114 tests each with their own server, but just 2 seconds when sharing.

I still think it's okay in this specific instance to share a server between tests. I'm not expecting to ever pass every test in this suite anyway, and a person is going to have to manually look at the results to generate minimal examples regardless, so I'd rather them need to wait double digit seconds instead of double digit minutes.

@MikhailArkhipov
Copy link

I think it is OK for now. Let's file a work item to review this and address if there are indeed issues.

@jakebailey jakebailey merged commit 47b8c7d into microsoft:master Dec 4, 2018
@jakebailey jakebailey deleted the test-gen branch February 14, 2019 20:22
jakebailey added a commit to jakebailey/python-language-server that referenced this pull request Nov 1, 2019
* add test generation script

* remove unused imports

* use SemaphoreSlim and async func instead of lock and Task.Run
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants