[IMP] model: add a bit of tracing

When opening a spreadsheet, it is often usefull to have an idea
of how long things take.
In this commit, I use console.info to log loading information, as well
as dispatching times.

closes #4132

Task: 3893683
Signed-off-by: Pierre Rousseau (pro) <pro@odoo.com>

src/collaborative/session.ts

@@ -149,11 +149,17 @@ export class Session extends EventBus<CollaborativeEvent> {
   }
 
   loadInitialMessages(messages: StateUpdateMessage[]) {
+    const start = performance.now();
+    const numberOfCommands = messages.reduce(
+      (acc, message) => acc + (message.type === "REMOTE_REVISION" ? message.commands.length : 1),
+      0
+    );
     this.isReplayingInitialRevisions = true;
     for (const message of messages) {
       this.onMessageReceived(message);
     }
     this.isReplayingInitialRevisions = false;
+    console.info("Replayed", numberOfCommands, "commands in", performance.now() - start, "ms");
   }
 
   /**

src/migrations/data.ts

@@ -40,6 +40,8 @@ export function load(data?: any, verboseImport?: boolean): WorkbookData {
   if (!data) {
     return createEmptyWorkbookData();
   }
+  console.group("Loading data");
+  const start = performance.now();
   if (data["[Content_Types].xml"]) {
     const reader = new XlsxReader(data);
     data = reader.convertXlsx();
@@ -53,10 +55,13 @@ export function load(data?: any, verboseImport?: boolean): WorkbookData {
   // apply migrations, if needed
   if ("version" in data) {
     if (data.version < CURRENT_VERSION) {
+      console.info("Migrating data from version", data.version);
       data = migrate(data);
     }
   }
   data = repairData(data);
+  console.info("Data loaded in", performance.now() - start, "ms");
+  console.groupEnd();
   return data;
 }
 
@@ -72,11 +77,12 @@ interface Migration {
 }
 
 function migrate(data: any): WorkbookData {
+  const start = performance.now();
   const index = MIGRATIONS.findIndex((m) => m.from === data.version);
   for (let i = index; i < MIGRATIONS.length; i++) {
     data = MIGRATIONS[i].applyMigration(data);
   }
-
+  console.info("Data migrated in", performance.now() - start, "ms");
   return data;
 }
 

src/model.ts

@@ -193,6 +193,8 @@ export class Model extends EventBus<any> implements CommandDispatcher {
     uuidGenerator: UuidGenerator = new UuidGenerator(),
     verboseImport = true
   ) {
+    const start = performance.now();
+    console.group("Model creation");
     super();
 
     stateUpdateMessages = repairInitialMessages(data, stateUpdateMessages);
@@ -281,12 +283,17 @@ export class Model extends EventBus<any> implements CommandDispatcher {
     this.joinSession();
 
     if (config.snapshotRequested) {
+      const startSnapshot = performance.now();
+      console.info("Snapshot requested");
       this.session.snapshot(this.exportData());
       this.garbageCollectExternalResources();
+      console.info("Snapshot taken in", performance.now() - startSnapshot, "ms");
     }
     // mark all models as "raw", so they will not be turned into reactive objects
     // by owl, since we do not rely on reactivity
     markRaw(this);
+    console.info("Model created in", performance.now() - start, "ms");
+    console.groupEnd();
   }
 
   joinSession() {
@@ -523,11 +530,16 @@ export class Model extends EventBus<any> implements CommandDispatcher {
         }
         this.status = Status.Running;
         const { changes, commands } = this.state.recordChanges(() => {
+          const start = performance.now();
           if (isCoreCommand(command)) {
             this.state.addCommand(command);
           }
           this.dispatchToHandlers(this.handlers, command);
           this.finalize();
+          const time = performance.now() - start;
+          if (time > 5) {
+            console.info(type, time, "ms");
+          }
         });
         this.session.save(command, commands, changes);
         this.status = Status.Ready;

src/plugins/ui_core_views/cell_evaluation/evaluator.ts

@@ -112,13 +112,15 @@ export class Evaluator {
   }
 
   evaluateCells(positions: CellPosition[]) {
+    const start = performance.now();
     const cellsToCompute = this.createEmptyPositionSet();
     cellsToCompute.addMany(positions);
     const arrayFormulasPositions = this.getArrayFormulasImpactedByChangesOf(positions);
     cellsToCompute.addMany(this.getCellsDependingOn(positions));
     cellsToCompute.addMany(arrayFormulasPositions);
     cellsToCompute.addMany(this.getCellsDependingOn(arrayFormulasPositions));
     this.evaluate(cellsToCompute);
+    console.info("evaluate Cells", performance.now() - start, "ms");
   }
 
   private getArrayFormulasImpactedByChangesOf(
@@ -161,8 +163,10 @@ export class Evaluator {
   }
 
   evaluateAllCells() {
+    const start = performance.now();
     this.evaluatedCells = new PositionMap();
     this.evaluate(this.getAllCells());
+    console.info("evaluate all cells", performance.now() - start, "ms");
   }
 
   evaluateFormula(sheetId: UID, formulaString: string): CellValue | Matrix<CellValue> {

tests/setup/jest.setup.ts

@@ -32,6 +32,10 @@ beforeAll(() => {
       this.innerHTML = value;
     },
   });
+
+  console.info = () => {};
+  console.group = () => {};
+  console.groupEnd = () => {};
 });
 
 beforeEach(() => {