Improve performance tracking

Measure actions when they are actually handled instead of on dispatch
(avoids inconsistencies due to action queue blocking)
Add in depth logging for set-model-command and model update

packages/editor/src/performance/per-set-model-command.ts

@@ -0,0 +1,21 @@
+import { CommandExecutionContext, GModelRoot, SetModelCommand } from '@eclipse-glsp/client';
+import { injectable } from 'inversify';
+
+@injectable()
+export class PerfSetModelCommand extends SetModelCommand {
+  protected counter = 0;
+
+  execute(context: CommandExecutionContext): GModelRoot {
+    const counter = ++this.counter;
+    console.time(`execute SetModelCommand (sc) ${counter}`);
+    console.time(`sc-createOldRoot (${counter})`);
+    this.oldRoot = context.modelFactory.createRoot(context.root);
+    console.timeEnd(`sc-createOldRoot (${counter})`);
+    console.time(`sc-createNewRoot (${counter})`);
+    this.newRoot = context.modelFactory.createRoot(this.action.newRoot);
+    console.timeEnd(`sc-createNewRoot (${counter})`);
+    console.timeEnd(`execute SetModelCommand (sc) ${counter}`);
+
+    return this.newRoot;
+  }
+}

packages/editor/src/performance/perf-action-dispatcher.ts

@@ -14,10 +14,12 @@ export class PerfActionDispatcher extends GLSPActionDispatcher {
     return result;
   }
 
-  override async dispatch(action: Action): Promise<void> {
+  protected override async handleAction(action: Action): Promise<void> {
     const counter = ++this.counter;
-    console.time(`dispatch-${action.kind}-${counter}`);
-    await super.dispatch(action);
-    console.timeEnd(`dispatch-${action.kind}-${counter}`);
+    console.time(`handleAction-${action.kind}-${counter}`);
+    console.log(`handleAction-${action.kind}-${counter}`, action);
+    const result = await super.handleAction(action);
+    console.timeEnd(`handleAction-${action.kind}-${counter}`);
+    return result;
   }
 }

packages/editor/src/performance/perf-diagram-loader.ts

@@ -1,4 +1,12 @@
-import { DiagramLoader, IDiagramStartup, ResolvedDiagramLoadingOptions } from '@eclipse-glsp/client';
+import {
+  ApplicationIdProvider,
+  DiagramLoader,
+  DiagramLoadingOptions,
+  GLSPClient,
+  IDiagramStartup,
+  Ranked,
+  ResolvedDiagramLoadingOptions
+} from '@eclipse-glsp/client';
 import { injectable } from 'inversify';
 
 @injectable()
@@ -20,4 +28,29 @@ export class PerfDiagramLoader extends DiagramLoader {
     await super.requestModel(options);
     console.timeEnd('DiagramLoader.requestModel');
   }
+
+  override async load(options: DiagramLoadingOptions = {}): Promise<void> {
+    this.diagramStartups.sort(Ranked.sort);
+    await this.invokeStartupHook('preLoadDiagram');
+    const resolvedOptions: ResolvedDiagramLoadingOptions = {
+      requestModelOptions: {
+        sourceUri: this.options.sourceUri ?? '',
+        diagramType: this.options.diagramType,
+        ...options.requestModelOptions
+      },
+      initializeParameters: {
+        applicationId: ApplicationIdProvider.get(),
+        protocolVersion: GLSPClient.protocolVersion,
+        ...options.initializeParameters
+      },
+      enableNotifications: options.enableNotifications ?? true
+    };
+    await this.actionDispatcher.initialize();
+    await this.invokeStartupHook('preInitialize');
+    await this.initialize(resolvedOptions);
+    await this.invokeStartupHook('preRequestModel');
+    await this.requestModel(resolvedOptions);
+    await this.invokeStartupHook('postRequestModel');
+    this.modelInitializationConstraint.onInitialized(() => this.invokeStartupHook('postModelInitialization'));
+  }
 }

packages/editor/src/performance/perf-viewer.tsx

@@ -0,0 +1,59 @@
+/** @jsx html */
+// eslint-disable-next-line @typescript-eslint/no-unused-vars
+import { Action, GModelRoot, ModelViewer, copyClassesFromElement, copyClassesFromVNode, html, setClass } from '@eclipse-glsp/client';
+import { injectable } from 'inversify';
+
+@injectable()
+export class PerfModelViewer extends ModelViewer {
+  protected counter = 0;
+  update(model: Readonly<GModelRoot>, cause?: Action): void {
+    const counter = ++this.counter;
+    console.time(`Viewer update (vu) (${counter})`);
+    this.logger.log(this, 'rendering', model);
+    console.time(`vu- renderElement (${counter})`);
+    const newVDOM = <div id={this.options.baseDiv}>{this.renderer.renderElement(model)}</div>;
+    console.timeEnd(`vu- renderElement (${counter})`);
+    if (this.lastVDOM !== undefined) {
+      const hadFocus = this.hasFocus();
+      console.time(`vu- copyClassesFromVNode (${counter})`);
+      copyClassesFromVNode(this.lastVDOM, newVDOM);
+      console.timeEnd(`vu- copyClassesFromVNode (${counter})`);
+      console.time(`vu- patch vdom (${counter})`);
+      this.lastVDOM = this.patcher.call(this, this.lastVDOM, newVDOM);
+      console.timeEnd(`vu- patch vdom (${counter})`);
+      console.time(`vu- restoreFocus (${counter})`);
+      this.restoreFocus(hadFocus);
+      console.timeEnd(`vu- restoreFocus (${counter})`);
+    } else if (typeof document !== 'undefined') {
+      let placeholder = null;
+      if (this.options.shadowRoot) {
+        const shadowRoot = document.getElementById(this.options.shadowRoot)?.shadowRoot;
+        if (shadowRoot) {
+          placeholder = shadowRoot.getElementById(this.options.baseDiv);
+        }
+      } else {
+        placeholder = document.getElementById(this.options.baseDiv);
+      }
+      if (placeholder !== null) {
+        if (typeof window !== 'undefined') {
+          window.addEventListener('resize', () => {
+            this.onWindowResize(newVDOM);
+          });
+        }
+        console.time(`vu- copyClassesFromElement (${counter})`);
+        copyClassesFromElement(placeholder, newVDOM);
+        setClass(newVDOM, this.options.baseClass, true);
+        console.timeEnd(`vu- copyClassesFromElement (${counter})`);
+        console.time(`vu- patch vdom (${counter})`);
+        this.lastVDOM = this.patcher.call(this, placeholder, newVDOM);
+        console.timeEnd(`vu- patch vdom (${counter})`);
+      } else {
+        this.logger.error(this, 'element not in DOM:', this.options.baseDiv);
+      }
+    }
+    console.time(`vu- postUpdate (${counter})`);
+    this.renderer.postUpdate(cause);
+    console.timeEnd(`vu- postUpdate (${counter})`);
+    console.timeEnd(`Viewer update (vu) (${counter})`);
+  }
+}

packages/editor/src/performance/performance-module.ts

@@ -1,7 +1,8 @@
-import { DiagramLoader, FeatureModule, GLSPActionDispatcher, TYPES } from '@eclipse-glsp/client';
+import { DiagramLoader, FeatureModule, GLSPActionDispatcher, SetModelCommand, TYPES } from '@eclipse-glsp/client';
 import { PerfDiagramLoader } from './perf-diagram-loader';
 import { PerfActionDispatcher } from './perf-action-dispatcher';
 import { PerfModelViewer } from './perf-viewer';
+import { PerfSetModelCommand } from './per-set-model-command';
 
 export function createPerformanceModule(enabled?: boolean): FeatureModule {
   return new FeatureModule(
@@ -12,6 +13,7 @@ export function createPerformanceModule(enabled?: boolean): FeatureModule {
       rebind(DiagramLoader).to(PerfDiagramLoader).inSingletonScope();
       rebind(GLSPActionDispatcher).to(PerfActionDispatcher).inSingletonScope();
       rebind(TYPES.ModelViewer).to(PerfModelViewer).inSingletonScope();
+      rebind(SetModelCommand).to(PerfSetModelCommand);
     },
     { featureId: Symbol('performance') }
   );