[4338] Improve the information available to debug performance issues

Bug: #4338 Signed-off-by: Stéphane Bégaudeau <[email protected]>
eclipse-sirius · Jan 2, 2025 · e561110 · e561110
1 parent 4b778e9
commit e561110
Show file tree

Hide file tree

Showing 11 changed files with 143 additions and 21 deletions.
diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc
@@ -22,6 +22,13 @@
 
 === New Features
 
+- https://github.com/eclipse-sirius/sirius-web/issues/4338[#4338] [core] A Spring log group dedicated to performance issues has been created.
+As a result, one can use `logging.level.sirius.web.performance=DEBUG` in order to display key performance metrics in a Sirius Web instance.
+Some log messages have been updated in order to provide more information and make them easier to read to idenfity key performance issues.
+The configuration property `sirius.web.graphql.tracing` has also been added to active the tracing mode of the GraphQL API.
+It can be activated using `sirius.web.graphql.tracing=true` since it is not enabled by default to not have any impact on the performance of the application.
+Some additional log has also been contributed on the frontend in order to view more easily the order and time of the GraphQL requests and responses.
+
 
 === Improvements
 

diff --git a/doc/how-to/debug-performance-related-issues.adoc b/doc/how-to/debug-performance-related-issues.adoc
@@ -0,0 +1,9 @@
+= How to debug performance related issues
+
+== Backend
+
+In order to activate the log dedicated to performance measurement, you should use the configuration property `logging.level.sirius.web.performance=DEBUG`.
+Once activated it will also log all AQL expressions taking more than 200ms to execute.
+
+On top of that, it is recommended to debug performance issues to activate the GraphQL tracing support to find the time taken by each datafetcher.
+It can be done using the configuration property `sirius.web.graphql.tracing=true`.
diff --git a/.../eclipse/sirius/components/collaborative/editingcontext/EditingContextEventProcessor.java b/.../eclipse/sirius/components/collaborative/editingcontext/EditingContextEventProcessor.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2019, 2024 Obeo.
+ * Copyright (c) 2019, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -82,6 +82,8 @@ public class EditingContextEventProcessor implements IEditingContextEventProcess
 
     public static final String INPUT = "INPUT";
 
+    private static final String LOG_TIMING_FORMAT = "%1$6s";
+
     private final Logger logger = LoggerFactory.getLogger(EditingContextEventProcessor.class);
 
     private final ICollaborativeMessageService messageService;
@@ -161,7 +163,19 @@ private Disposable setupChangeDescriptionSinkConsumer() {
             if (representationEventProcessorEntry != null) {
                 try {
                     IRepresentationEventProcessor representationEventProcessor = representationEventProcessorEntry.getRepresentationEventProcessor();
+
+                    long start = System.currentTimeMillis();
                     representationEventProcessor.refresh(changeDescription);
+                    long end = System.currentTimeMillis();
+
+                    this.logger.atDebug()
+                            .setMessage("EditingContext {}: {}ms to refresh the {} with id {}")
+                            .addArgument(this.editingContext.getId())
+                            .addArgument(() -> String.format(LOG_TIMING_FORMAT, end - start))
+                            .addArgument(representationEventProcessor.getClass().getSimpleName())
+                            .addArgument(representationEventProcessor.getRepresentation().getId())
+                            .log();
+
                     IRepresentation representation = representationEventProcessor.getRepresentation();
                     this.applicationEventPublisher.publishEvent(new RepresentationRefreshedEvent(this.editingContext.getId(), representation));
                 } catch (Exception exception) {
@@ -267,6 +281,7 @@ public Mono<IPayload> handle(IInput input) {
      */
     private void doHandle(One<IPayload> payloadSink, IInput input) {
         this.logger.trace("Input received: {}", input);
+        long start = System.currentTimeMillis();
 
         AtomicReference<IInput> inputAfterPreProcessing = new AtomicReference<>(input);
         this.inputPreProcessors.forEach(preProcessor -> inputAfterPreProcessing.set(preProcessor.preProcess(this.editingContext, inputAfterPreProcessing.get(), this.changeDescriptionSink)));
@@ -279,6 +294,14 @@ private void doHandle(One<IPayload> payloadSink, IInput input) {
 
         this.inputPostProcessors.forEach(postProcessor -> postProcessor.postProcess(this.editingContext, inputAfterPreProcessing.get(), this.changeDescriptionSink));
 
+        long end = System.currentTimeMillis();
+        this.logger.atDebug()
+                .setMessage("EditingContext {}: {}ms to handle the {} with id {}")
+                .addArgument(this.editingContext.getId())
+                .addArgument(() -> String.format(LOG_TIMING_FORMAT, end - start))
+                .addArgument(input.getClass().getSimpleName())
+                .addArgument(input.id())
+                .log();
     }
 
     /**
@@ -293,7 +316,18 @@ private void refreshOtherRepresentations(ChangeDescription changeDescription) {
             .map(Entry::getValue)
             .map(RepresentationEventProcessorEntry::getRepresentationEventProcessor)
             .forEach(representationEventProcessor -> {
+                long start = System.currentTimeMillis();
                 representationEventProcessor.refresh(changeDescription);
+                long end = System.currentTimeMillis();
+
+                this.logger.atDebug()
+                        .setMessage("EditingContext {}: {}ms to refresh the {} with id {}")
+                        .addArgument(this.editingContext.getId())
+                        .addArgument(() -> String.format(LOG_TIMING_FORMAT, end - start))
+                        .addArgument(representationEventProcessor.getClass().getSimpleName())
+                        .addArgument(representationEventProcessor.getRepresentation().getId())
+                        .log();
+
                 IRepresentation representation = representationEventProcessor.getRepresentation();
                 this.applicationEventPublisher.publishEvent(new RepresentationRefreshedEvent(this.editingContext.getId(), representation));
             });

diff --git a/...s-interpreter/src/main/java/org/eclipse/sirius/components/interpreter/AQLInterpreter.java b/...s-interpreter/src/main/java/org/eclipse/sirius/components/interpreter/AQLInterpreter.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2019, 2023 Obeo.
+ * Copyright (c) 2019, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -131,6 +131,8 @@ public Result evaluateExpression(Map<String, Object> variables, String expressio
         }
 
         try {
+            long start = System.currentTimeMillis();
+
             AstResult build = this.parsedExpressions.get(expression);
             IQueryEvaluationEngine evaluationEngine = QueryEvaluation.newEngine(this.queryEnvironment);
             EvaluationResult evalResult = evaluationEngine.eval(build, variables);
@@ -145,6 +147,15 @@ public Result evaluateExpression(Map<String, Object> variables, String expressio
 
             this.log(expressionBody, diagnostic);
 
+            long end = System.currentTimeMillis();
+            if (end - start > 200) {
+                this.logger.atDebug()
+                        .setMessage("{}ms to execute the expression {}")
+                        .addArgument(end - start)
+                        .addArgument(expressionBody)
+                        .log();
+            }
+
             return new Result(Optional.ofNullable(evalResult.getResult()), Status.getStatus(diagnostic.getSeverity()));
         } catch (ExecutionException exception) {
             this.logger.warn(exception.getMessage(), exception);

diff --git a/...ipse/sirius/web/application/editingcontext/services/EditingContextPersistenceService.java b/...ipse/sirius/web/application/editingcontext/services/EditingContextPersistenceService.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2024 Obeo.
+ * Copyright (c) 2024, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -31,6 +31,8 @@
 import org.eclipse.sirius.web.domain.boundedcontexts.project.Project;
 import org.eclipse.sirius.web.domain.boundedcontexts.semanticdata.Document;
 import org.eclipse.sirius.web.domain.boundedcontexts.semanticdata.services.api.ISemanticDataUpdateService;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.data.jdbc.core.mapping.AggregateReference;
 import org.springframework.stereotype.Service;
 import org.springframework.transaction.annotation.Transactional;
@@ -58,6 +60,8 @@ public class EditingContextPersistenceService implements IEditingContextPersiste
 
     private final Timer timer;
 
+    private final Logger logger = LoggerFactory.getLogger(EditingContextPersistenceService.class);
+
     public EditingContextPersistenceService(ISemanticDataUpdateService semanticDataUpdateService, IResourceToDocumentService resourceToDocumentService, List<IEditingContextPersistenceFilter> persistenceFilters, List<IEditingContextMigrationParticipantPredicate> migrationParticipantPredicates, MeterRegistry meterRegistry) {
         this.semanticDataUpdateService = Objects.requireNonNull(semanticDataUpdateService);
         this.resourceToDocumentService = Objects.requireNonNull(resourceToDocumentService);
@@ -97,5 +101,11 @@ public void persist(ICause cause, IEditingContext editingContext) {
 
         long end = System.currentTimeMillis();
         this.timer.record(end - start, TimeUnit.MILLISECONDS);
+
+        this.logger.atDebug()
+                .setMessage("EditingContext {}: {}ms to persist the semantic data")
+                .addArgument(editingContext.getId())
+                .addArgument(() -> String.format("%1$6s", end - start))
+                .log();
     }
 }
diff --git a/...g/eclipse/sirius/web/application/editingcontext/services/EditingContextSearchService.java b/...g/eclipse/sirius/web/application/editingcontext/services/EditingContextSearchService.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2024 Obeo.
+ * Copyright (c) 2024, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -84,8 +84,6 @@ public Optional<IEditingContext> findById(String editingContextId) {
     private IEditingContext toEditingContext(Project project) {
         long start = System.currentTimeMillis();
 
-        this.logger.debug("Loading the editing context {}", project.getId());
-
         AdapterFactoryEditingDomain editingDomain = this.editingDomainFactory.createEditingDomain(project);
         EditingContext editingContext = new EditingContext(project.getId().toString(), editingDomain, new HashMap<>(), new ArrayList<>());
         this.editingContextLoader.load(editingContext, project.getId());
@@ -94,13 +92,14 @@ private IEditingContext toEditingContext(Project project) {
         this.timer.record(end - start, TimeUnit.MILLISECONDS);
 
         this.logger.atDebug()
-                .setMessage("{} objects have been loaded in {} ms")
+                .setMessage("EditingContext {}: {}ms to load {} objects")
+                .addArgument(project.getId())
+                .addArgument(() -> String.format("%1$6s", end - start))
                 .addArgument(() -> {
                     var iterator = editingDomain.getResourceSet().getAllContents();
                     var stream = StreamSupport.stream(Spliterators.spliteratorUnknownSize(iterator, Spliterator.ORDERED), false);
                     return stream.count();
                 })
-                .addArgument(end - start)
                 .log();
 
         return editingContext;

diff --git a/...ava/org/eclipse/sirius/web/infrastructure/configuration/graphql/GraphQLConfiguration.java b/...ava/org/eclipse/sirius/web/infrastructure/configuration/graphql/GraphQLConfiguration.java
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2024, 2024 Obeo.
+ * Copyright (c) 2024, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -20,6 +20,7 @@
 import org.eclipse.sirius.components.graphql.api.UploadScalarType;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.springframework.beans.factory.annotation.Value;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.core.io.Resource;
@@ -30,6 +31,7 @@
 import graphql.execution.AsyncSerialExecutionStrategy;
 import graphql.execution.DataFetcherExceptionHandler;
 import graphql.execution.ExecutionStrategy;
+import graphql.execution.instrumentation.tracing.TracingInstrumentation;
 import graphql.schema.GraphQLCodeRegistry;
 import graphql.schema.GraphQLSchema;
 import graphql.schema.idl.RuntimeWiring;
@@ -54,7 +56,7 @@ public class GraphQLConfiguration {
     private final Logger logger = LoggerFactory.getLogger(GraphQLConfiguration.class);
 
     @Bean
-    public GraphQL graphQL(GraphQLSchema graphQLSchema) {
+    public GraphQL graphQL(GraphQLSchema graphQLSchema, @Value("${sirius.web.graphql.tracing:false}") boolean activateTracing) {
         var options = SchemaPrinter.Options.defaultOptions();
         String schema = new SchemaPrinter(options).print(graphQLSchema);
 
@@ -65,12 +67,17 @@ public GraphQL graphQL(GraphQLSchema graphQLSchema) {
         // @see https://www.graphql-java.com/documentation/v11/execution/ The graphql specification says that mutations
         // MUST be executed serially and in the order in which the query fields occur.
         ExecutionStrategy mutationExecutionStrategy = new AsyncSerialExecutionStrategy(exceptionHandler);
-        // @formatter:off
-        return GraphQL.newGraphQL(graphQLSchema)
+
+        var graphQLJavaBuilder = GraphQL.newGraphQL(graphQLSchema)
                 .queryExecutionStrategy(queryExecutionStrategy)
-                .mutationExecutionStrategy(mutationExecutionStrategy)
-                .build();
-        // @formatter:on
+                .mutationExecutionStrategy(mutationExecutionStrategy);
+
+        if (activateTracing) {
+            var tracingOptions = TracingInstrumentation.Options.newOptions().includeTrivialDataFetchers(false);
+            graphQLJavaBuilder.instrumentation(new TracingInstrumentation(tracingOptions));
+        }
+
+        return graphQLJavaBuilder.build();
     }
 
     @Bean

diff --git a/packages/sirius-web/backend/sirius-web/src/main/resources/application.properties b/packages/sirius-web/backend/sirius-web/src/main/resources/application.properties
@@ -26,4 +26,7 @@ spring.liquibase.change-log=classpath:db/db.changelog-master.xml
 
 sirius.web.enabled=*
 sirius.components.cors.allowedOriginPatterns=*
-sirius.components.cors.allowedCredentials=true
+sirius.components.cors.allowedCredentials=true
+
+sirius.web.graphql.tracing=true
+logging.group.sirius.web.performance=org.eclipse.sirius.web.application.editingcontext.services.EditingContextSearchService,org.eclipse.sirius.web.application.editingcontext.services.EditingContextPersistenceService,org.eclipse.sirius.components.collaborative.editingcontext.EditingContextEventProcessor,org.eclipse.sirius.components.interpreter.AQLInterpreter
diff --git a/packages/sirius-web/frontend/sirius-web-application/src/graphql/ApolloLinkUndoRedoStack.tsx b/packages/sirius-web/frontend/sirius-web-application/src/graphql/ApolloLinkUndoRedoStack.tsx
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2024 Obeo.
+ * Copyright (c) 2024, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -10,7 +10,7 @@
  * Contributors:
  *     Obeo - initial API and implementation
  *******************************************************************************/
-import { ApolloLink, Operation } from '@apollo/client';
+import { ApolloLink, FetchResult, NextLink, Observable, Operation } from '@apollo/client';
 import { Kind, OperationTypeNode } from 'graphql/language';
 
 export class ApolloLinkUndoRedoStack extends ApolloLink {
@@ -19,7 +19,8 @@ export class ApolloLinkUndoRedoStack extends ApolloLink {
     sessionStorage.setItem('undoStack', JSON.stringify([]));
     sessionStorage.setItem('redoStack', JSON.stringify([]));
   }
-  override request(operation: Operation, forward) {
+
+  override request(operation: Operation, forward?: NextLink): Observable<FetchResult> | null {
     if (
       operation.query.definitions[0].kind === Kind.OPERATION_DEFINITION &&
       operation.query.definitions[0].operation === OperationTypeNode.MUTATION &&

diff --git a/packages/sirius-web/frontend/sirius-web-application/src/graphql/ApolloLoggerLink.tsx b/packages/sirius-web/frontend/sirius-web-application/src/graphql/ApolloLoggerLink.tsx
@@ -0,0 +1,37 @@
+/*******************************************************************************
+ * Copyright (c) 2024, 2025 Obeo.
+ * This program and the accompanying materials
+ * are made available under the terms of the Eclipse Public License v2.0
+ * which accompanies this distribution, and is available at
+ * https://www.eclipse.org/legal/epl-2.0/
+ *
+ * SPDX-License-Identifier: EPL-2.0
+ *
+ * Contributors:
+ *     Obeo - initial API and implementation
+ *******************************************************************************/
+import { ApolloLink, FetchResult, NextLink, Observable, Operation } from '@apollo/client';
+import { DefinitionNode, Kind, OperationDefinitionNode } from 'graphql/language';
+
+const isOperationDefinitionNode = (definitionNode: DefinitionNode): definitionNode is OperationDefinitionNode =>
+  definitionNode.kind === Kind.OPERATION_DEFINITION;
+
+export class ApolloLoggerLink extends ApolloLink {
+  override request(operation: Operation, forward: NextLink): Observable<FetchResult> | null {
+    const node = operation.query.definitions.find((definitionNode) => isOperationDefinitionNode(definitionNode));
+
+    const operationKind: string = isOperationDefinitionNode(node) ? node.operation : 'unknown kind';
+    const operationName: string = isOperationDefinitionNode(node) ? node.name?.value : 'unknwown name';
+
+    console.debug(`${operationKind} ${operationName}: request sent`);
+
+    if ('subscription' === operationKind) {
+      return forward(operation);
+    }
+
+    return forward(operation).map((fetchResult) => {
+      console.debug(`${operationKind} ${operationName}: response received`);
+      return fetchResult;
+    });
+  }
+}
diff --git a/packages/sirius-web/frontend/sirius-web-application/src/graphql/useCreateApolloClient.ts b/packages/sirius-web/frontend/sirius-web-application/src/graphql/useCreateApolloClient.ts
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2024 Obeo.
+ * Copyright (c) 2024, 2025 Obeo.
  * This program and the accompanying materials
  * are made available under the terms of the Eclipse Public License v2.0
  * which accompanies this distribution, and is available at
@@ -14,6 +14,7 @@
 import {
   ApolloClient,
   ApolloClientOptions,
+  ApolloLink,
   DefaultOptions,
   HttpLink,
   HttpOptions,
@@ -33,6 +34,7 @@ import {
   ProjectFragment,
   ViewerProjectsFragment,
 } from '../views/project-browser/list-projects-area/useProjects.fragments';
+import { ApolloLoggerLink } from './ApolloLoggerLink';
 import {
   apolloClientOptionsConfigurersExtensionPoint,
   cacheOptionsConfigurersExtensionPoint,
@@ -104,8 +106,10 @@ export const useCreateApolloClient = (httpOrigin: string, wsOrigin: string): Apo
     },
   };
 
+  var apolloLink = ApolloLink.from([new ApolloLoggerLink(), link]);
+
   let apolloClientOptions: ApolloClientOptions<NormalizedCacheObject> = {
-    link,
+    link: apolloLink,
     cache,
     connectToDevTools: true,
     defaultOptions,