From 24cd043ac318a6943ddbde1352035c350b0be335 Mon Sep 17 00:00:00 2001 From: HeeJae Chang Date: Thu, 25 Jun 2020 15:56:00 -0700 Subject: [PATCH] added more logging and fixed hover bug --- client/package-lock.json | 267 +------------ client/package.json | 8 +- server/src/analyzer/program.ts | 110 ++--- server/src/analyzer/sourceFile.ts | 376 +++++++++--------- server/src/analyzer/typeEvaluator.ts | 3 +- server/src/common/logTracker.ts | 89 +++++ server/src/tests/deferred.test.ts | 54 +++ .../tests/fourslash/hover.import.fourslash.ts | 11 + .../src/tests/harness/fourslash/testState.ts | 3 +- 9 files changed, 422 insertions(+), 499 deletions(-) create mode 100644 server/src/common/logTracker.ts create mode 100644 server/src/tests/deferred.test.ts create mode 100644 server/src/tests/fourslash/hover.import.fourslash.ts diff --git a/client/package-lock.json b/client/package-lock.json index 493d852794f6..844a02160900 100644 --- a/client/package-lock.json +++ b/client/package-lock.json @@ -4,26 +4,17 @@ "lockfileVersion": 1, "requires": true, "dependencies": { - "@tootallnate/once": { - "version": "1.1.2", - "resolved": "https://registry.npmjs.org/@tootallnate/once/-/once-1.1.2.tgz", - "integrity": "sha512-RbzJvlNzmRq5c3O09UipeuXno4tA1FE6ikOjxZK0tuxVv3412l64l5t1W5pj4+rJq9vpkm/kwiR07aZXnsKPxw==", - "dev": true - }, "@types/node": { "version": "14.0.13", "resolved": "https://registry.npmjs.org/@types/node/-/node-14.0.13.tgz", "integrity": "sha512-rouEWBImiRaSJsVA+ITTFM6ZxibuAlTuNOCyxVbwreu6k6+ujs7DfnU9o+PShFhET78pMBl3eH+AGSI5eOTkPA==", "dev": true }, - "agent-base": { - "version": "6.0.0", - "resolved": "https://registry.npmjs.org/agent-base/-/agent-base-6.0.0.tgz", - "integrity": "sha512-j1Q7cSCqN+AwrmDd+pzgqc0/NpC655x2bUf5ZjRIO77DcNBFmh+OgRNzF6OKdCC9RSCb19fGd99+bhXFdkRNqw==", - "dev": true, - "requires": { - "debug": "4" - } + "@types/vscode": { + "version": "1.46.0", + "resolved": "https://registry.npmjs.org/@types/vscode/-/vscode-1.46.0.tgz", + "integrity": "sha512-8m9wPEB2mcRqTWNKs9A9Eqs8DrQZt0qNFO8GkxBOnyW6xR//3s77SoMgb/nY1ctzACsZXwZj3YRTDsn4bAoaUw==", + "dev": true }, "ansi-styles": { "version": "3.2.1", @@ -77,24 +68,12 @@ "concat-map": "0.0.1" } }, - "browser-stdout": { - "version": "1.3.1", - "resolved": "https://registry.npmjs.org/browser-stdout/-/browser-stdout-1.3.1.tgz", - "integrity": "sha512-qhAVI1+Av2X7qelOfAIYwXONood6XlZE/fXaBSmW/T5SzLAmCgzi+eiWE7fUvbHaeNBQH13UftjpXxsfLkMpgw==", - "dev": true - }, "buffer-crc32": { "version": "0.2.13", "resolved": "https://registry.npmjs.org/buffer-crc32/-/buffer-crc32-0.2.13.tgz", "integrity": "sha1-DTM+PwDqxQqhRUq9MO+MKl2ackI=", "dev": true }, - "buffer-from": { - "version": "1.1.1", - "resolved": "https://registry.npmjs.org/buffer-from/-/buffer-from-1.1.1.tgz", - "integrity": "sha512-MQcXEUbCKtEo7bhqEs6560Hyd4XaovZlO/k9V3hjVUF/zwW7KBVdSK4gIt/bzwS9MbR5qob+F5jusZsb0YQK2A==", - "dev": true - }, "chalk": { "version": "2.4.2", "resolved": "https://registry.npmjs.org/chalk/-/chalk-2.4.2.tgz", @@ -165,27 +144,12 @@ "integrity": "sha512-a+EPoD+uZiNfh+5fxw2nO9QwFa6nJe2Or35fGY6Ipw1R3R4AGz1d1TEZrCegvw2YTmZ0jXirGYlzxxpYSHwpEg==", "dev": true }, - "debug": { - "version": "4.1.1", - "resolved": "https://registry.npmjs.org/debug/-/debug-4.1.1.tgz", - "integrity": "sha512-pYAIzeRo8J6KPEaJ0VWOh5Pzkbw/RetuzehGM7QRRX5he4fPHx2rdKMB256ehJCkX+XRQm16eZLqLNS8RSZXZw==", - "dev": true, - "requires": { - "ms": "^2.1.1" - } - }, "denodeify": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/denodeify/-/denodeify-1.2.1.tgz", "integrity": "sha1-OjYof1A05pnnV3kBBSwubJQlFjE=", "dev": true }, - "diff": { - "version": "3.5.0", - "resolved": "https://registry.npmjs.org/diff/-/diff-3.5.0.tgz", - "integrity": "sha512-A46qtFgd+g7pDZinpnwiRJtxbC1hpgf0uzP3iG89scHk0AUC7A1TGxf5OiiOUv/JMZR8GOt8hL900hV0bOy5xA==", - "dev": true - }, "dom-serializer": { "version": "0.1.1", "resolved": "https://registry.npmjs.org/dom-serializer/-/dom-serializer-0.1.1.tgz", @@ -227,21 +191,6 @@ "integrity": "sha512-f2LZMYl1Fzu7YSBKg+RoROelpOaNrcGmE9AZubeDfrCEia483oW4MI4VyFd5VNHIgQ/7qm1I0wUHK1eJnn2y2w==", "dev": true }, - "es6-promise": { - "version": "4.2.8", - "resolved": "https://registry.npmjs.org/es6-promise/-/es6-promise-4.2.8.tgz", - "integrity": "sha512-HJDGx5daxeIvxdBxvG2cb9g4tEvwIk3i8+nhX0yGrYmZUzbkdg8QbDevheDB8gd0//uPj4c1EQua8Q+MViT0/w==", - "dev": true - }, - "es6-promisify": { - "version": "5.0.0", - "resolved": "https://registry.npmjs.org/es6-promisify/-/es6-promisify-5.0.0.tgz", - "integrity": "sha1-UQnWLz5W6pZ8S2NQWu8IKRyKUgM=", - "dev": true, - "requires": { - "es6-promise": "^4.0.3" - } - }, "escape-string-regexp": { "version": "1.0.5", "resolved": "https://registry.npmjs.org/escape-string-regexp/-/escape-string-regexp-1.0.5.tgz", @@ -277,24 +226,12 @@ "path-is-absolute": "^1.0.0" } }, - "growl": { - "version": "1.10.5", - "resolved": "https://registry.npmjs.org/growl/-/growl-1.10.5.tgz", - "integrity": "sha512-qBr4OuELkhPenW6goKVXiv47US3clb3/IbuWF9KNKEijAy9oeHxU9IgzjvJhHkUzhaj7rOUD7+YGWqUjLp5oSA==", - "dev": true - }, "has-flag": { "version": "3.0.0", "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-3.0.0.tgz", "integrity": "sha1-tdRU3CGZriJWmfNGfloH87lVuv0=", "dev": true }, - "he": { - "version": "1.1.1", - "resolved": "https://registry.npmjs.org/he/-/he-1.1.1.tgz", - "integrity": "sha1-k0EP0hsAlzUVH4howvJx80J+I/0=", - "dev": true - }, "htmlparser2": { "version": "3.10.1", "resolved": "https://registry.npmjs.org/htmlparser2/-/htmlparser2-3.10.1.tgz", @@ -309,27 +246,6 @@ "readable-stream": "^3.1.1" } }, - "http-proxy-agent": { - "version": "4.0.1", - "resolved": "https://registry.npmjs.org/http-proxy-agent/-/http-proxy-agent-4.0.1.tgz", - "integrity": "sha512-k0zdNgqWTGA6aeIRVpvfVob4fL52dTfaehylg0Y4UvSySvOq/Y+BOyPrgpUrA7HylqvU8vIZGsRuXmspskV0Tg==", - "dev": true, - "requires": { - "@tootallnate/once": "1", - "agent-base": "6", - "debug": "4" - } - }, - "https-proxy-agent": { - "version": "5.0.0", - "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-5.0.0.tgz", - "integrity": "sha512-EkYm5BcKUGiduxzSt3Eppko+PiNWNEpa4ySk9vTC6wDsQJW9rHSa+UhGNJoRYp7bz6Ht1eaRIa6QaJqO5rCFbA==", - "dev": true, - "requires": { - "agent-base": "6", - "debug": "4" - } - }, "inflight": { "version": "1.0.6", "resolved": "https://registry.npmjs.org/inflight/-/inflight-1.0.6.tgz", @@ -408,92 +324,6 @@ "brace-expansion": "^1.1.7" } }, - "minimist": { - "version": "0.0.8", - "resolved": "https://registry.npmjs.org/minimist/-/minimist-0.0.8.tgz", - "integrity": "sha1-hX/Kv8M5fSYluCKCYuhqp6ARsF0=", - "dev": true - }, - "mkdirp": { - "version": "0.5.1", - "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-0.5.1.tgz", - "integrity": "sha1-MAV0OOrGz3+MR2fzhkjWaX11yQM=", - "dev": true, - "requires": { - "minimist": "0.0.8" - } - }, - "mocha": { - "version": "5.2.0", - "resolved": "https://registry.npmjs.org/mocha/-/mocha-5.2.0.tgz", - "integrity": "sha512-2IUgKDhc3J7Uug+FxMXuqIyYzH7gJjXECKe/w43IGgQHTSj3InJi+yAA7T24L9bQMRKiUEHxEX37G5JpVUGLcQ==", - "dev": true, - "requires": { - "browser-stdout": "1.3.1", - "commander": "2.15.1", - "debug": "3.1.0", - "diff": "3.5.0", - "escape-string-regexp": "1.0.5", - "glob": "7.1.2", - "growl": "1.10.5", - "he": "1.1.1", - "minimatch": "3.0.4", - "mkdirp": "0.5.1", - "supports-color": "5.4.0" - }, - "dependencies": { - "commander": { - "version": "2.15.1", - "resolved": "https://registry.npmjs.org/commander/-/commander-2.15.1.tgz", - "integrity": "sha512-VlfT9F3V0v+jr4yxPc5gg9s62/fIVWsd2Bk2iD435um1NlGMYdVCq+MjcXnhYq2icNOizHr1kK+5TI6H0Hy0ag==", - "dev": true - }, - "debug": { - "version": "3.1.0", - "resolved": "https://registry.npmjs.org/debug/-/debug-3.1.0.tgz", - "integrity": "sha512-OX8XqP7/1a9cqkxYw2yXss15f26NKWBpDXQd0/uK/KPqdQhxbPa994hnzjcE2VqQpDslf55723cKPUOGSmMY3g==", - "dev": true, - "requires": { - "ms": "2.0.0" - } - }, - "glob": { - "version": "7.1.2", - "resolved": "https://registry.npmjs.org/glob/-/glob-7.1.2.tgz", - "integrity": "sha512-MJTUg1kjuLeQCJ+ccE4Vpa6kKVXkPYJ2mOCQyUuKLcLQsdrMCpBPUi8qVE6+YuaJkozeA9NusTAw3hLr8Xe5EQ==", - "dev": true, - "requires": { - "fs.realpath": "^1.0.0", - "inflight": "^1.0.4", - "inherits": "2", - "minimatch": "^3.0.4", - "once": "^1.3.0", - "path-is-absolute": "^1.0.0" - } - }, - "ms": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", - "integrity": "sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g=", - "dev": true - }, - "supports-color": { - "version": "5.4.0", - "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-5.4.0.tgz", - "integrity": "sha512-zjaXglF5nnWpsq470jSv6P9DwPvgLkuapYmfDm3JWOm0vkNTVF2tI4UrN2r6jH1qM/uc/WtxYY1hYoA2dOKj5w==", - "dev": true, - "requires": { - "has-flag": "^3.0.0" - } - } - } - }, - "ms": { - "version": "2.1.2", - "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz", - "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==", - "dev": true - }, "mute-stream": { "version": "0.0.8", "resolved": "https://registry.npmjs.org/mute-stream/-/mute-stream-0.0.8.tgz", @@ -608,22 +438,6 @@ "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==", "dev": true }, - "source-map": { - "version": "0.6.1", - "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", - "integrity": "sha512-UjgapumWlbMhkBgzT7Ykc5YXUT46F0iKu8SGXq0bcwP5dz/h0Plj6enJqjz1Zbq2l5WaqYnrVbwWOWMyF3F47g==", - "dev": true - }, - "source-map-support": { - "version": "0.5.19", - "resolved": "https://registry.npmjs.org/source-map-support/-/source-map-support-0.5.19.tgz", - "integrity": "sha512-Wonm7zOCIJzBGQdB+thsPar0kYuCIzYvxZwlBa87yi/Mdjv7Tip2cyVbLj5o0cFPN4EVkuTwb3GDDyUx2DGnGw==", - "dev": true, - "requires": { - "buffer-from": "^1.0.0", - "source-map": "^0.6.0" - } - }, "sprintf-js": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", @@ -731,21 +545,6 @@ "yazl": "^2.2.2" } }, - "vscode": { - "version": "1.1.37", - "resolved": "https://registry.npmjs.org/vscode/-/vscode-1.1.37.tgz", - "integrity": "sha512-vJNj6IlN7IJPdMavlQa1KoFB3Ihn06q1AiN3ZFI/HfzPNzbKZWPPuiU+XkpNOfGU5k15m4r80nxNPlM7wcc0wg==", - "dev": true, - "requires": { - "glob": "^7.1.2", - "http-proxy-agent": "^4.0.1", - "https-proxy-agent": "^5.0.0", - "mocha": "^5.2.0", - "semver": "^5.4.1", - "source-map-support": "^0.5.0", - "vscode-test": "^0.4.1" - } - }, "vscode-jsonrpc": { "version": "6.0.0-next.3", "resolved": "https://registry.npmjs.org/vscode-jsonrpc/-/vscode-jsonrpc-6.0.0-next.3.tgz", @@ -803,62 +602,6 @@ "resolved": "https://registry.npmjs.org/vscode-languageserver-types/-/vscode-languageserver-types-3.16.0-next.2.tgz", "integrity": "sha512-QjXB7CKIfFzKbiCJC4OWC8xUncLsxo19FzGVp/ADFvvi87PlmBSCAtZI5xwGjF5qE0xkLf0jjKUn3DzmpDP52Q==" }, - "vscode-test": { - "version": "0.4.3", - "resolved": "https://registry.npmjs.org/vscode-test/-/vscode-test-0.4.3.tgz", - "integrity": "sha512-EkMGqBSefZH2MgW65nY05rdRSko15uvzq4VAPM5jVmwYuFQKE7eikKXNJDRxL+OITXHB6pI+a3XqqD32Y3KC5w==", - "dev": true, - "requires": { - "http-proxy-agent": "^2.1.0", - "https-proxy-agent": "^2.2.1" - }, - "dependencies": { - "agent-base": { - "version": "4.3.0", - "resolved": "https://registry.npmjs.org/agent-base/-/agent-base-4.3.0.tgz", - "integrity": "sha512-salcGninV0nPrwpGNn4VTXBb1SOuXQBiqbrNXoeizJsHrsL6ERFM2Ne3JUSBWRE6aeNJI2ROP/WEEIDUiDe3cg==", - "dev": true, - "requires": { - "es6-promisify": "^5.0.0" - } - }, - "debug": { - "version": "3.1.0", - "resolved": "https://registry.npmjs.org/debug/-/debug-3.1.0.tgz", - "integrity": "sha512-OX8XqP7/1a9cqkxYw2yXss15f26NKWBpDXQd0/uK/KPqdQhxbPa994hnzjcE2VqQpDslf55723cKPUOGSmMY3g==", - "dev": true, - "requires": { - "ms": "2.0.0" - } - }, - "http-proxy-agent": { - "version": "2.1.0", - "resolved": "https://registry.npmjs.org/http-proxy-agent/-/http-proxy-agent-2.1.0.tgz", - "integrity": "sha512-qwHbBLV7WviBl0rQsOzH6o5lwyOIvwp/BdFnvVxXORldu5TmjFfjzBcWUWS5kWAZhmv+JtiDhSuQCp4sBfbIgg==", - "dev": true, - "requires": { - "agent-base": "4", - "debug": "3.1.0" - } - }, - "https-proxy-agent": { - "version": "2.2.4", - "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-2.2.4.tgz", - "integrity": "sha512-OmvfoQ53WLjtA9HeYP9RNrWMJzzAz1JGaSFr1nijg0PVR1JaD/xbJq1mdEIIlxGpXp9eSe/O2LgU9DJmTPd0Eg==", - "dev": true, - "requires": { - "agent-base": "^4.3.0", - "debug": "^3.1.0" - } - }, - "ms": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", - "integrity": "sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g=", - "dev": true - } - } - }, "vscode-uri": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/vscode-uri/-/vscode-uri-2.1.2.tgz", diff --git a/client/package.json b/client/package.json index 493d63bfe06e..ed89189e1a2d 100644 --- a/client/package.json +++ b/client/package.json @@ -169,14 +169,12 @@ }, "scripts": { "vscode:prepublish": "npm run build", - "build": "tsc -p ./", - "update-vscode": "node ./node_modules/vscode/bin/install", - "postinstall": "node ./node_modules/vscode/bin/install" + "build": "tsc -p ./" }, "devDependencies": { + "@types/vscode": "^1.46.0", "typescript": "^3.9.5", - "vsce": "^1.77.0", - "vscode": "^1.1.37" + "vsce": "^1.77.0" }, "dependencies": { "leven": "^3.1.0", diff --git a/server/src/analyzer/program.ts b/server/src/analyzer/program.ts index ab6d6513cf41..f9303ca614ff 100644 --- a/server/src/analyzer/program.ts +++ b/server/src/analyzer/program.ts @@ -16,6 +16,7 @@ import { SymbolInformation, } from 'vscode-languageserver'; import { CallHierarchyIncomingCall, CallHierarchyItem, CallHierarchyOutgoingCall } from 'vscode-languageserver-types'; +import { isMainThread } from 'worker_threads'; import { OperationCanceledException, throwIfCancellationRequested } from '../common/cancellationUtils'; import { ConfigOptions, ExecutionEnvironment } from '../common/configOptions'; @@ -26,6 +27,7 @@ import { Diagnostic } from '../common/diagnostic'; import { FileDiagnostics } from '../common/diagnosticSink'; import { FileEditAction, TextEditAction } from '../common/editAction'; import { LanguageServiceExtension } from '../common/extensibility'; +import { LogTracker } from '../common/logTracker'; import { combinePaths, getDirectoryPath, @@ -118,6 +120,7 @@ export class Program { private _evaluator: TypeEvaluator; private _configOptions: ConfigOptions; private _importResolver: ImportResolver; + private _logTracker: LogTracker; constructor( initialImportResolver: ImportResolver, @@ -126,6 +129,7 @@ export class Program { private _extension?: LanguageServiceExtension ) { this._console = console || new StandardConsole(); + this._logTracker = new LogTracker(console, isMainThread ? 'FG' : 'BG'); this._importResolver = initialImportResolver; this._configOptions = initialConfigOptions; this._createNewEvaluator(); @@ -189,7 +193,7 @@ export class Program { return sourceFileInfo.sourceFile; } - const sourceFile = new SourceFile(this._fs, filePath, false, this._console); + const sourceFile = new SourceFile(this._fs, filePath, false, this._console, this._logTracker); sourceFileInfo = { sourceFile, isTracked: true, @@ -209,7 +213,7 @@ export class Program { setFileOpened(filePath: string, version: number | null, contents: string) { let sourceFileInfo = this._sourceFileMap.get(filePath); if (!sourceFileInfo) { - const sourceFile = new SourceFile(this._fs, filePath, false, this._console); + const sourceFile = new SourceFile(this._fs, filePath, false, this._console, this._logTracker); sourceFileInfo = { sourceFile, isTracked: false, @@ -524,7 +528,7 @@ export class Program { return sourceFileInfo.sourceFile; } - const sourceFile = new SourceFile(this._fs, filePath, false, this._console); + const sourceFile = new SourceFile(this._fs, filePath, false, this._console, this._logTracker); sourceFileInfo = { sourceFile, isTracked: true, @@ -549,7 +553,7 @@ export class Program { let shadowFileInfo = this._sourceFileMap.get(shadowImplPath); if (!shadowFileInfo) { - const sourceFile = new SourceFile(this._fs, shadowImplPath, false, this._console); + const sourceFile = new SourceFile(this._fs, shadowImplPath, false, this._console, this._logTracker); shadowFileInfo = { sourceFile, isTracked: false, @@ -679,62 +683,67 @@ export class Program { } private _checkTypes(fileToCheck: SourceFileInfo) { - // If the file isn't needed because it was eliminated from the - // transitive closure or deleted, skip the file rather than wasting - // time on it. - if (!this._isFileNeeded(fileToCheck)) { - return false; - } + return this._logTracker.log(`analyzing: ${fileToCheck.sourceFile.getFilePath()}`, (ls) => { + // If the file isn't needed because it was eliminated from the + // transitive closure or deleted, skip the file rather than wasting + // time on it. + if (!this._isFileNeeded(fileToCheck)) { + ls.add(`analysis not needed`); + return false; + } - if (!fileToCheck.sourceFile.isCheckingRequired()) { - return false; - } + if (!fileToCheck.sourceFile.isCheckingRequired()) { + ls.add(`cache hit`); + return false; + } - if (!this._shouldCheckFile(fileToCheck)) { - return false; - } + if (!this._shouldCheckFile(fileToCheck)) { + ls.add(`analysis not needed`); + return false; + } - this._bindFile(fileToCheck); + this._bindFile(fileToCheck); - // For very large programs, we may need to discard the evaluator and - // its cached types to avoid running out of heap space. - const typeCacheSize = this._evaluator.getTypeCacheSize(); + // For very large programs, we may need to discard the evaluator and + // its cached types to avoid running out of heap space. + const typeCacheSize = this._evaluator.getTypeCacheSize(); - // If the type cache size has exceeded a high-water mark, query the heap usage. - // Don't bother doing this until we hit this point because the heap usage may not - // drop immediately after we empty the cache due to garbage collection timing. - if (typeCacheSize > 750000) { - const heapSizeInMb = Math.round(process.memoryUsage().heapUsed / (1024 * 1024)); + // If the type cache size has exceeded a high-water mark, query the heap usage. + // Don't bother doing this until we hit this point because the heap usage may not + // drop immediately after we empty the cache due to garbage collection timing. + if (typeCacheSize > 750000) { + const heapSizeInMb = Math.round(process.memoryUsage().heapUsed / (1024 * 1024)); - // Don't allow the heap to get close to the 2GB limit imposed by - // the OS when running Node in a 32-bit process. - if (heapSizeInMb > 1536) { - this._console.info(`Emptying type cache to avoid heap overflow. Heap size used: ${heapSizeInMb}MB`); - this._createNewEvaluator(); + // Don't allow the heap to get close to the 2GB limit imposed by + // the OS when running Node in a 32-bit process. + if (heapSizeInMb > 1536) { + this._console.info(`Emptying type cache to avoid heap overflow. Heap size used: ${heapSizeInMb}MB`); + this._createNewEvaluator(); + } } - } - fileToCheck.sourceFile.check(this._evaluator); - - // Detect import cycles that involve the file. - if (this._configOptions.diagnosticRuleSet.reportImportCycles !== 'none') { - // Don't detect import cycles when doing type stub generation. Some - // third-party modules are pretty convoluted. - if (!this._allowedThirdPartyImports) { - // We need to force all of the files to be parsed and build - // a closure map for the files. - const closureMap = new Map(); - this._getImportsRecursive(fileToCheck, closureMap, 0); - - closureMap.forEach((file) => { - timingStats.cycleDetectionTime.timeOperation(() => { - this._detectAndReportImportCycles(file); + fileToCheck.sourceFile.check(this._evaluator); + + // Detect import cycles that involve the file. + if (this._configOptions.diagnosticRuleSet.reportImportCycles !== 'none') { + // Don't detect import cycles when doing type stub generation. Some + // third-party modules are pretty convoluted. + if (!this._allowedThirdPartyImports) { + // We need to force all of the files to be parsed and build + // a closure map for the files. + const closureMap = new Map(); + this._getImportsRecursive(fileToCheck, closureMap, 0); + + closureMap.forEach((file) => { + timingStats.cycleDetectionTime.timeOperation(() => { + this._detectAndReportImportCycles(file); + }); }); - }); + } } - } - return true; + return true; + }); } // Builds a map of files that includes the specified file and all of the files @@ -1686,7 +1695,8 @@ export class Program { this._fs, importPath, importInfo.isThirdPartyImport, - this._console + this._console, + this._logTracker ); importedFileInfo = { sourceFile, diff --git a/server/src/analyzer/sourceFile.ts b/server/src/analyzer/sourceFile.ts index e5774e16812c..ceff03fcad7b 100644 --- a/server/src/analyzer/sourceFile.ts +++ b/server/src/analyzer/sourceFile.ts @@ -14,6 +14,7 @@ import { DocumentSymbol, SymbolInformation, } from 'vscode-languageserver'; +import { isMainThread } from 'worker_threads'; import { OperationCanceledException } from '../common/cancellationUtils'; import { ConfigOptions, ExecutionEnvironment, getBasicDiagnosticRuleSet } from '../common/configOptions'; @@ -23,6 +24,7 @@ import { convertLevelToCategory, Diagnostic, DiagnosticCategory } from '../commo import { DiagnosticSink, TextRangeDiagnosticSink } from '../common/diagnosticSink'; import { TextEditAction } from '../common/editAction'; import { FileSystem } from '../common/fileSystem'; +import { LogTracker } from '../common/logTracker'; import { getFileName, normalizeSlashes } from '../common/pathUtils'; import * as StringUtils from '../common/stringUtils'; import { DocumentRange, getEmptyRange, Position, TextRange } from '../common/textRange'; @@ -144,9 +146,16 @@ export class SourceFile { private _typingModulePath?: string; private _collectionsModulePath?: string; + private _logTracker: LogTracker; readonly fileSystem: FileSystem; - constructor(fs: FileSystem, filePath: string, isThirdPartyImport: boolean, console?: ConsoleInterface) { + constructor( + fs: FileSystem, + filePath: string, + isThirdPartyImport: boolean, + console?: ConsoleInterface, + logTracker?: LogTracker + ) { this.fileSystem = fs; this._console = console || new StandardConsole(); this._filePath = filePath; @@ -170,6 +179,9 @@ export class SourceFile { this._isBuiltInStubFile = true; } } + + // 'FG' or 'BG' based on current thread. + this._logTracker = logTracker ?? new LogTracker(console, isMainThread ? 'FG' : 'BG'); } getFilePath(): string { @@ -433,113 +445,117 @@ export class SourceFile { // (or at least cancel) prior to calling again. It returns true if a parse // was required and false if the parse information was up to date already. parse(configOptions: ConfigOptions, importResolver: ImportResolver): boolean { - // If the file is already parsed, we can skip. - if (!this.isParseRequired()) { - return false; - } - - const diagSink = new DiagnosticSink(); - let fileContents = this._fileContents; - if (this._clientVersion === null) { - try { - timingStats.readFileTime.timeOperation(() => { - // Read the file's contents. - fileContents = this.fileSystem.readFileSync(this._filePath, 'utf8'); - - // Remember the length and hash for comparison purposes. - this._lastFileContentLength = fileContents.length; - this._lastFileContentHash = StringUtils.hashString(fileContents); - }); - } catch (error) { - diagSink.addError(`Source file could not be read`, getEmptyRange()); - fileContents = ''; + return this._logTracker.log(`parsing: ${this._filePath}`, (ls) => { + // If the file is already parsed, we can skip. + if (!this.isParseRequired()) { + ls.add(`cache hit`); + return false; + } - if (!this.fileSystem.existsSync(this._filePath)) { - this._isFileDeleted = true; + const diagSink = new DiagnosticSink(); + let fileContents = this._fileContents; + if (this._clientVersion === null) { + try { + timingStats.readFileTime.timeOperation(() => { + // Read the file's contents. + fileContents = this.fileSystem.readFileSync(this._filePath, 'utf8'); + + // Remember the length and hash for comparison purposes. + this._lastFileContentLength = fileContents.length; + this._lastFileContentHash = StringUtils.hashString(fileContents); + }); + } catch (error) { + diagSink.addError(`Source file could not be read`, getEmptyRange()); + fileContents = ''; + + if (!this.fileSystem.existsSync(this._filePath)) { + this._isFileDeleted = true; + } } } - } - // Use the configuration options to determine the environment in which - // this source file will be executed. - const execEnvironment = configOptions.findExecEnvironment(this._filePath); + // Use the configuration options to determine the environment in which + // this source file will be executed. + const execEnvironment = configOptions.findExecEnvironment(this._filePath); - const parseOptions = new ParseOptions(); - if (this._filePath.endsWith('pyi')) { - parseOptions.isStubFile = true; - } - parseOptions.pythonVersion = execEnvironment.pythonVersion; + const parseOptions = new ParseOptions(); + if (this._filePath.endsWith('pyi')) { + parseOptions.isStubFile = true; + } + parseOptions.pythonVersion = execEnvironment.pythonVersion; - try { - // Parse the token stream, building the abstract syntax tree. - const parser = new Parser(); - const parseResults = parser.parseSourceFile(fileContents!, parseOptions, diagSink); - assert(parseResults !== undefined && parseResults.tokenizerOutput !== undefined); - this._parseResults = parseResults; - - // Resolve imports. - timingStats.resolveImportsTime.timeOperation(() => { - [ - this._imports, - this._builtinsImport, - this._typingModulePath, - this._collectionsModulePath, - ] = this._resolveImports(importResolver, parseResults.importedModules, execEnvironment); - this._parseDiagnostics = diagSink.fetchAndClear(); - }); + try { + // Parse the token stream, building the abstract syntax tree. + const parser = new Parser(); + const parseResults = parser.parseSourceFile(fileContents!, parseOptions, diagSink); + assert(parseResults !== undefined && parseResults.tokenizerOutput !== undefined); + this._parseResults = parseResults; + + // Resolve imports. + timingStats.resolveImportsTime.timeOperation(() => { + [ + this._imports, + this._builtinsImport, + this._typingModulePath, + this._collectionsModulePath, + ] = this._resolveImports(importResolver, parseResults.importedModules, execEnvironment); + this._parseDiagnostics = diagSink.fetchAndClear(); + }); - // Is this file in a "strict" path? - const useStrict = - configOptions.strict.find((strictFileSpec) => strictFileSpec.regExp.test(this._filePath)) !== undefined; + // Is this file in a "strict" path? + const useStrict = + configOptions.strict.find((strictFileSpec) => strictFileSpec.regExp.test(this._filePath)) !== + undefined; - this._diagnosticRuleSet = CommentUtils.getFileLevelDirectives( - this._parseResults.tokenizerOutput.tokens, - configOptions.diagnosticRuleSet, - useStrict - ); - } catch (e) { - const message: string = - (e.stack ? e.stack.toString() : undefined) || - (typeof e.message === 'string' ? e.message : undefined) || - JSON.stringify(e); - this._console.error(`An internal error occurred while parsing ${this.getFilePath()}: ` + message); - - // Create dummy parse results. - this._parseResults = { - text: '', - parseTree: ModuleNode.create({ start: 0, length: 0 }), - importedModules: [], - futureImports: new Map(), - tokenizerOutput: { - tokens: new TextRangeCollection([]), - lines: new TextRangeCollection([]), - typeIgnoreAll: false, - typeIgnoreLines: {}, - predominantEndOfLineSequence: '\n', - predominantTabSequence: ' ', - predominantSingleQuoteCharacter: "'", - }, - containsWildcardImport: false, - }; - this._imports = undefined; - this._builtinsImport = undefined; + this._diagnosticRuleSet = CommentUtils.getFileLevelDirectives( + this._parseResults.tokenizerOutput.tokens, + configOptions.diagnosticRuleSet, + useStrict + ); + } catch (e) { + const message: string = + (e.stack ? e.stack.toString() : undefined) || + (typeof e.message === 'string' ? e.message : undefined) || + JSON.stringify(e); + this._console.error(`An internal error occurred while parsing ${this.getFilePath()}: ` + message); + + // Create dummy parse results. + this._parseResults = { + text: '', + parseTree: ModuleNode.create({ start: 0, length: 0 }), + importedModules: [], + futureImports: new Map(), + tokenizerOutput: { + tokens: new TextRangeCollection([]), + lines: new TextRangeCollection([]), + typeIgnoreAll: false, + typeIgnoreLines: {}, + predominantEndOfLineSequence: '\n', + predominantTabSequence: ' ', + predominantSingleQuoteCharacter: "'", + }, + containsWildcardImport: false, + }; + this._imports = undefined; + this._builtinsImport = undefined; - const diagSink = new DiagnosticSink(); - diagSink.addError(`An internal error occurred while parsing file`, getEmptyRange()); - this._parseDiagnostics = diagSink.fetchAndClear(); + const diagSink = new DiagnosticSink(); + diagSink.addError(`An internal error occurred while parsing file`, getEmptyRange()); + this._parseDiagnostics = diagSink.fetchAndClear(); - // Do not rethrow the exception, swallow it here. Callers are not - // prepared to handle an exception. - } + // Do not rethrow the exception, swallow it here. Callers are not + // prepared to handle an exception. + } - this._analyzedFileContentsVersion = this._fileContentsVersion; - this._isBindingNeeded = true; - this._isCheckingNeeded = true; - this._parseTreeNeedsCleaning = false; - this._hitMaxImportDepth = undefined; - this._diagnosticVersion++; + this._analyzedFileContentsVersion = this._fileContentsVersion; + this._isBindingNeeded = true; + this._isCheckingNeeded = true; + this._parseTreeNeedsCleaning = false; + this._hitMaxImportDepth = undefined; + this._diagnosticVersion++; - return true; + return true; + }); } getDefinitionsForPosition( @@ -760,58 +776,60 @@ export class SourceFile { assert(!this._isBindingInProgress); assert(this._parseResults !== undefined); - try { - // Perform name binding. - timingStats.bindTime.timeOperation(() => { - this._cleanParseTreeIfRequired(); - - const fileInfo = this._buildFileInfo( - configOptions, - this._parseResults!.text, - importLookup, - builtinsScope - ); - AnalyzerNodeInfo.setFileInfo(this._parseResults!.parseTree, fileInfo); - - const binder = new Binder(fileInfo); - this._isBindingInProgress = true; - this._binderResults = binder.bindModule(this._parseResults!.parseTree); - - // If we're in "test mode" (used for unit testing), run an additional - // "test walker" over the parse tree to validate its internal consistency. - if (configOptions.internalTestMode) { - const testWalker = new TestWalker(); - testWalker.walk(this._parseResults!.parseTree); - } + return this._logTracker.log(`binding: ${this._filePath}`, () => { + try { + // Perform name binding. + timingStats.bindTime.timeOperation(() => { + this._cleanParseTreeIfRequired(); + + const fileInfo = this._buildFileInfo( + configOptions, + this._parseResults!.text, + importLookup, + builtinsScope + ); + AnalyzerNodeInfo.setFileInfo(this._parseResults!.parseTree, fileInfo); + + const binder = new Binder(fileInfo); + this._isBindingInProgress = true; + this._binderResults = binder.bindModule(this._parseResults!.parseTree); + + // If we're in "test mode" (used for unit testing), run an additional + // "test walker" over the parse tree to validate its internal consistency. + if (configOptions.internalTestMode) { + const testWalker = new TestWalker(); + testWalker.walk(this._parseResults!.parseTree); + } - this._bindDiagnostics = fileInfo.diagnosticSink.fetchAndClear(); - const moduleScope = AnalyzerNodeInfo.getScope(this._parseResults!.parseTree); - assert(moduleScope !== undefined); - this._moduleSymbolTable = moduleScope!.symbolTable; - }); - } catch (e) { - const message: string = - (e.stack ? e.stack.toString() : undefined) || - (typeof e.message === 'string' ? e.message : undefined) || - JSON.stringify(e); - this._console.error( - `An internal error occurred while performing name binding for ${this.getFilePath()}: ` + message - ); + this._bindDiagnostics = fileInfo.diagnosticSink.fetchAndClear(); + const moduleScope = AnalyzerNodeInfo.getScope(this._parseResults!.parseTree); + assert(moduleScope !== undefined); + this._moduleSymbolTable = moduleScope!.symbolTable; + }); + } catch (e) { + const message: string = + (e.stack ? e.stack.toString() : undefined) || + (typeof e.message === 'string' ? e.message : undefined) || + JSON.stringify(e); + this._console.error( + `An internal error occurred while performing name binding for ${this.getFilePath()}: ` + message + ); - const diagSink = new DiagnosticSink(); - diagSink.addError(`An internal error occurred while performing name binding`, getEmptyRange()); - this._bindDiagnostics = diagSink.fetchAndClear(); + const diagSink = new DiagnosticSink(); + diagSink.addError(`An internal error occurred while performing name binding`, getEmptyRange()); + this._bindDiagnostics = diagSink.fetchAndClear(); - // Do not rethrow the exception, swallow it here. Callers are not - // prepared to handle an exception. - } finally { - this._isBindingInProgress = false; - } + // Do not rethrow the exception, swallow it here. Callers are not + // prepared to handle an exception. + } finally { + this._isBindingInProgress = false; + } - // Prepare for the next stage of the analysis. - this._diagnosticVersion++; - this._isCheckingNeeded = true; - this._isBindingNeeded = false; + // Prepare for the next stage of the analysis. + this._diagnosticVersion++; + this._isCheckingNeeded = true; + this._isBindingNeeded = false; + }); } check(evaluator: TypeEvaluator) { @@ -821,43 +839,45 @@ export class SourceFile { assert(this.isCheckingRequired()); assert(this._parseResults !== undefined); - try { - timingStats.typeCheckerTime.timeOperation(() => { - const checker = new Checker(this._parseResults!.parseTree, evaluator); - checker.check(); - this._isCheckingNeeded = false; - - const fileInfo = AnalyzerNodeInfo.getFileInfo(this._parseResults!.parseTree)!; - this._checkerDiagnostics = fileInfo.diagnosticSink.fetchAndClear(); - }); - } catch (e) { - const isCancellation = OperationCanceledException.is(e); - if (!isCancellation) { - const message: string = - (e.stack ? e.stack.toString() : undefined) || - (typeof e.message === 'string' ? e.message : undefined) || - JSON.stringify(e); - this._console.error( - `An internal error occurred while while performing type checking for ${this.getFilePath()}: ` + - message - ); - const diagSink = new DiagnosticSink(); - diagSink.addError(`An internal error occurred while performing type checking`, getEmptyRange()); + return this._logTracker.log(`checking: ${this._filePath}`, () => { + try { + timingStats.typeCheckerTime.timeOperation(() => { + const checker = new Checker(this._parseResults!.parseTree, evaluator); + checker.check(); + this._isCheckingNeeded = false; - this._checkerDiagnostics = diagSink.fetchAndClear(); + const fileInfo = AnalyzerNodeInfo.getFileInfo(this._parseResults!.parseTree)!; + this._checkerDiagnostics = fileInfo.diagnosticSink.fetchAndClear(); + }); + } catch (e) { + const isCancellation = OperationCanceledException.is(e); + if (!isCancellation) { + const message: string = + (e.stack ? e.stack.toString() : undefined) || + (typeof e.message === 'string' ? e.message : undefined) || + JSON.stringify(e); + this._console.error( + `An internal error occurred while while performing type checking for ${this.getFilePath()}: ` + + message + ); + const diagSink = new DiagnosticSink(); + diagSink.addError(`An internal error occurred while performing type checking`, getEmptyRange()); + + this._checkerDiagnostics = diagSink.fetchAndClear(); + + // Mark the file as complete so we don't get into an infinite loop. + this._isCheckingNeeded = false; + } - // Mark the file as complete so we don't get into an infinite loop. - this._isCheckingNeeded = false; + throw e; + } finally { + // Clear any circular dependencies associated with this file. + // These will be detected by the program module and associated + // with the source file right before it is finalized. + this._circularDependencies = []; + this._diagnosticVersion++; } - - throw e; - } finally { - // Clear any circular dependencies associated with this file. - // These will be detected by the program module and associated - // with the source file right before it is finalized. - this._circularDependencies = []; - this._diagnosticVersion++; - } + }); } private _buildFileInfo( diff --git a/server/src/analyzer/typeEvaluator.ts b/server/src/analyzer/typeEvaluator.ts index acd3aed61bd2..da6ac2ade67a 100644 --- a/server/src/analyzer/typeEvaluator.ts +++ b/server/src/analyzer/typeEvaluator.ts @@ -9150,8 +9150,7 @@ export function createTypeEvaluator(importLookup: ImportLookup, printTypeFlags: } if (parent.nodeType === ParseNodeType.ModuleName) { - // A name within a module name isn't an expression, - // so there's nothing we can evaluate here. + getTypeOfExpression(lastContextualExpression); return; } diff --git a/server/src/common/logTracker.ts b/server/src/common/logTracker.ts new file mode 100644 index 000000000000..6a2643af5910 --- /dev/null +++ b/server/src/common/logTracker.ts @@ -0,0 +1,89 @@ +/* + * logTracker.ts + * Copyright (c) Microsoft Corporation. + * Licensed under the MIT license. + * + * A simple logging class that can be used to track nested loggings. + */ + +import { ConsoleInterface, LogLevel } from './console'; +import { Duration } from './timing'; + +export class LogTracker { + private _dummyState = new State(); + private _indentation = ''; + private _previousTitles: string[] = []; + + constructor(private _console: ConsoleInterface | undefined, private _prefix: string) {} + + log(title: string, callback: (state: LogState) => T) { + // If no console is given, don't do anything. + if (this._console === undefined) { + return callback(this._dummyState); + } + + // This only get enabled when level is LogLevel.Log or not exist + const level = (this._console as any).level; + if (level !== undefined && level !== LogLevel.Log) { + return callback(this._dummyState); + } + + // Since this is only used when LogLevel.Log is set or BG, we don't care much + // on extra logging cost. + const duration = new Duration(); + + const current = this._indentation; + this._previousTitles.push(`${current}${title} ...`); + + this._indentation += ' '; + const state = new State(); + + try { + return callback(state); + } finally { + this._printPreviousTitles(); + + this._indentation = current; + this._console.log( + `[${this._prefix}] ${ + this._indentation + }${title}${state.get()} (${duration.getDurationInMilliseconds()}ms)` + ); + } + } + + private _printPreviousTitles() { + // Get rid of myself + this._previousTitles.pop(); + + if (this._previousTitles.length <= 0) { + return; + } + + for (const previousTitle of this._previousTitles) { + this._console!.log(`[${this._prefix}] ${previousTitle}`); + } + + this._previousTitles.length = 0; + } +} + +export interface LogState { + add(_addendum: string): void; +} + +class State { + private _addendum: string; + + add(_addendum: string) { + this._addendum = _addendum; + } + + get() { + if (this._addendum) { + return ` [${this._addendum}]`; + } + + return ''; + } +} diff --git a/server/src/tests/deferred.test.ts b/server/src/tests/deferred.test.ts new file mode 100644 index 000000000000..b89c3a8ebe16 --- /dev/null +++ b/server/src/tests/deferred.test.ts @@ -0,0 +1,54 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +'use strict'; + +import * as assert from 'assert'; + +import { createDeferred } from '../common/deferred'; + +test('Deferred - resolve', (done) => { + const valueToSent = new Date().getTime(); + const def = createDeferred(); + def.promise + .then((value) => { + assert.equal(value, valueToSent); + assert.equal(def.resolved, true, 'resolved property value is not `true`'); + }) + .then(done) + .catch(done); + + assert.equal(def.resolved, false, 'Promise is resolved even when it should not be'); + assert.equal(def.rejected, false, 'Promise is rejected even when it should not be'); + assert.equal(def.completed, false, 'Promise is completed even when it should not be'); + + def.resolve(valueToSent); + + assert.equal(def.resolved, true, 'Promise is not resolved even when it should not be'); + assert.equal(def.rejected, false, 'Promise is rejected even when it should not be'); + assert.equal(def.completed, true, 'Promise is not completed even when it should not be'); +}); +test('Deferred - reject', (done) => { + const errorToSend = new Error('Something'); + const def = createDeferred(); + def.promise + .then((value) => { + assert.fail(value, 'Error', 'Was expecting promise to get rejected, however it was resolved', ''); + done(); + }) + .catch((reason) => { + assert.equal(reason, errorToSend, 'Error received is not the same'); + done(); + }) + .catch(done); + + assert.equal(def.resolved, false, 'Promise is resolved even when it should not be'); + assert.equal(def.rejected, false, 'Promise is rejected even when it should not be'); + assert.equal(def.completed, false, 'Promise is completed even when it should not be'); + + def.reject(errorToSend); + + assert.equal(def.resolved, false, 'Promise is resolved even when it should not be'); + assert.equal(def.rejected, true, 'Promise is not rejected even when it should not be'); + assert.equal(def.completed, true, 'Promise is not completed even when it should not be'); +}); diff --git a/server/src/tests/fourslash/hover.import.fourslash.ts b/server/src/tests/fourslash/hover.import.fourslash.ts new file mode 100644 index 000000000000..50ce59d3f20f --- /dev/null +++ b/server/src/tests/fourslash/hover.import.fourslash.ts @@ -0,0 +1,11 @@ +/// + +// @filename: test.py +//// import [|/*marker*/library|] + +// @filename: library/__init__.py +//// '''documentation for library''' + +helper.verifyHover({ + marker: { value: '```python\n(module) library\n```\ndocumentation for library', kind: 'markdown' }, +}); diff --git a/server/src/tests/harness/fourslash/testState.ts b/server/src/tests/harness/fourslash/testState.ts index 236b40b3032e..88964229801a 100644 --- a/server/src/tests/harness/fourslash/testState.ts +++ b/server/src/tests/harness/fourslash/testState.ts @@ -722,8 +722,7 @@ export class TestState { } verifyHover(map: { [marker: string]: { value: string; kind: string } }): void { - this._analyze(); - + // Do not force analyze, it can lead to test passing while it doesn't work in product for (const range of this.getRanges()) { const name = this.getMarkerName(range.marker!); const expected = map[name];