Perf investigation - Time qgl query (#18911)

Added a new IS_GRAPHQL_QUERY_TIMING_ENABLED feature flag that, when
activated per workspace, logs the execution time and operation name of
every GraphQL query across both the standard Yoga pipeline and the
direct execution fast path. The timing context propagates via
AsyncLocalStorage to also instrument buildColumnsToSelect and
formatResult — giving a breakdown of column selection and result
transformation costs without any caller changes.

packages/twenty-server/src/engine/api/graphql/direct-execution/hooks/use-direct-execution.hook.ts

@@ -1,3 +1,5 @@
+import { Logger } from '@nestjs/common';
+
 import { type Request } from 'express';
 import { DocumentNode, parse } from 'graphql';
 import { type Plugin } from 'graphql-yoga';
@@ -5,12 +7,15 @@ import { FeatureFlagKey } from 'twenty-shared/types';
 
 import { isNull } from '@sniptt/guards';
 import { type DirectExecutionService } from 'src/engine/api/graphql/direct-execution/direct-execution.service';
+import { queryTimingContextStorage } from 'src/engine/core-modules/graphql/storage/query-timing-context.storage';
 import { computeSkipWorkspaceSchemaCreation } from 'src/engine/api/graphql/direct-execution/utils/compute-skip-workspace-schema-creation.util';
 import { findOperationDefinition } from 'src/engine/api/graphql/direct-execution/utils/find-operation-definition.util';
 import { hasOnlyGeneratedWorkspaceResolvers } from 'src/engine/api/graphql/direct-execution/utils/has-only-generated-workspace-resolvers.util';
 import { isSubscriptionOperation } from 'src/engine/api/graphql/direct-execution/utils/is-subscription-operation.util';
 import { type FeatureFlagService } from 'src/engine/core-modules/feature-flag/services/feature-flag.service';
 
+const logger = new Logger('GraphQLQueryTiming');
+
 export type DirectExecutionPluginConfig = {
   directExecutionService: DirectExecutionService;
   featureFlagService: FeatureFlagService;
@@ -27,12 +32,13 @@ export function useDirectExecution(
         return;
       }
 
-      const isEnabled = await config.featureFlagService.isFeatureEnabled(
-        FeatureFlagKey.IS_DIRECT_GRAPHQL_EXECUTION_ENABLED,
-        req.workspace.id,
-      );
+      const isDirectExecutionEnabled =
+        await config.featureFlagService.isFeatureEnabled(
+          FeatureFlagKey.IS_DIRECT_GRAPHQL_EXECUTION_ENABLED,
+          req.workspace.id,
+        );
 
-      if (!isEnabled) {
+      if (!isDirectExecutionEnabled) {
         return;
       }
 
@@ -83,6 +89,33 @@ export function useDirectExecution(
         return;
       }
 
+      const isTimingEnabled = await config.featureFlagService.isFeatureEnabled(
+        FeatureFlagKey.IS_GRAPHQL_QUERY_TIMING_ENABLED,
+        req.workspace.id,
+      );
+
+      const resolvedOperationName = operationName ?? 'Anonymous';
+
+      if (isTimingEnabled) {
+        const startTime = performance.now();
+
+        const timedResult = await queryTimingContextStorage.run(true, () =>
+          config.directExecutionService.execute(req, document),
+        );
+
+        const durationMs = (performance.now() - startTime).toFixed(2);
+
+        logger.log(
+          `[direct-execution] ${resolvedOperationName} — ${durationMs}ms (workspace: ${req.workspace.id})`,
+        );
+
+        if (isNull(timedResult)) {
+          return;
+        }
+
+        return endResponse(Response.json(timedResult));
+      }
+
       const result = await config.directExecutionService.execute(req, document);
 
       if (isNull(result)) {

packages/twenty-server/src/engine/api/graphql/graphql-config/graphql-config.service.ts

@@ -27,6 +27,7 @@ import { FeatureFlagService } from 'src/engine/core-modules/feature-flag/service
 import { useSentryTracing } from 'src/engine/core-modules/exception-handler/hooks/use-sentry-tracing';
 import { useDisableIntrospectionAndSuggestionsForUnauthenticatedUsers } from 'src/engine/core-modules/graphql/hooks/use-disable-introspection-and-suggestions-for-unauthenticated-users.hook';
 import { useGraphQLErrorHandlerHook } from 'src/engine/core-modules/graphql/hooks/use-graphql-error-handler.hook';
+import { useGraphQLQueryTiming } from 'src/engine/core-modules/graphql/hooks/use-graphql-query-timing.hook';
 import { useValidateGraphqlQueryComplexity } from 'src/engine/core-modules/graphql/hooks/use-validate-graphql-query-complexity.hook';
 import { I18nService } from 'src/engine/core-modules/i18n/i18n.service';
 import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service';
@@ -61,6 +62,9 @@ export class GraphQLConfigService
     const isDebugMode =
       this.twentyConfigService.get('NODE_ENV') === NodeEnvironment.DEVELOPMENT;
     const plugins = [
+      useGraphQLQueryTiming({
+        featureFlagService: this.featureFlagService,
+      }),
       useDirectExecution({
         directExecutionService: this.directExecutionService,
         featureFlagService: this.featureFlagService,

packages/twenty-server/src/engine/api/graphql/graphql-query-runner/utils/build-columns-to-select.ts

@@ -1,6 +1,9 @@
+import { Logger } from '@nestjs/common';
+
 import { FieldMetadataType } from 'twenty-shared/types';
 import { isDefined } from 'twenty-shared/utils';
 
+import { isQueryTimingEnabled } from 'src/engine/core-modules/graphql/storage/query-timing-context.storage';
 import { RelationType } from 'src/engine/metadata-modules/field-metadata/interfaces/relation-type.interface';
 
 import { type FlatEntityMaps } from 'src/engine/metadata-modules/flat-entity/types/flat-entity-maps.type';
@@ -10,6 +13,8 @@ import { type FlatFieldMetadata } from 'src/engine/metadata-modules/flat-field-m
 import { isFlatFieldMetadataOfType } from 'src/engine/metadata-modules/flat-field-metadata/utils/is-flat-field-metadata-of-type.util';
 import { type FlatObjectMetadata } from 'src/engine/metadata-modules/flat-object-metadata/types/flat-object-metadata.type';
 
+const logger = new Logger('buildColumnsToSelect');
+
 export const buildColumnsToSelect = ({
   select,
   relations,
@@ -23,6 +28,9 @@ export const buildColumnsToSelect = ({
   flatObjectMetadataMaps: FlatEntityMaps<FlatObjectMetadata>;
   flatFieldMetadataMaps: FlatEntityMaps<FlatFieldMetadata>;
 }) => {
+  const timingEnabled = isQueryTimingEnabled();
+  const startTime = timingEnabled ? performance.now() : 0;
+
   const requiredRelationColumns = getRequiredRelationColumns(
     relations,
     flatObjectMetadata,
@@ -40,7 +48,17 @@ export const buildColumnsToSelect = ({
     fieldsToSelect[columnName] = true;
   }
 
-  return { ...fieldsToSelect, id: true };
+  const result = { ...fieldsToSelect, id: true };
+
+  if (timingEnabled) {
+    const durationMs = (performance.now() - startTime).toFixed(2);
+
+    logger.log(
+      `${flatObjectMetadata.nameSingular} — ${durationMs}ms (${Object.keys(select).length} select, ${flatObjectMetadata.fieldIds.length} fields)`,
+    );
+  }
+
+  return result;
 };
 
 const getRequiredRelationColumns = (

packages/twenty-server/src/engine/api/graphql/metadata-graphql-api.module.ts

@@ -7,6 +7,7 @@ import { GraphQLConfigModule } from 'src/engine/api/graphql/graphql-config/graph
 import { metadataModuleFactory } from 'src/engine/api/graphql/metadata.module-factory';
 import { CacheStorageNamespace } from 'src/engine/core-modules/cache-storage/types/cache-storage-namespace.enum';
 import { ExceptionHandlerService } from 'src/engine/core-modules/exception-handler/exception-handler.service';
+import { FeatureFlagService } from 'src/engine/core-modules/feature-flag/services/feature-flag.service';
 import { I18nModule } from 'src/engine/core-modules/i18n/i18n.module';
 import { I18nService } from 'src/engine/core-modules/i18n/i18n.service';
 import { MetricsModule } from 'src/engine/core-modules/metrics/metrics.module';
@@ -34,6 +35,7 @@ import { MetadataEngineModule } from 'src/engine/metadata-modules/metadata-engin
         CacheStorageNamespace.EngineWorkspace,
         MetricsService,
         I18nService,
+        FeatureFlagService,
       ],
     }),
     MetadataEngineModule,

packages/twenty-server/src/engine/api/graphql/metadata.module-factory.ts

@@ -8,8 +8,10 @@ import { MetadataGraphQLApiModule } from 'src/engine/api/graphql/metadata-graphq
 import { ClientConfig } from 'src/engine/core-modules/client-config/client-config.entity';
 import { type CacheStorageService } from 'src/engine/core-modules/cache-storage/services/cache-storage.service';
 import { type ExceptionHandlerService } from 'src/engine/core-modules/exception-handler/exception-handler.service';
+import { type FeatureFlagService } from 'src/engine/core-modules/feature-flag/services/feature-flag.service';
 import { useDisableIntrospectionAndSuggestionsForUnauthenticatedUsers } from 'src/engine/core-modules/graphql/hooks/use-disable-introspection-and-suggestions-for-unauthenticated-users.hook';
 import { useGraphQLErrorHandlerHook } from 'src/engine/core-modules/graphql/hooks/use-graphql-error-handler.hook';
+import { useGraphQLQueryTiming } from 'src/engine/core-modules/graphql/hooks/use-graphql-query-timing.hook';
 import { useValidateGraphqlQueryComplexity } from 'src/engine/core-modules/graphql/hooks/use-validate-graphql-query-complexity.hook';
 import { type I18nService } from 'src/engine/core-modules/i18n/i18n.service';
 import { type MetricsService } from 'src/engine/core-modules/metrics/metrics.service';
@@ -24,6 +26,7 @@ export const metadataModuleFactory = async (
   cacheStorageService: CacheStorageService,
   metricsService: MetricsService,
   i18nService: I18nService,
+  featureFlagService: FeatureFlagService,
 ): Promise<YogaDriverConfig> => {
   const config: YogaDriverConfig = {
     autoSchemaFile: true,
@@ -37,6 +40,7 @@ export const metadataModuleFactory = async (
     },
     resolvers: { JSON: GraphQLJSON },
     plugins: [
+      useGraphQLQueryTiming({ featureFlagService }),
       useGraphQLErrorHandlerHook({
         metricsService: metricsService,
         exceptionHandlerService,

packages/twenty-server/src/engine/core-modules/graphql/hooks/use-graphql-query-timing.hook.ts

@@ -0,0 +1,63 @@
+import { Logger } from '@nestjs/common';
+
+import { type Plugin } from '@envelop/core';
+import { Kind, type OperationDefinitionNode } from 'graphql';
+import { FeatureFlagKey } from 'twenty-shared/types';
+
+import { type GraphQLContext } from 'src/engine/api/graphql/graphql-config/interfaces/graphql-context.interface';
+import { type FeatureFlagService } from 'src/engine/core-modules/feature-flag/services/feature-flag.service';
+import { queryTimingContextStorage } from 'src/engine/core-modules/graphql/storage/query-timing-context.storage';
+
+type GraphQLQueryTimingOptions = {
+  featureFlagService: FeatureFlagService;
+};
+
+const logger = new Logger('GraphQLQueryTiming');
+
+export const useGraphQLQueryTiming = <PluginContext extends GraphQLContext>(
+  options: GraphQLQueryTimingOptions,
+): Plugin<PluginContext> => {
+  return {
+    async onExecute({ args, executeFn, setExecuteFn }) {
+      const workspaceId = args.contextValue.req?.workspace?.id;
+
+      if (!workspaceId) {
+        return;
+      }
+
+      const isEnabled = await options.featureFlagService.isFeatureEnabled(
+        FeatureFlagKey.IS_GRAPHQL_QUERY_TIMING_ENABLED,
+        workspaceId,
+      );
+
+      if (!isEnabled) {
+        return;
+      }
+
+      const rootOperation = args.document.definitions.find(
+        (definition: { kind: string }) =>
+          definition.kind === Kind.OPERATION_DEFINITION,
+      ) as OperationDefinitionNode | undefined;
+
+      const operationName =
+        args.operationName || rootOperation?.name?.value || 'Anonymous';
+
+      const operationType = rootOperation?.operation ?? 'unknown';
+      const startTime = performance.now();
+
+      setExecuteFn((executeArgs) =>
+        queryTimingContextStorage.run(true, () => executeFn(executeArgs)),
+      );
+
+      return {
+        onExecuteDone() {
+          const durationMs = (performance.now() - startTime).toFixed(2);
+
+          logger.log(
+            `[${operationType}] ${operationName} — ${durationMs}ms (workspace: ${workspaceId})`,
+          );
+        },
+      };
+    },
+  };
+};

packages/twenty-server/src/engine/core-modules/graphql/storage/query-timing-context.storage.ts

@@ -0,0 +1,6 @@
+import { AsyncLocalStorage } from 'async_hooks';
+
+export const queryTimingContextStorage = new AsyncLocalStorage<boolean>();
+
+export const isQueryTimingEnabled = (): boolean =>
+  queryTimingContextStorage.getStore() === true;

packages/twenty-server/src/engine/twenty-orm/entity-manager/workspace-entity-manager.spec.ts

@@ -250,6 +250,7 @@ describe('WorkspaceEntityManager', () => {
         IS_DIRECT_GRAPHQL_EXECUTION_ENABLED: false,
         IS_RECORD_PAGE_LAYOUT_GLOBAL_EDITION_ENABLED: false,
         IS_CONNECTED_ACCOUNT_MIGRATED: false,
+        IS_GRAPHQL_QUERY_TIMING_ENABLED: false,
       },
       userWorkspaceRoleMap: {},
       eventEmitterService: {

packages/twenty-server/src/engine/twenty-orm/utils/format-result.util.ts

@@ -1,3 +1,4 @@
+import { Logger } from '@nestjs/common';
 import { isPlainObject } from '@nestjs/common/utils/shared.utils';
 
 import { isNonEmptyString, isNull } from '@sniptt/guards';
@@ -26,6 +27,10 @@ import { type FlatObjectMetadata } from 'src/engine/metadata-modules/flat-object
 import { getCompositeFieldMetadataCollection } from 'src/engine/twenty-orm/utils/get-composite-field-metadata-collection';
 import { isFieldMetadataEntityOfType } from 'src/engine/utils/is-field-metadata-of-type.util';
 
+import { isQueryTimingEnabled } from 'src/engine/core-modules/graphql/storage/query-timing-context.storage';
+
+const formatResultLogger = new Logger('formatResult');
+
 export function formatResult<T>(
   // oxlint-disable-next-line @typescripttypescript/no-explicit-any
   data: any,
@@ -33,6 +38,36 @@ export function formatResult<T>(
   flatObjectMetadataMaps: FlatEntityMaps<FlatObjectMetadata>,
   flatFieldMetadataMaps: FlatEntityMaps<FlatFieldMetadata>,
   fieldMapsForObject?: FieldMapsForObject,
+): T {
+  const timingEnabled = isQueryTimingEnabled();
+  const startTime = timingEnabled ? performance.now() : 0;
+  const result = formatResultInternal<T>(
+    data,
+    flatObjectMetadata,
+    flatObjectMetadataMaps,
+    flatFieldMetadataMaps,
+    fieldMapsForObject,
+  );
+
+  if (timingEnabled && isDefined(flatObjectMetadata)) {
+    const durationMs = (performance.now() - startTime).toFixed(2);
+    const recordCount = Array.isArray(data) ? data.length : 1;
+
+    formatResultLogger.log(
+      `${flatObjectMetadata.nameSingular} — ${durationMs}ms (${recordCount} records)`,
+    );
+  }
+
+  return result;
+}
+
+function formatResultInternal<T>(
+  // oxlint-disable-next-line @typescripttypescript/no-explicit-any
+  data: any,
+  flatObjectMetadata: FlatObjectMetadata | undefined,
+  flatObjectMetadataMaps: FlatEntityMaps<FlatObjectMetadata>,
+  flatFieldMetadataMaps: FlatEntityMaps<FlatFieldMetadata>,
+  fieldMapsForObject?: FieldMapsForObject,
 ): T {
   if (!isDefined(data)) {
     return data;
@@ -41,7 +76,7 @@ export function formatResult<T>(
   if (!isPlainObject(data)) {
     if (Array.isArray(data)) {
       return data.map((item) =>
-        formatResult(
+        formatResultInternal(
           item,
           flatObjectMetadata,
           flatObjectMetadataMaps,
@@ -93,7 +128,7 @@ export function formatResult<T>(
     if (!compositePropertyArgs && !isRelation) {
       if (isPlainObject(value)) {
         // @ts-expect-error legacy noImplicitAny
-        newData[key] = formatResult(
+        newData[key] = formatResultInternal(
           value,
           flatObjectMetadata,
           flatObjectMetadataMaps,
@@ -130,7 +165,7 @@ export function formatResult<T>(
       }
 
       // @ts-expect-error legacy noImplicitAny
-      newData[key] = formatResult(
+      newData[key] = formatResultInternal(
         value,
         targetObjectMetadata,
         flatObjectMetadataMaps,