add more logging in graph building

finos · Mar 18, 2022 · 05c84ad · 05c84ad
1 parent 59656fd
commit 05c84ad
Show file tree

Hide file tree

Showing 6 changed files with 72 additions and 7 deletions.
diff --git a/.changeset/spicy-rockets-pretend.md b/.changeset/spicy-rockets-pretend.md
@@ -0,0 +1,5 @@
+---
+"@finos/legend-query": patch
+"@finos/legend-server-depot": patch
+"@finos/legend-studio": patch
+---
diff --git a/packages/legend-graph/src/graphManager/GraphManagerLogEvent.ts b/packages/legend-graph/src/graphManager/GraphManagerLogEvent.ts
@@ -19,6 +19,7 @@ export enum GRAPH_MANAGER_LOG_EVENT {
 
   GRAPH_BUILDER_SYSTEM_BUILT = 'GRAPH_BUILDER_SYSTEM_BUILT',
   GRAPH_BUILDER_DEPENDENCIES_PREPROCESSED = 'GRAPH_BUILDER_DEPENDENCIES_PREPROCESSED',
+  GRAPH_BUILDER_DEPENDENCIES_ENTITIES_FETCHED = 'GRAPH_BUILDER_DEPENDENCIES_ENTITIES_FETCHED',
   GRAPH_BUILDER_DEPENDENCIES_PROCESSED = 'GRAPH_BUILDER_DEPENDENCIES_PROCESSED',
   GRAPH_BUILDER_DEPENDENCIES_BUILT = 'GRAPH_BUILDER_DEPENDENCIES_BUILT',
   GRAPH_BUILDER_GENERATIONS_BUILT = 'GRAPH_BUILDER_GENERATIONS_BUILT',

diff --git a/packages/legend-graph/src/models/protocols/pure/v1/V1_PureGraphManager.ts b/packages/legend-graph/src/models/protocols/pure/v1/V1_PureGraphManager.ts
@@ -483,7 +483,7 @@ export class V1_PureGraphManager extends AbstractPureGraphManager {
           LogEvent.create(GRAPH_MANAGER_LOG_EVENT.GRAPH_BUILDER_SYSTEM_BUILT),
           Date.now() - startTime,
           'ms',
-          `[profile: ${systemModel.ownProfiles.length}, enumeration: ${systemModel.ownEnumerations.length}]`,
+          `[class: ${systemModel.ownClasses.length}, profile: ${systemModel.ownProfiles.length}, enumeration: ${systemModel.ownEnumerations.length}, [TOTAL]: ${systemModel.allOwnElements.length}]`,
         );
       }
       systemModel.buildState.pass();
@@ -510,6 +510,18 @@ export class V1_PureGraphManager extends AbstractPureGraphManager {
     options?: GraphBuilderOptions,
   ): GeneratorFn<void> {
     const startTime = Date.now();
+    if (!options?.quiet) {
+      this.log.info(
+        LogEvent.create(
+          GRAPH_MANAGER_LOG_EVENT.GRAPH_BUILDER_DEPENDENCIES_ENTITIES_FETCHED,
+        ),
+        Date.now() - startTime,
+        'ms',
+        `[projects: ${dependencyEntitiesMap.size}, entities: ${
+          Array.from(dependencyEntitiesMap.values()).flat().length
+        }]`,
+      );
+    }
     dependencyManager.buildState.reset();
     // Create a dummy graph for system processing. This is to ensure dependency models do not depend on the main graph
     const graph = new PureModel(
@@ -595,6 +607,18 @@ export class V1_PureGraphManager extends AbstractPureGraphManager {
           Date.now() - startTime,
           'ms',
         );
+        this.log.info(
+          LogEvent.create(
+            GRAPH_MANAGER_LOG_EVENT.GRAPH_BUILDER_DEPENDENCIES_BUILT,
+          ),
+          Date.now() - startTime,
+          'ms',
+          `[elements: ${
+            Array.from(dependencyManager.projectDependencyModelsIndex.values())
+              .map((v) => v.allOwnElements)
+              .flat().length
+          }]`,
+        );
       }
     } catch (error) {
       assertErrorThrown(error);

diff --git a/packages/legend-query/src/stores/LegendQueryStore.ts b/packages/legend-query/src/stores/LegendQueryStore.ts
@@ -80,6 +80,7 @@ import {
 import type { LegendQueryPluginManager } from '../application/LegendQueryPluginManager';
 import type { LegendQueryConfig } from '../application/LegendQueryConfig';
 import { LegendQueryEventNotifierService } from './LegendQueryEventNotifierService';
+import { DEPOT_SERVER_LOG_EVENT } from '@finos/legend-server-depot/src/DepotServerClient';
 
 export abstract class QueryInfoState {
   queryStore: LegendQueryStore;
@@ -716,11 +717,15 @@ export class LegendQueryStore {
     }
   }
 
-  *buildGraph(project: ProjectData, versionId: string): GeneratorFn<void> {
+  *buildGraph(
+    project: ProjectData,
+    versionId: string,
+    options?: { quiet?: boolean },
+  ): GeneratorFn<void> {
     try {
       this.buildGraphState.inProgress();
       let entities: Entity[] = [];
-
+      const startTime = Date.now();
       if (versionId === SNAPSHOT_VERSION_ALIAS) {
         entities = (yield this.depotServerClient.getLatestRevisionEntities(
           project.groupId,
@@ -735,7 +740,15 @@ export class LegendQueryStore {
             : versionId,
         )) as Entity[];
       }
-
+      if (!options?.quiet) {
+        this.graphManagerState.graphManager.log.info(
+          LogEvent.create(
+            DEPOT_SERVER_LOG_EVENT.DEPENDENCY_ENTITIES_FETCH,
+          ),
+          Date.now() - startTime,
+          'ms',
+        );
+      }
       this.graphManagerState.resetGraph();
       // build dependencies
       const dependencyManager =
@@ -746,7 +759,7 @@ export class LegendQueryStore {
           this.graphManagerState.systemModel,
           dependencyManager,
           (yield flowResult(
-            this.getProjectDependencyEntities(project, versionId),
+            this.getProjectDependencyEntities(project, versionId, options),
           )) as Map<string, Entity[]>,
         ),
       );
@@ -774,10 +787,12 @@ export class LegendQueryStore {
   *getProjectDependencyEntities(
     project: ProjectData,
     versionId: string,
+    options?: { quiet?: boolean},
   ): GeneratorFn<Map<string, Entity[]>> {
     this.buildGraphState.inProgress();
     const dependencyEntitiesMap = new Map<string, Entity[]>();
     try {
+      const startTime = Date.now();
       let dependencyEntitiesJson: PlainObject<ProjectVersionEntities>[] = [];
       if (versionId === SNAPSHOT_VERSION_ALIAS) {
         dependencyEntitiesJson =
@@ -799,6 +814,13 @@ export class LegendQueryStore {
             false,
           )) as PlainObject<ProjectVersionEntities>[];
       }
+      if (!options?.quiet) {
+        this.graphManagerState.graphManager.log.info(
+          LogEvent.create(DEPOT_SERVER_LOG_EVENT.DEPENDENCY_ENTITIES_FETCH),
+          Date.now() - startTime,
+          'ms',
+        );
+      }
       dependencyEntitiesJson
         .map((e) => ProjectVersionEntities.serialization.fromJson(e))
         .forEach((dependencyInfo) => {

diff --git a/packages/legend-server-depot/src/DepotServerClient.ts b/packages/legend-server-depot/src/DepotServerClient.ts
@@ -29,6 +29,10 @@ export interface DepotServerClientConfig {
   TEMPORARY__useLegacyDepotServerAPIRoutes?: boolean | undefined;
 }
 
+export enum DEPOT_SERVER_LOG_EVENT {
+  DEPENDENCY_ENTITIES_FETCH = 'DEPENDENCY_ENTITIES_FETCH',
+}
+
 export class DepotServerClient extends AbstractServerClient {
   private TEMPORARY__useLegacyDepotServerAPIRoutes = false;
 

diff --git a/packages/legend-studio/src/stores/EditorGraphState.ts b/packages/legend-studio/src/stores/EditorGraphState.ts
@@ -93,6 +93,7 @@ import {
 } from '@finos/legend-application';
 import { CONFIGURATION_EDITOR_TAB } from './editor-state/ProjectConfigurationEditorState';
 import type { DSLMapping_LegendStudioPlugin_Extension } from './DSLMapping_LegendStudioPlugin_Extension';
+import { DEPOT_SERVER_LOG_EVENT } from '@finos/legend-server-depot/src/DepotServerClient';
 
 export enum GraphBuilderStatus {
   SUCCEEDED = 'SUCCEEDED',
@@ -960,7 +961,7 @@ export class EditorGraphState {
     }
   }
 
-  *getConfigurationProjectDependencyEntities(): GeneratorFn<
+  *getConfigurationProjectDependencyEntities(options?: { quiet?: boolean}): GeneratorFn<
     Map<string, Entity[]>
   > {
     const dependencyEntitiesMap = new Map<string, Entity[]>();
@@ -974,6 +975,7 @@ export class EditorGraphState {
             currentConfiguration.projectDependencies,
           ),
         )) as ProjectDependencyCoordinates[];
+        const startTime = Date.now();
         // NOTE: if A@v1 is transitive dependencies of 2 or more
         // direct dependencies, metadata server will take care of deduplication
         const dependencyEntitiesJson =
@@ -984,6 +986,13 @@ export class EditorGraphState {
             true,
             true,
           )) as PlainObject<ProjectVersionEntities>[];
+          if (!options?.quiet) {
+          this.editorStore.applicationStore.log.info(
+            LogEvent.create(DEPOT_SERVER_LOG_EVENT.DEPENDENCY_ENTITIES_FETCH),
+            Date.now() - startTime,
+            'ms',
+          );
+        }
         const dependencyEntities = dependencyEntitiesJson.map((e) =>
           ProjectVersionEntities.serialization.fromJson(e),
         );
@@ -1090,7 +1099,7 @@ export class EditorGraphState {
    * methods here so that we can load plugins.
    */
 
-  getPackageableElementType(element: PackageableElement): string {
+   getPackageableElementType(element: PackageableElement): string {
     if (element instanceof PrimitiveType) {
       return PACKAGEABLE_ELEMENT_TYPE.PRIMITIVE;
     } else if (element instanceof Package) {