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

Farbdose · 2018-12-11T17:27:34Z

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.

The text was updated successfully, but these errors were encountered:

Farbdose · 2018-12-12T10:35:45Z

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].

huafu · 2018-12-13T06:55:46Z

@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 · 2018-12-13T20:20:35Z

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

Farbdose · 2018-12-18T12:12:59Z

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 · 2018-12-18T15:44:29Z

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 · 2018-12-19T07:14:41Z

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 · 2018-12-19T10:41:12Z

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.

fruchtose · 2019-01-04T18:02:33Z

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 · 2019-01-07T21:36:24Z

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 · 2019-01-08T12:17:23Z

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.)

dubbha · 2019-02-20T16:10:58Z

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

jensengar · 2019-04-01T20:19:13Z

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.

VicJer · 2019-04-16T16:09:09Z

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 · 2019-04-17T11:22:51Z

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.

camsjams · 2020-03-25T21:34:23Z

Thanks @VicJer that config adjustment worked brilliantly!

ahnpnl · 2020-04-12T16:29:12Z

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 · 2020-04-21T11:20:51Z

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

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 mentioned this issue Dec 12, 2018

ts-jest with cleared cache is reading package.json in node_modules over and over - start takes forever ionic-team/ionic-framework#16703

Closed

ahnpnl mentioned this issue Dec 16, 2018

Tests are running much slower in 7.0.0-alpha.1 with --no-cache thymikee/jest-preset-angular#213

Closed

Farbdose mentioned this issue Dec 20, 2018

new cache for readFile, fileExists, directoryExist, is not working as advertised microsoft/TypeScript#29107

Closed

IOuser added a commit to IOuser/ts-jest that referenced this issue Jan 8, 2019

fix(perf): add cache for fs calls (kulshekhar#908)

ca09996

This was referenced Jan 8, 2019

fix(perf): add cache for fs calls when using language service (#908) #940

Closed

ts-jest 23.xx.xx never finishes during CI tests but 22.xx.xx does #845

Closed

ahnpnl added Help Wanted Performance Severe performance issue labels Mar 17, 2019

wtho mentioned this issue Mar 17, 2019

Huge increase in test time since upgraded to jest 24 and new preset thymikee/jest-preset-angular#242

Closed

4kochi mentioned this issue Apr 2, 2019

There is a new Jest memory leak after updating to v7.7 nrwl/nx#1217

Closed

snyk-bot mentioned this issue Dec 1, 2019

[Snyk] Upgrade ts-jest from 24.1.0 to 24.2.0 ryshu/enib-internships#113

Merged

ahnpnl mentioned this issue Jan 12, 2020

Unit test runs very slow (6 sec per a test) #259

Closed

ahnpnl closed this as completed Apr 12, 2020

duck-nukem mentioned this issue Apr 20, 2020

Jest is 3x slower on all windows machines (Windows 10 and lower) jestjs/jest#7631

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

Farbdose commented Dec 11, 2018 •

edited

Loading

Farbdose commented Dec 12, 2018 •

edited

Loading

huafu commented Dec 13, 2018

ericanderson commented Dec 13, 2018

Farbdose commented Dec 18, 2018

Farbdose commented Dec 18, 2018 •

edited

Loading

Farbdose commented Dec 19, 2018 •

edited

Loading

Farbdose commented Dec 19, 2018 •

edited

Loading

fruchtose commented Jan 4, 2019

AndriiShpak commented Jan 7, 2019 •

edited

Loading

IOuser commented Jan 8, 2019

dubbha commented Feb 20, 2019

jensengar commented Apr 1, 2019

VicJer commented Apr 16, 2019

VicJer commented Apr 17, 2019

camsjams commented Mar 25, 2020

ahnpnl commented Apr 12, 2020

ahnpnl commented Apr 21, 2020

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

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

Comments

Farbdose commented Dec 11, 2018 • edited Loading

Issue:

Expected behavior :

Debug log:

Minimal repo :

Farbdose commented Dec 12, 2018 • edited Loading

huafu commented Dec 13, 2018

ericanderson commented Dec 13, 2018

Farbdose commented Dec 18, 2018

Farbdose commented Dec 18, 2018 • edited Loading

Farbdose commented Dec 19, 2018 • edited Loading

Farbdose commented Dec 19, 2018 • edited Loading

fruchtose commented Jan 4, 2019

AndriiShpak commented Jan 7, 2019 • edited Loading

IOuser commented Jan 8, 2019

dubbha commented Feb 20, 2019

jensengar commented Apr 1, 2019

VicJer commented Apr 16, 2019

VicJer commented Apr 17, 2019

camsjams commented Mar 25, 2020

ahnpnl commented Apr 12, 2020

ahnpnl commented Apr 21, 2020

Farbdose commented Dec 11, 2018 •

edited

Loading

Farbdose commented Dec 12, 2018 •

edited

Loading

Farbdose commented Dec 18, 2018 •

edited

Loading

Farbdose commented Dec 19, 2018 •

edited

Loading

Farbdose commented Dec 19, 2018 •

edited

Loading

AndriiShpak commented Jan 7, 2019 •

edited

Loading