Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ts-jest with cleared cache is reading package.json in node_modules over and over - start takes forever #908

Closed
Farbdose opened this issue Dec 11, 2018 · 17 comments
Closed

ts-jest with cleared cache is reading package.json in node_modules over and over - start takes forever #908

Farbdose opened this issue Dec 11, 2018 · 17 comments
Labels
Help Wanted Performance Severe performance issue

Comments

@Farbdose
Copy link

Farbdose commented Dec 11, 2018 •
edited

Issue:

I just updated to ts-jest@23.10.5 from somewhere around ~23.1.3 (which increased the runtime of my testsuite from 10ish seconds [on the first run / with cleared cache) to over 40 seconds - with cache around 2.5s.

Update: problem was already present at 23.10.1 [not sure if earlier - the config format changed there so I have to rewrite that first if I want to go further back]

So I started investigating... and found out that something is calling readFile like mad.
To be precise: almost all calls to ts.resolveModuleName in typescript.js seem to cause a readFile of the corresponding package.json

I added some consolge.log to node_modules/typescript/lib/typescript.js and

got the following log 
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/di/reflective_injector
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/di/reflective_provider
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/profile/profile
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/profile/wtf_impl
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/fields
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/instructions
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/interfaces/player
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/interfaces/view
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/styling/player_factory
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/util
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/render3/view_engine_compatibility
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/util/decorators
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/util/property
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/view/provider
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/view/services
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/view/types
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./public_api
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./src/core
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./version
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./util/decorators
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./di
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./application_ref
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./is_dev_mode
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./application_tokens
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./application_init
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./zone
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./render
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./linker
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./debug/debug_node
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./testability/testability
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./change_detection
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./platform_core_providers
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./i18n/tokens
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./application_module
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./profile/profile
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./type
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./event_emitter
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./error_handler
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./core_private_export
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./core_render3_private_export
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./sanitization/security
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./codegen_private_exports
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata/di
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata/directives
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata/lifecycle_hooks
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata/ng_module
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ./metadata/view
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json
ts.resolveModuleName triggered by ../di/injection_token
readFile hook, someone is reading: /demoProject/node_modules/@angular/core/package.json

... 20Mb more of this

I would appreciate a second opinion as I'm not even sure if this is some weird edge case in ts-jest, an oversight in typescript or if its possible to cause it through misconfiguration.

Update: I think I managed to track it down to js files that need to be processed by ts-jest (as they contain import statements) being present in on of the imported modules (one of our own). Removing it causes the runtime to go back to normal. The interesting thing is that the module in question has its own jest tests and when I use the same config there I have no problems, so the problem is not the code itself but the fact that I'm importing the compiled version of it.

Also with typescript below 2.9 it's still present but only around 26 seconds [not >40]

So upgrading:
ts-jest@>=23.10.1 (23.10.0 doesn't work because of #740) causes a slowdown of around x5 and
typescript@>=2.9 causes an additional slowdown of x2

Also, removing ionic removed the problem too. So its possible this is actually an ionic issue. I created a separate issue for that though: ionic-team/ionic-framework#16703

Expected behavior :

The initial start of the test suite shouldn't take so much longer. Maybe the package.json files should be cached.

Debug log:

ts-jest.log 
# 
{"context":{"allowJs":false,"logLevel":20,"namespace":"jest-preset","package":"ts-jest","version":"23.10.5"},"message":"creating jest presets not handling JavaScript files","sequence":1,"time":"2018-12-12T10:21:04.615Z"}
{"context":{"logLevel":20,"namespace":"Importer","package":"ts-jest","version":"23.10.5"},"message":"creating Importer singleton","sequence":2,"time":"2018-12-12T10:21:05.788Z"}
{"context":{"allowJs":false,"logLevel":20,"namespace":"jest-preset","package":"ts-jest","version":"23.10.5"},"message":"creating jest presets not handling JavaScript files","sequence":3,"time":"2018-12-12T10:21:05.791Z"}
{"context":{"actualVersion":"23.6.0","expectedVersion":">=22 <24","logLevel":20,"namespace":"versions","package":"ts-jest","version":"23.10.5"},"message":"checking version of jest: OK","sequence":4,"time":"2018-12-12T10:21:05.794Z"}
{"context":{"baseOptions":{},"logLevel":20,"namespace":"jest-transformer","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"created new transformer","sequence":5,"time":"2018-12-12T10:21:05.794Z"}
{"context":{"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":20,"namespace":"jest-transformer","package":"ts-jest","transformOptions":{"instrument":false,"rootDir":"/demoProject/ts-jest-multiple-readFile"},"transformerId":1,"version":"23.10.5"},"message":"computing cache key for /demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","sequence":6,"time":"2018-12-12T10:21:05.795Z"}
{"context":{"logLevel":30,"namespace":"jest-transformer","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"no matching config-set found, creating a new one","sequence":7,"time":"2018-12-12T10:21:05.796Z"}
{"context":{"config":{"automock":false,"browser":false,"cache":false,"cacheDirectory":"/tmp/jest_rs","clearMocks":false,"coveragePathIgnorePatterns":["/node_modules/"],"cwd":"/demoProject/ts-jest-multiple-readFile","detectLeaks":false,"detectOpenHandles":false,"errorOnDeprecated":false,"filter":null,"forceCoverageMatch":[],"globals":{"ts-jest":{"astTransformers":["/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js"],"stringifyContentPathRegex":"\\.html$","tsConfig":"<rootDir>/src/tsconfig.spec.json"}},"haste":{"providesModuleNodeModules":[]},"moduleDirectories":["node_modules"],"moduleFileExtensions":["js","json","jsx","node","ts","tsx","html"],"moduleNameMapper":[["^@ionic/core/loader","/demoProject/ts-jest-multiple-readFile/node_modules/@ionic/core/dist/esm/es5/ionic.define.js"],["^@ionic/core/dist/ionic/svg","/demoProject/ts-jest-multiple-readFile/svgoverride.js"],["^src/(.*)$","/demoProject/ts-jest-multiple-readFile/src/$1"],["^app/(.*)$","/demoProject/ts-jest-multiple-readFile/src/app/$1"],["^assets/(.*)$","/demoProject/ts-jest-multiple-readFile/src/assets/$1"],["^environments/(.*)$","/demoProject/ts-jest-multiple-readFile/src/environments/$1"]],"modulePathIgnorePatterns":[],"name":"e00816d3a3081a8635b95b2cf88db78d","prettierPath":null,"resetMocks":false,"resetModules":false,"resolver":null,"restoreMocks":false,"rootDir":"/demoProject/ts-jest-multiple-readFile","roots":["/demoProject/ts-jest-multiple-readFile/src"],"runner":"jest-runner","setupFiles":[],"setupTestFrameworkScriptFile":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","skipFilter":false,"snapshotSerializers":["/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/AngularSnapshotSerializer.js","/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/HTMLCommentSerializer.js"],"testEnvironment":"jest-environment-jsdom","testEnvironmentOptions":{},"testLocationInResults":false,"testMatch":["**/__tests__/**/*.+(ts|js)?(x)","**/+(*.)+(spec|test).+(ts|js)?(x)"],"testPathIgnorePatterns":["/node_modules/"],"testRegex":"","testRunner":"/demoProject/ts-jest-multiple-readFile/node_modules/jest-jasmine2/build/index.js","testURL":"http://localhost/","timers":"real","transform":[["^.+\\.(ts|js|html)$","/demoProject/ts-jest-multiple-readFile/node_modules/ts-jest/dist/index.js"]],"transformIgnorePatterns":["node_modules/(?!(@angular/common|@ionic|@ionic))"],"watchPathIgnorePatterns":[]},"logLevel":20,"namespace":"backports","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"backporting config","sequence":8,"time":"2018-12-12T10:21:05.796Z"}
{"context":{"jestConfig":{"automock":false,"browser":false,"cache":false,"cacheDirectory":"/tmp/jest_rs","clearMocks":false,"coveragePathIgnorePatterns":["/node_modules/"],"cwd":"/demoProject/ts-jest-multiple-readFile","detectLeaks":false,"detectOpenHandles":false,"errorOnDeprecated":false,"filter":null,"forceCoverageMatch":[],"globals":{"ts-jest":{"astTransformers":["/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js"],"stringifyContentPathRegex":"\\.html$","tsConfig":"<rootDir>/src/tsconfig.spec.json"}},"haste":{"providesModuleNodeModules":[]},"moduleDirectories":["node_modules"],"moduleFileExtensions":["js","json","jsx","node","ts","tsx","html"],"moduleNameMapper":[["^@ionic/core/loader","/demoProject/ts-jest-multiple-readFile/node_modules/@ionic/core/dist/esm/es5/ionic.define.js"],["^@ionic/core/dist/ionic/svg","/demoProject/ts-jest-multiple-readFile/svgoverride.js"],["^src/(.*)$","/demoProject/ts-jest-multiple-readFile/src/$1"],["^app/(.*)$","/demoProject/ts-jest-multiple-readFile/src/app/$1"],["^assets/(.*)$","/demoProject/ts-jest-multiple-readFile/src/assets/$1"],["^environments/(.*)$","/demoProject/ts-jest-multiple-readFile/src/environments/$1"]],"modulePathIgnorePatterns":[],"name":"e00816d3a3081a8635b95b2cf88db78d","prettierPath":null,"resetMocks":false,"resetModules":false,"resolver":null,"restoreMocks":false,"rootDir":"/demoProject/ts-jest-multiple-readFile","roots":["/demoProject/ts-jest-multiple-readFile/src"],"runner":"jest-runner","setupFiles":[],"setupTestFrameworkScriptFile":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","skipFilter":false,"snapshotSerializers":["/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/AngularSnapshotSerializer.js","/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/HTMLCommentSerializer.js"],"testEnvironment":"jest-environment-jsdom","testEnvironmentOptions":{},"testLocationInResults":false,"testMatch":["**/__tests__/**/*.+(ts|js)?(x)","**/+(*.)+(spec|test).+(ts|js)?(x)"],"testPathIgnorePatterns":["/node_modules/"],"testRegex":"","testRunner":"/demoProject/ts-jest-multiple-readFile/node_modules/jest-jasmine2/build/index.js","testURL":"http://localhost/","timers":"real","transform":[["^.+\\.(ts|js|html)$","/demoProject/ts-jest-multiple-readFile/node_modules/ts-jest/dist/index.js"]],"transformIgnorePatterns":["node_modules/(?!(@angular/common|@ionic|@ionic))"],"watchPathIgnorePatterns":[]},"logLevel":20,"namespace":"config","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"normalized jest config","sequence":9,"time":"2018-12-12T10:21:05.796Z"}
{"context":{"fromPath":"<rootDir>/src/tsconfig.spec.json","logLevel":20,"namespace":"config","package":"ts-jest","toPath":"/demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json","transformerId":1,"version":"23.10.5"},"message":"resolved path from <rootDir>/src/tsconfig.spec.json to /demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json","sequence":10,"time":"2018-12-12T10:21:05.797Z"}
{"context":{"fromPath":"/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js","logLevel":20,"namespace":"config","package":"ts-jest","toPath":"/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js","transformerId":1,"version":"23.10.5"},"message":"resolved path from /demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js to /demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js","sequence":11,"time":"2018-12-12T10:21:05.797Z"}
{"context":{"logLevel":20,"namespace":"config","package":"ts-jest","transformerId":1,"tsJestConfig":{"compiler":"typescript","diagnostics":{"ignoreCodes":[6059,18002,18003],"pretty":true,"throws":true},"isolatedModules":false,"stringifyContentPathRegex":"\\.html$","transformers":["/demoProject/ts-jest-multiple-readFile/node_modules/jest-preset-angular/InlineHtmlStripStylesTransformer.js"],"tsConfig":{"kind":"file","value":"/demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json"}},"version":"23.10.5"},"message":"normalized ts-jest config","sequence":12,"time":"2018-12-12T10:21:05.798Z"}
{"context":{"logLevel":20,"namespace":"config","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"babel is disabled","sequence":13,"time":"2018-12-12T10:21:05.800Z"}
{"context":{"logLevel":20,"namespace":"Importer","package":"ts-jest","requireResult":{"exists":true,"given":"typescript","path":"/demoProject/ts-jest-multiple-readFile/node_modules/typescript/lib/typescript.js"},"version":"23.10.5"},"message":"loaded module typescript","sequence":14,"time":"2018-12-12T10:21:06.016Z"}
{"context":{"logLevel":20,"namespace":"Importer","package":"ts-jest","version":"23.10.5"},"message":"patching typescript","sequence":15,"time":"2018-12-12T10:21:06.016Z"}
{"context":{"actualVersion":"3.1.6","expectedVersion":">=2.7 <4","logLevel":20,"namespace":"versions","package":"ts-jest","version":"23.10.5"},"message":"checking version of typescript: OK","sequence":16,"time":"2018-12-12T10:21:06.017Z"}
{"context":{"logLevel":20,"namespace":"config","package":"ts-jest","transformerId":1,"tsConfigFileName":"/demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json","version":"23.10.5"},"message":"readTsConfig(): reading /demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json","sequence":17,"time":"2018-12-12T10:21:06.017Z"}
{"context":{"logLevel":20,"namespace":"config","package":"ts-jest","transformerId":1,"tsconfig":{"input":{"compilerOptions":{"allowJs":true,"baseUrl":"","module":"commonjs","outDir":"../out-tsc/spec","target":"es5","types":["node","jest"]},"extends":"../tsconfig.json","include":["**/*.spec.ts","**/*.d.ts","index.ts"]},"resolved":{"compileOnSave":false,"configFileSpecs":{"excludeSpecs":["../dist","../node_modules"],"includeSpecs":["**/*.spec.ts","**/*.d.ts","index.ts"],"validatedExcludeSpecs":["../dist","../node_modules"],"validatedIncludeSpecs":["**/*.spec.ts","**/*.d.ts","index.ts"],"wildcardDirectories":{"/demoProject/ts-jest-multiple-readFile/src":1}},"errors":[],"fileNames":["/demoProject/ts-jest-multiple-readFile/src/providers/my-provider.spec.ts","/demoProject/ts-jest-multiple-readFile/src/index.ts"],"options":{"allowJs":true,"baseUrl":"/demoProject/ts-jest-multiple-readFile/src","configFilePath":"/demoProject/ts-jest-multiple-readFile/src/tsconfig.spec.json","declaration":false,"emitDecoratorMetadata":true,"experimentalDecorators":true,"inlineSourceMap":false,"inlineSources":true,"lib":["lib.es2018.d.ts","lib.dom.d.ts"],"module":1,"moduleResolution":2,"noEmit":false,"noImplicitAny":false,"outDir":"$$ts-jest$$","removeComments":false,"rootDir":"/demoProject/ts-jest-multiple-readFile/src","sourceMap":true,"target":1,"typeRoots":["/demoProject/ts-jest-multiple-readFile/node_modules/@types"],"types":["node","jest"]},"raw":{"compileOnSave":false,"compilerOptions":{"allowJs":true,"baseUrl":"","module":"commonjs","outDir":"../out-tsc/spec","target":"es5","types":["node","jest"]},"exclude":["../dist","../node_modules"],"extends":"../tsconfig.json","include":["**/*.spec.ts","**/*.d.ts","index.ts"]},"typeAcquisition":{"enable":false,"exclude":[],"include":[]},"wildcardDirectories":{"/demoProject/ts-jest-multiple-readFile/src":1}}},"version":"23.10.5"},"message":"normalized typescript config","sequence":18,"time":"2018-12-12T10:21:06.035Z"}
{"context":{"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":20,"namespace":"jest-transformer","package":"ts-jest","transformOptions":{"instrument":false},"transformerId":1,"version":"23.10.5"},"message":"processing /demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","sequence":19,"time":"2018-12-12T10:21:06.036Z"}
{"context":{"logLevel":20,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"creating typescript compiler (language service)","sequence":20,"time":"2018-12-12T10:21:06.038Z"}
{"context":{"logLevel":20,"namespace":"config","package":"ts-jest","version":"23.10.5"},"message":"file caching disabled","sequence":21,"time":"2018-12-12T10:21:06.038Z"}
{"context":{"logLevel":20,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"creating language service","sequence":22,"time":"2018-12-12T10:21:06.038Z"}
{"context":{"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":20,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readThrough(): no cache","sequence":23,"time":"2018-12-12T10:21:06.041Z"}
{"context":{"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":20,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getOutput(): compiling using language service","sequence":24,"time":"2018-12-12T10:21:06.041Z"}
{"context":{"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":20,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"updateMemoryCache()","sequence":25,"time":"2018-12-12T10:21:06.041Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/src/providers/my-provider.spec.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":26,"time":"2018-12-12T10:21:06.042Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/src/index.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":27,"time":"2018-12-12T10:21:06.042Z"}
{"context":{"cacheHit":true,"fileName":"/demoProject/ts-jest-multiple-readFile/src/setup-jest.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache hit","sequence":28,"time":"2018-12-12T10:21:06.042Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":29,"time":"2018-12-12T10:21:06.057Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":30,"time":"2018-12-12T10:21:06.060Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":31,"time":"2018-12-12T10:21:06.064Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":32,"time":"2018-12-12T10:21:06.065Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/testing.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":33,"time":"2018-12-12T10:21:06.067Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":34,"time":"2018-12-12T10:21:06.070Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":35,"time":"2018-12-12T10:21:06.072Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":36,"time":"2018-12-12T10:21:06.074Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/index.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":37,"time":"2018-12-12T10:21:06.076Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":38,"time":"2018-12-12T10:21:06.077Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/public_api.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":39,"time":"2018-12-12T10:21:06.080Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":40,"time":"2018-12-12T10:21:06.081Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/src/testing.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":41,"time":"2018-12-12T10:21:06.082Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":42,"time":"2018-12-12T10:21:06.083Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":43,"time":"2018-12-12T10:21:06.086Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":44,"time":"2018-12-12T10:21:06.088Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":45,"time":"2018-12-12T10:21:06.091Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":46,"time":"2018-12-12T10:21:06.093Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":47,"time":"2018-12-12T10:21:06.096Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":48,"time":"2018-12-12T10:21:06.098Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":49,"time":"2018-12-12T10:21:06.099Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":50,"time":"2018-12-12T10:21:06.101Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/src/async.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":51,"time":"2018-12-12T10:21:06.103Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/testing/src/component_fixture.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":52,"time":"2018-12-12T10:21:06.104Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":53,"time":"2018-12-12T10:21:06.110Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/core.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":54,"time":"2018-12-12T10:21:06.112Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":55,"time":"2018-12-12T10:21:06.114Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":56,"time":"2018-12-12T10:21:06.116Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":57,"time":"2018-12-12T10:21:06.119Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":58,"time":"2018-12-12T10:21:06.121Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":59,"time":"2018-12-12T10:21:06.123Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":60,"time":"2018-12-12T10:21:06.125Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":61,"time":"2018-12-12T10:21:06.126Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":62,"time":"2018-12-12T10:21:06.128Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":63,"time":"2018-12-12T10:21:06.130Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":64,"time":"2018-12-12T10:21:06.132Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":65,"time":"2018-12-12T10:21:06.134Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":66,"time":"2018-12-12T10:21:06.136Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":67,"time":"2018-12-12T10:21:06.138Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":68,"time":"2018-12-12T10:21:06.139Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":69,"time":"2018-12-12T10:21:06.140Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":70,"time":"2018-12-12T10:21:06.143Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":71,"time":"2018-12-12T10:21:06.145Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":72,"time":"2018-12-12T10:21:06.146Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":73,"time":"2018-12-12T10:21:06.148Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":74,"time":"2018-12-12T10:21:06.151Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":75,"time":"2018-12-12T10:21:06.152Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/index.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":76,"time":"2018-12-12T10:21:06.153Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":77,"time":"2018-12-12T10:21:06.154Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/public_api.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":78,"time":"2018-12-12T10:21:06.155Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":79,"time":"2018-12-12T10:21:06.156Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/core.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":80,"time":"2018-12-12T10:21:06.157Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":81,"time":"2018-12-12T10:21:06.159Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":82,"time":"2018-12-12T10:21:06.161Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":83,"time":"2018-12-12T10:21:06.162Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":84,"time":"2018-12-12T10:21:06.164Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":85,"time":"2018-12-12T10:21:06.166Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":86,"time":"2018-12-12T10:21:06.167Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":87,"time":"2018-12-12T10:21:06.168Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":88,"time":"2018-12-12T10:21:06.169Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":89,"time":"2018-12-12T10:21:06.171Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":90,"time":"2018-12-12T10:21:06.172Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":91,"time":"2018-12-12T10:21:06.173Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":92,"time":"2018-12-12T10:21:06.174Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":93,"time":"2018-12-12T10:21:06.176Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":94,"time":"2018-12-12T10:21:06.177Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":95,"time":"2018-12-12T10:21:06.178Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":96,"time":"2018-12-12T10:21:06.180Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":97,"time":"2018-12-12T10:21:06.182Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":98,"time":"2018-12-12T10:21:06.183Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":99,"time":"2018-12-12T10:21:06.184Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":100,"time":"2018-12-12T10:21:06.185Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":101,"time":"2018-12-12T10:21:06.187Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":102,"time":"2018-12-12T10:21:06.188Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":103,"time":"2018-12-12T10:21:06.189Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":104,"time":"2018-12-12T10:21:06.190Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":105,"time":"2018-12-12T10:21:06.191Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/metadata.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":106,"time":"2018-12-12T10:21:06.192Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":107,"time":"2018-12-12T10:21:06.194Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":108,"time":"2018-12-12T10:21:06.195Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":109,"time":"2018-12-12T10:21:06.196Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":110,"time":"2018-12-12T10:21:06.197Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":111,"time":"2018-12-12T10:21:06.199Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/metadata/di.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":112,"time":"2018-12-12T10:21:06.200Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":113,"time":"2018-12-12T10:21:06.209Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":114,"time":"2018-12-12T10:21:06.210Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/di/injection_token.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":115,"time":"2018-12-12T10:21:06.211Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":116,"time":"2018-12-12T10:21:06.213Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/type.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":117,"time":"2018-12-12T10:21:06.213Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/metadata/directives.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":118,"time":"2018-12-12T10:21:06.215Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":119,"time":"2018-12-12T10:21:06.237Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":120,"time":"2018-12-12T10:21:06.238Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":121,"time":"2018-12-12T10:21:06.239Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":122,"time":"2018-12-12T10:21:06.240Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/change_detection/constants.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":123,"time":"2018-12-12T10:21:06.240Z"}
{"context":{"cacheHit":false,"fileName":"/demoProject/ts-jest-multiple-readFile/node_modules/@angular/core/src/di.d.ts","logLevel":10,"namespace":"ts-compiler","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"getScriptSnapshot(): cache miss","sequence":124,"time":"2018-12-12T10:21:06.242Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":125,"time":"2018-12-12T10:21:06.244Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":126,"time":"2018-12-12T10:21:06.245Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":127,"time":"2018-12-12T10:21:06.246Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":128,"time":"2018-12-12T10:21:06.249Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":129,"time":"2018-12-12T10:21:06.250Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":130,"time":"2018-12-12T10:21:06.251Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":131,"time":"2018-12-12T10:21:06.252Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":132,"time":"2018-12-12T10:21:06.253Z"}
{"context":{"call":null,"logLevel":10,"namespace":"ts:serviceHost","package":"ts-jest","transformerId":1,"version":"23.10.5"},"message":"readFile","sequence":133,"time":"2018-12-12T10:21:06.254Z"}

... 20Mb more of this, full version here: https://gitlab.com/Farbdose/ts-jest-multiple-fileread/raw/master/ts-jest.log

Full version at https://gitlab.com/Farbdose/ts-jest-multiple-fileread/raw/master/ts-jest.log

Minimal repo :

https://gitlab.com/Farbdose/ts-jest-multiple-fileread
While creating this demo repository I realized that the problem goes away if I remove ionic so this seems to be partially responsible too.
@Farbdose Farbdose changed the title ts-jest with cleared cache is reading package.json over and over - start takes forever ts-jest with cleared cache is reading package.json in node_modules over and over - start takes forever Dec 11, 2018
@Farbdose
Copy link
Author

Farbdose commented Dec 12, 2018 •
edited

I got a minimal repo working - not sure how mini it is though. Removing all the unneeded packages (like ionic) results in the problem going away so apparently they are needed after all.

Update: The demo is now as small as possible [probably].

@Farbdose Farbdose mentioned this issue Dec 12, 2018
Closed
@huafu
Copy link
Collaborator

huafu commented Dec 13, 2018

@Farbdose thanks for investigation and minimal repo. I have no time looking at this now, but if the read is in node_modules/typescript/lib/typescript.js, then it's in typescript that they should fix smthg. Anyway, as soon as I have time to look deeper at that, I'll see if a cache can be added at this location.

@ericanderson
Copy link
Contributor

I think the broader problem is something changed in 20.10 from 20.1 such that we rolled back.

@ahnpnl ahnpnl mentioned this issue Dec 16, 2018
Closed
@Farbdose
Copy link
Author

I removed some dependencies from the demo repo that were apparently unnecessary.
I also updated the rest and managed to increase the test time to 40 seconds by doing so [was around 25 before]...

@Farbdose
Copy link
Author

Farbdose commented Dec 18, 2018 •
edited

Update: I played a bit around and wrote a very basic [destructive] cache into getPackageJsonInfo (typescript.js around line 26097)

getPackageJsonInfo 
var customCache = {};
var customCachePathLen = process.cwd().length+13;
function getPackageJsonInfo(packageDirectory, subModuleName, onlyRecordFailures, state) {
    var host = state.host, traceEnabled = state.traceEnabled;
    var directoryExists = !onlyRecordFailures && ts.directoryProbablyExists(packageDirectory, host);
    var packageJsonPath = ts.combinePaths(packageDirectory, "package.json");

    var key = packageDirectory.substr(customCachePathLen);
    var cache = customCache[key];
    if(cache || cache === null) {
	    return cache;
    }

    if (directoryExists && host.fileExists(packageJsonPath)) {
        var packageJsonContent = ts.readJson(packageJsonPath, host);
        if (subModuleName === "") { // looking up the root - need to handle types/typings/main redirects for subModuleName
            var path = readPackageJsonTypesFields(packageJsonContent, packageDirectory, state);
            if (typeof path === "string") {
                subModuleName = addExtensionAndIndex(path.substring(packageDirectory.length + 1));
            }
            else {
                var jsPath = readPackageJsonMainField(packageJsonContent, packageDirectory, state);
                if (typeof jsPath === "string" && jsPath.length > packageDirectory.length) {
                    var potentialSubModule_1 = jsPath.substring(packageDirectory.length + 1);
                    subModuleName = (ts.forEach(ts.supportedJSExtensions, function (extension) {
                        return ts.tryRemoveExtension(potentialSubModule_1, extension);
                    }) || potentialSubModule_1) + ".d.ts" /* Dts */;
                }
                else {
                    subModuleName = "index.d.ts";
                }
            }
        }
        if (!ts.endsWith(subModuleName, ".d.ts" /* Dts */)) {
            subModuleName = addExtensionAndIndex(subModuleName);
        }
        var versionPaths = readPackageJsonTypesVersionPaths(packageJsonContent, state);
        var packageId = typeof packageJsonContent.name === "string" && typeof packageJsonContent.version === "string"
            ? { name: packageJsonContent.name, subModuleName: subModuleName, version: packageJsonContent.version }
            : undefined;
        if (traceEnabled) {
            if (packageId) {
                trace(host, ts.Diagnostics.Found_package_json_at_0_Package_ID_is_1, packageJsonPath, ts.packageIdToString(packageId));
            }
            else {
                trace(host, ts.Diagnostics.Found_package_json_at_0, packageJsonPath);
            }
        }
        var res = { packageJsonContent: packageJsonContent, packageId: packageId, versionPaths: versionPaths };
        customCache[key] = res || null;
        return res;
    }
    else {
        if (directoryExists && traceEnabled) {
            trace(host, ts.Diagnostics.File_0_does_not_exist, packageJsonPath);
        }
        // record package json as one of failed lookup locations - in the future if this file will appear it will invalidate resolution results
        state.failedLookupLocations.push(packageJsonPath);
    }
}

...which got the time down to around 24s again.

The interesting thing though is, that after that I got a much clearer cpu profile:
CPU-20181218T162138.zip

Update2 I tried that mini cache in a bigger project and it just crashed typescript. So apparently this only works if you aren't importing anything complex (like in the demo repo)

Update 3: I found a proper place to cache the json files readJson:
This approach seems to be actually stable and got the demo repository from 40s down to 28s [again]...
Testing on a bigger project resulted in a speedup of 100%

I'll investigate what update introduced the additional slowdown to the demo project and try to get rid of that too... after that ... it looks like I'll have to create a pullreqest for typescript.

readJson patch V1 for compiled typescript.js 
var readJsonCache = {};
function readJson(path, host) {
    var cache = readJsonCache[path];

    if(cache) {
        return cache;
    } else {
        readJsonCache[path] = {};
    }

    try {
        var jsonText = host.readFile(path);
        if (!jsonText) {
            return {};
        }
        var result = ts.parseConfigFileTextToJson(path, jsonText);
        if (result.error) {
            return {};
        } else {
            readJsonCache[path] = result.config;
            return result.config;
        }
    } catch (e) {
        // gracefully handle if readFile fails or returns not JSON
        return {};
    }
}
readJson patch V2 for typescript/src/compiler/utilities.ts 
const readJsonCache = createMap<object>();
export function readJson(path: string, host: { readFile(fileName: string): string | undefined }): object {
    if (readJsonCache.has(path)) {
        return <object>readJsonCache.get(path);
    } else {
        readJsonCache.set(path, {})
    }

    try {
        const jsonText = host.readFile(path);
        if (!jsonText) return {};
        const result = parseConfigFileTextToJson(path, jsonText);
        if (result.error) {
            return {};
        }

        readJsonCache.set(path, result.config);
        return result.config;
    }
    catch (e) {
        // gracefully handle if readFile fails or returns not JSON
        return {};
    }
}

@Farbdose
Copy link
Author

Farbdose commented Dec 19, 2018 •
edited

Update 4: so with readJson cached the above CPU profile revealed fileSystemEntryExists to be the next culprit. After caching that too:

fileSystemEntryExists patch V1 for compiled typescript.js 
var fileExistsCache = {}
function fileSystemEntryExists(path, entryKind) {
    var cache = fileExistsCache[path];
    if(cache) {
        return cache == entryKind;
    }

    try {
        var stat = _fs.statSync(path);
        if(stat.isFile()) {
            fileExistsCache[path] = 0;
            return 0 == entryKind;
        } else if(isDirectory()) {
            fileExistsCache[path] = 1;
            return 1 == entryKind;
        }else {
            fileExistsCache[path] = -1;
            return false;
        }
    } catch (e) {
        fileExistsCache[path] = -1;
        return false;
    }
}
fileSystemEntryExists patch V2 for typescript/src/compiler/sys.ts 
const fileExistsCache = createMap<FileSystemEntryKind | -1>();
function fileSystemEntryExists(path: string, entryKind: FileSystemEntryKind): boolean {
    if(fileSystemEntryCache.has(path)) {
        return fileSystemEntryCache.get(path) == entryKind;
    }
    try {
        const stat = _fs.statSync(path);
        if (stat.isFile()) {
            fileSystemEntryCache.set(path, FileSystemEntryKind.File);
            return entryKind == FileSystemEntryKind.File;
        } else if(stat.isDirectory()) {
            fileSystemEntryCache.set(path, FileSystemEntryKind.Directory);
            return entryKind == FileSystemEntryKind.Directory;
        } else {
            fileSystemEntryCache.set(path, -1);
            return false;
        }
    }
    catch (e) {
        fileSystemEntryCache.set(path, -1);
        return false;
    }
}


I got my demo repository down to 15s.

So it seems this slowdown is caused by non-highspeed-file-access ... apparently one needs an unencrypted SSD for this stuff. I will try to put node_modules into a ramdisk and compare the performance.

I will create an issue over at typescript in the following days (after I found out how I can get the tests to pass again^^)

The only thing that's left is to find out why performance dropped so much in the first place.
Ionic just got more files so that's one mystery solved...

@huafu @ericanderson But why did this get so much worse with the ts-jest update?

Update 5: I put node_modules into a ram_disk and removed my caches witch got it down to 14s (no overhead for cache)

tl;tr Check if your node_modules is on a fast hard drive (eg unencrypted SSD)

If you are trying to optimize a CI pipeline without node_modules cache (like me) that reinstalls everything on each build, consider creating a ramdisk for node_modules before running npm install

ram disk example 
#!/bin/bash

uid=$(id -u)
gid=$(id -g)

mkdir -p node_modules
sudo mount -t ramfs ramfs node_modules
sudo chown $uid:$gid node_modules

npm install

Update 6: It seems like readJson is only slow because of the containing calls to fileSystemEntryExists so the second fix already contains the first.

@Farbdose
Copy link
Author

Farbdose commented Dec 19, 2018 •
edited

Update 7: typescript apparently already added a cache microsoft/TypeScript#27068
It looks like this fix should be placed in ts-jest/src/compiler.ts instead
Note: adding the fix there doesn't overwrite the calls to fileExists that are actually causing the slowdown though...

Update 8: I'm giving up on fixing this. For some reason now even my baseline version that should have no extras is slow with a ramdisk - no idea what I did...

I updated the demo repository to the latest ionic version and typescript to 3.2.2 and 3.3.0-dev.20181220 in another branch It now takes around 45 seconds in the gitlab build pipeline so if anybody wants to try his luck, you are welcome.

I'll create an issue over at Typescript maybe they have an idea.

@Farbdose Farbdose mentioned this issue Dec 20, 2018
Closed
@fruchtose
Copy link

I'd like to add that I also experienced a big performance regression trying to update from 23.0.x to 23.10.5. The size of this regression prevents me from upgrading. I really appreciate that this library exists and all the work that goes into it, but I may have to consider an alternative in the future.

@AndriiShpak
Copy link

AndriiShpak commented Jan 7, 2019 •
edited

Also would like to inform that I tried upgrading to alpha version of jest-preset-angular (which depends on new version of ts-jest) and timing difference was impossible to work with.
Tried 1 test block (with cleared cache) and run time was around 65s (compared to ~6s before update). Also when running all tests in my project(~350 tests) I had to cancel - I waited for 10 minutes and tests were still running (before update tests needed around 60s with cleared cache)

@IOuser
Copy link
Contributor

IOuser commented Jan 8, 2019

Recently, I also encountered the slowdown of tests with disabled jest cache.
As @Farbdose noted, the reason for the slowdown is intensive work with the file system.
So I tried to implement a simple cache for fs calls in TS language service.

And here's results for my codebase:
Before adding fs cache: ~280s (3 runs avg.)
After adding fs cache: ~91s (3 runs avg.)

IOuser added a commit to IOuser/ts-jest that referenced this issue Jan 8, 2019
@IOuser
fix(perf): add cache for fs calls (kulshekhar#908)
ca09996
This was referenced Jan 8, 2019
Closed
Closed
@dubbha
Copy link

dubbha commented Feb 20, 2019

Same issue remains for version 24.0, as far as I can tell...

@ahnpnl ahnpnl added Help Wanted Performance Severe performance issue labels Mar 17, 2019
@wtho wtho mentioned this issue Mar 17, 2019
Closed
@jensengar
Copy link

I have a simple lib that I'm working on. It probably has about a dozen small ts files and it takes ~25 seconds to start running the tests.

@4kochi 4kochi mentioned this issue Apr 2, 2019
Closed
@VicJer
Copy link

VicJer commented Apr 16, 2019

I like how you guys experience tests slowing down to N seconds... you think you have ts-jest slow... PASS src/redux/epics.test.ts (1371.894s) And I have absolutely no clue why that is. Running jest --no-cache absolutely kills it. Initial tests are always > 10m on ts-jest 24.0.2 whereas on 23.1.4 the whole suite of over 1800 tests passes in 56 seconds.

@VicJer
Copy link

VicJer commented Apr 17, 2019

OH MY GOD! A week of banging my head against the wall just to find this little package.json option deep down in convoluted issue threads....
"globals": { "ts-jest": { "isolatedModules": true } }
My tests pass within 120s instead of 10 mins.

@snyk-bot snyk-bot mentioned this issue Dec 1, 2019
Merged
@ahnpnl ahnpnl mentioned this issue Jan 12, 2020
Closed
@camsjams
Copy link

Thanks @VicJer that config adjustment worked brilliantly!

@ahnpnl
Copy link
Collaborator

ahnpnl commented Apr 12, 2020

Hi guys, 23.10.5 was a complete rewrite version and ts-jest switched to use typescript language service as default mode, which is be slower than isolatedModules mode. 23.1.x used isolatedModules mode so it explained why the tests ran faster. However, using this isolatedModules mode you will lose some functionalities see doc

We have tried our best to do some improvements regarding to this topic. I will close this issue, please test with 25.2.1 and share your opinions and statistics about this topic in #1115. Any helps are welcome 🙏

@ahnpnl ahnpnl closed this as completed Apr 12, 2020
@duck-nukem duck-nukem mentioned this issue Apr 20, 2020
Open
@ahnpnl
Copy link
Collaborator

ahnpnl commented Apr 21, 2020

FYI: #1549 will be in alpha version of ts-jest (possibly today). Anyone who is using ts-jest please help to test the alpha version and give us some feedbacks for #1115

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Help Wanted Performance Severe performance issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests