[quality][preferences] Reduce the number of fired preference change events at app startup

[kittaakos]

I started to look into the electron issue as described in #5284.

My previous investigations took me to the fileSystemWatcher.watchFileChanges(uri) call when setting the workspace root. This is important, I have experienced the startup time issue when a workspace was set. I have tested with the Theia source as the workspace root.

I adding the following "logging" to the watcher:

diff --git a/packages/filesystem/src/browser/filesystem-watcher.ts b/packages/filesystem/src/browser/filesystem-watcher.ts
index bd806d167..45e2f047b 100644
--- a/packages/filesystem/src/browser/filesystem-watcher.ts
+++ b/packages/filesystem/src/browser/filesystem-watcher.ts
@@ -184,7 +184,9 @@ export class FileSystemWatcher implements Disposable {
     }
 
     protected async getIgnored(uri: string): Promise<string[]> {
+        console.time('getIgnored' + uri);
         const patterns = this.preferences.get('files.watcherExclude', undefined, uri);
+        console.timeEnd('getIgnored' + uri);
         return Object.keys(patterns).filter(pattern => patterns[pattern]);
     }

I got the following outut:

filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/.theia: 0.131103515625ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/.theia: 0.0419921875ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia: 8401.737060546875ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia/.theia/tasks.json: 0.676025390625ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia: 0.3330078125ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia: 0.105224609375ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia/.theia/launch.json: 0.211181640625ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia/.theia/settings.json: 0.535888671875ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia/.vscode/launch.json: 0.21826171875ms
filesystem-watcher.ts:189 getIgnoredfile:///Users/akos.kitta/git/theia/.vscode/settings.json: 0.244873046875ms

You can see the ~8 sec time. This is mentioned in #5284 and most likely the same as

I applied the following changes on the peferences service:

diff --git a/packages/core/src/browser/preferences/preference-service.ts b/packages/core/src/browser/preferences/preference-service.ts
index a97ca7ad3..bc42be3d7 100644
--- a/packages/core/src/browser/preferences/preference-service.ts
+++ b/packages/core/src/browser/preferences/preference-service.ts
@@ -137,6 +137,7 @@ export class PreferenceServiceImpl implements PreferenceService, FrontendApplica
     }
 
     protected readonly _ready = new Deferred<void>();
+    protected counter = 0;
     get ready(): Promise<void> {
         return this._ready.promise;
     }
@@ -283,13 +284,20 @@ export class PreferenceServiceImpl implements PreferenceService, FrontendApplica
         configUri?: URI,
         value?: T
     } {
+        if (++this.counter % 100 === 0) {
+            console.warn('Resolve called ' + this.counter + ' times');
+        }
+        const now = performance.now();
         const { value, configUri } = this.doResolve(preferenceName, defaultValue, resourceUri);
         if (value === undefined) {
             const overriden = this.overridenPreferenceName(preferenceName);
             if (overriden) {
-                return this.doResolve(overriden.preferenceName, defaultValue, resourceUri);
+                const x = this.doResolve(overriden.preferenceName, defaultValue, resourceUri);
+                // console.warn('PreferenceServiceImpl#resolve' + preferenceName + '-' + (resourceUri || '') + ' took: ' + (performance.now() - now));
+                return x;
             }
         }
+        // console.warn('PreferenceServiceImpl#resolve' + preferenceName + '-' + (resourceUri || '') + ' took: ' + (performance.now() - now));
         return { value, configUri };
     }

This led me to this output:

Akoss-MacBook-Pro:theia akos.kitta$ yarn --cwd ./examples/electron/ start
yarn run v1.16.0
$ theia start --plugins=local-dir:../../plugins
root INFO Theia app listening on http://localhost:65319.
root INFO Git askpass helper is listening on http://127.0.0.1:65322.
root INFO Using Git [2.20.1] from the PATH. (/usr/local/bin/git)
root WARN Resolve called 200 times
root WARN Resolve called 300 times
root WARN Resolve called 400 times
root WARN Resolve called 500 times
root INFO [nsfw-watcher: 96772] Started watching: /Users/akos.kitta/.theia
root WARN Resolve called 600 times
root WARN Resolve called 700 times
root WARN Resolve called 800 times
root WARN Resolve called 900 times
root WARN Resolve called 1000 times
root WARN Resolve called 1100 times
root WARN Resolve called 1200 times
root WARN Resolve called 1300 times
root WARN Resolve called 1400 times
root WARN Resolve called 1500 times
root WARN Resolve called 1600 times
root WARN Resolve called 1700 times
root WARN Resolve called 1800 times
root WARN Resolve called 1900 times
root WARN Resolve called 2000 times
root WARN Resolve called 2100 times
root WARN Resolve called 2200 times
root WARN Resolve called 2300 times
root WARN Resolve called 2400 times
root WARN Resolve called 2500 times
root WARN Resolve called 2600 times
root WARN Resolve called 2700 times
root WARN Resolve called 2800 times
root WARN Resolve called 2900 times
root WARN Resolve called 3000 times
root WARN Resolve called 3100 times
root WARN Resolve called 3200 times
root WARN Resolve called 3300 times
root WARN Resolve called 3400 times
root WARN Resolve called 3500 times
root WARN Resolve called 3600 times
root WARN LanguagesFrontendContribution.onStart is slow, took: 139.10000000032596 ms
root INFO [nsfw-watcher: 96772] Started watching: /Users/akos.kitta/.theia
root INFO [nsfw-watcher: 96772] Started watching: /Users/akos.kitta/git/theia
root WARN Resolve called 3700 times
root WARN Resolve called 3800 times
root WARN Resolve called 3900 times
root WARN Resolve called 4000 times
root WARN Resolve called 4100 times
root WARN Resolve called 4200 times
root WARN Resolve called 4300 times
root WARN Resolve called 4400 times
root WARN Resolve called 4500 times
root WARN Resolve called 4600 times
root WARN Resolve called 4700 times
root WARN Resolve called 4800 times
root WARN Resolve called 4900 times
root WARN Resolve called 5000 times
root WARN Resolve called 5100 times
root WARN Resolve called 5200 times
root WARN Resolve called 5300 times
root WARN Resolve called 5400 times
root WARN Resolve called 5500 times
root WARN Resolve called 5600 times
root WARN Resolve called 5700 times
root WARN Resolve called 5800 times
root WARN Resolve called 5900 times
root WARN Resolve called 6000 times
root WARN Resolve called 6100 times
root WARN Resolve called 6200 times
root WARN Resolve called 6300 times
root WARN Resolve called 6400 times
root WARN Resolve called 6500 times
root WARN Resolve called 6600 times
root WARN Resolve called 6700 times
root WARN Resolve called 6800 times
root WARN Resolve called 6900 times
root WARN Resolve called 7000 times
root WARN Resolve called 7100 times
root WARN Resolve called 7200 times
root WARN Resolve called 7300 times
root WARN Resolve called 7400 times
root WARN Resolve called 7500 times
root WARN Resolve called 7600 times
root WARN Resolve called 7700 times
root WARN Resolve called 7800 times
root WARN Resolve called 7900 times
root WARN Resolve called 8000 times
root WARN Resolve called 8100 times
root WARN Resolve called 8200 times
root WARN Resolve called 8300 times
root WARN Resolve called 8400 times
root WARN Resolve called 8500 times
root WARN Resolve called 8600 times
root WARN Resolve called 8700 times
root WARN Resolve called 8800 times
root WARN Resolve called 8900 times
root WARN Resolve called 9000 times
root WARN Resolve called 9100 times
root WARN Resolve called 9200 times
root WARN Resolve called 9300 times
root WARN Resolve called 9400 times
root WARN Resolve called 9500 times
root WARN Resolve called 9600 times
root WARN Resolve called 9700 times
root WARN Resolve called 9800 times
root WARN Resolve called 9900 times
root WARN Resolve called 10000 times
root WARN Resolve called 10100 times
root WARN Resolve called 10200 times
root WARN Resolve called 10300 times
root WARN Resolve called 10400 times
root WARN Resolve called 10500 times
root WARN Resolve called 10600 times
root WARN Resolve called 10700 times
root WARN Resolve called 10800 times
root INFO [nsfw-watcher: 96772] Stopped watching: /Users/akos.kitta/.theia
root WARN Resolve called 10900 times
root WARN Resolve called 11000 times
root WARN Resolve called 11100 times
root WARN Resolve called 11200 times
root WARN Resolve called 11300 times
root WARN Resolve called 11400 times
root WARN Resolve called 11500 times
root WARN Resolve called 11600 times
root WARN Resolve called 11700 times
root WARN Resolve called 11800 times
root WARN Resolve called 11900 times
root WARN Resolve called 12000 times
root WARN Resolve called 12100 times
root WARN Resolve called 12200 times
root WARN Resolve called 12300 times
root WARN Resolve called 12400 times
root WARN Resolve called 12500 times
root WARN Resolve called 12600 times
root WARN Resolve called 12700 times
root WARN Resolve called 12800 times
root WARN Resolve called 12900 times
root WARN Resolve called 13000 times
root WARN Resolve called 13100 times
root WARN Resolve called 13200 times
root WARN Resolve called 13300 times
root WARN Resolve called 13400 times
root WARN Resolve called 13500 times
root WARN Resolve called 13600 times
root WARN Resolve called 13700 times
root WARN Resolve called 13800 times
root WARN Resolve called 13900 times
root WARN Resolve called 14000 times
root WARN Resolve called 14100 times
root WARN Resolve called 14200 times
root WARN Resolve called 14300 times
root WARN Resolve called 14400 times
root WARN Resolve called 14500 times
root WARN Resolve called 14600 times
root WARN Resolve called 14700 times
root WARN Resolve called 14800 times
root WARN Resolve called 14900 times
root WARN Resolve called 15000 times
root WARN Resolve called 15100 times
root WARN Resolve called 15200 times
root WARN Resolve called 15300 times
root WARN Resolve called 15400 times
root WARN Resolve called 15500 times
root WARN Resolve called 15600 times
root WARN Resolve called 15700 times
root WARN Resolve called 15800 times
root WARN Resolve called 15900 times
root WARN Resolve called 16000 times
root WARN Resolve called 16100 times
root WARN Resolve called 16200 times
root WARN Resolve called 16300 times
root WARN Resolve called 16400 times
root WARN Resolve called 16500 times
root WARN Resolve called 16600 times
root WARN Resolve called 16700 times
root WARN Resolve called 16800 times
root WARN Resolve called 16900 times
root WARN Resolve called 17000 times
root WARN Resolve called 17100 times
root WARN Resolve called 17200 times
root WARN Resolve called 17300 times
root WARN Resolve called 17400 times
root WARN Resolve called 17500 times
root WARN Resolve called 17600 times
root WARN Resolve called 17700 times
root WARN EditorNavigationContribution.onStart is slow, took: 8542.300000000978 ms
root INFO [nsfw-watcher: 96772] Started watching: /Users/akos.kitta/git/theia
Started watching: /Users/akos.kitta/git/theia
root INFO Checking whether '--no-optional-locks' can be used with the current Git executable. Minimum required version is '2.15.0'.
root INFO '--no-optional-locks' is a valid Git option for the current Git version: '2.20.1'.
root INFO Config file tasks.json does not exist under file:///Users/akos.kitta/git/theia
root INFO [nsfw-watcher: 96772] Started watching: /Users/akos.kitta/git/theia/.theia/settings.json
Started watching: /Users/akos.kitta/git/theia/.vscode/launch.json
Started watching: /Users/akos.kitta/git/theia/.vscode/settings.json
root WARN Resolve called 17800 times
root WARN Resolve called 17900 times
root WARN Resolve called 18000 times
root WARN Resolve called 18100 times
root WARN Resolve called 18200 times
root WARN Resolve called 18300 times
root WARN Resolve called 18400 times
root WARN Resolve called 18500 times
root WARN Resolve called 18600 times
root WARN Resolve called 18700 times
root WARN Resolve called 18800 times
root WARN Resolve called 18900 times
root WARN Resolve called 19000 times
root WARN Resolve called 19100 times
root WARN Resolve called 19200 times
root WARN Resolve called 19300 times
root WARN Resolve called 19400 times
root WARN Resolve called 19500 times
root WARN Resolve called 19600 times
root WARN Resolve called 19700 times
root WARN Resolve called 19800 times
root WARN Resolve called 19900 times
root WARN Resolve called 20000 times
root WARN Resolve called 20100 times
root WARN Resolve called 20200 times
root WARN Resolve called 20300 times
root WARN Resolve called 20400 times
root WARN Resolve called 20500 times
root WARN Resolve called 20600 times
root WARN Resolve called 20700 times
root WARN Resolve called 20800 times
root WARN Resolve called 20900 times
root WARN Resolve called 21000 times
root WARN Resolve called 21100 times
root WARN Resolve called 21200 times
root WARN Resolve called 21300 times
root WARN Resolve called 21400 times
root WARN Resolve called 21500 times
root WARN Resolve called 21600 times
root WARN Resolve called 21700 times
root WARN Resolve called 21800 times
root WARN Resolve called 21900 times
root WARN Resolve called 22000 times
root WARN Resolve called 22100 times
root WARN Resolve called 22200 times
root WARN Resolve called 22300 times
root WARN Resolve called 22400 times
root WARN Resolve called 22500 times
root WARN Resolve called 22600 times
root WARN Resolve called 22700 times
root WARN Resolve called 22800 times
root WARN Resolve called 22900 times
root WARN Resolve called 23000 times
root WARN Resolve called 23100 times
root WARN Resolve called 23200 times
root WARN Resolve called 23300 times
root WARN Resolve called 23400 times
root WARN Resolve called 23500 times
root WARN Resolve called 23600 times
root WARN Resolve called 23700 times
root WARN Resolve called 23800 times
root WARN Resolve called 23900 times
root WARN Resolve called 24000 times
root WARN Resolve called 24100 times
root WARN Resolve called 24200 times
root WARN Resolve called 24300 times
root WARN Resolve called 24400 times
root WARN Resolve called 24500 times
root WARN Resolve called 24600 times
root WARN Resolve called 24700 times
root WARN Resolve called 24800 times
root WARN "tslint.enable" preference is not supported
root WARN "search.exclude" preference is not supported
root WARN "lcov.path" preference is not supported
root WARN "lcov.watch" preference is not supported
root WARN "files.insertFinalNewline" preference is not supported
root WARN Resolve called 24900 times
root WARN Resolve called 25000 times
root INFO Started watching the git repository: file:///Users/akos.kitta/git/theia
root WARN Resolve called 25100 times
root WARN Resolve called 25200 times
root WARN Resolve called 25300 times
root WARN Resolve called 25400 times
root WARN Resolve called 25500 times
root WARN Resolve called 25600 times
root WARN Resolve called 25700 times
root WARN Resolve called 25800 times
root WARN Resolve called 25900 times
root WARN Resolve called 26000 times
root WARN Resolve called 26100 times
root WARN Resolve called 26200 times
root WARN Resolve called 26300 times
root WARN Resolve called 26400 times
root WARN Resolve called 26500 times
root WARN Resolve called 26600 times
root WARN Resolve called 26700 times
root WARN Resolve called 26800 times
root WARN Resolve called 26900 times
root WARN Resolve called 27000 times
root WARN Resolve called 27100 times
root WARN Resolve called 27200 times
root WARN Resolve called 27300 times
root WARN Resolve called 27400 times
root WARN Resolve called 27500 times
root WARN Resolve called 27600 times
root WARN Resolve called 27700 times
root WARN Resolve called 27800 times
root WARN Resolve called 27900 times
root WARN Resolve called 28000 times
root WARN Resolve called 28100 times
root WARN Resolve called 28200 times
root WARN Resolve called 28300 times
root WARN Resolve called 28400 times
root INFO Stopped watching the git repository: file:///Users/akos.kitta/git/theia
root INFO Started watching the git repository: file:///Users/akos.kitta/git/theia
root INFO Stopped watching the git repository: file:///Users/akos.kitta/git/theia
root INFO Started watching the git repository: file:///Users/akos.kitta/git/theia

If you uncomment the per preference logging, you can see same preference is accessed multiple times. I am not sure if this is expected or not. I am not yet sure if this is the real cause of the performance problem, but probably we should not resolve the preferences ~28k times.

[kittaakos]

not yet sure if this is the real cause

No, it wasn't. See: #5386

[kittaakos]

The 28k resolve call is more or less legit considering the fact we have 3,5k preference change values for the "extension" languages only. Still, we should try to make it a bit more relaxed.

[akosyakov]

It would be good to know what is the total time of 28k calls and whether it is a bottleneck relatively to the total startup time before proceeding.

[kittaakos]

Closed via #6172.