diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index c8806953ae..19905980f4 100644 --- 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 new file mode 100644 index 0000000000..92bab0a118 --- /dev/null +++ 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/packages/core/backend/sirius-components-collaborative/src/main/java/org/eclipse/sirius/components/collaborative/editingcontext/EditingContextEventProcessor.java b/packages/core/backend/sirius-components-collaborative/src/main/java/org/eclipse/sirius/components/collaborative/editingcontext/EditingContextEventProcessor.java index b9eed4fd78..90ea043757 100644 --- a/packages/core/backend/sirius-components-collaborative/src/main/java/org/eclipse/sirius/components/collaborative/editingcontext/EditingContextEventProcessor.java +++ b/packages/core/backend/sirius-components-collaborative/src/main/java/org/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 handle(IInput input) { */ private void doHandle(One payloadSink, IInput input) { this.logger.trace("Input received: {}", input); + long start = System.currentTimeMillis(); AtomicReference 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 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/packages/emf/backend/sirius-components-interpreter/src/main/java/org/eclipse/sirius/components/interpreter/AQLInterpreter.java b/packages/emf/backend/sirius-components-interpreter/src/main/java/org/eclipse/sirius/components/interpreter/AQLInterpreter.java index 340766ef7d..02597157c3 100644 --- a/packages/emf/backend/sirius-components-interpreter/src/main/java/org/eclipse/sirius/components/interpreter/AQLInterpreter.java +++ b/packages/emf/backend/sirius-components-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 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 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/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextPersistenceService.java b/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextPersistenceService.java index 43cc38b0d4..dec11f5ed6 100644 --- a/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextPersistenceService.java +++ b/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/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 persistenceFilters, List 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/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextSearchService.java b/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextSearchService.java index 4cb0049268..10a2cff745 100644 --- a/packages/sirius-web/backend/sirius-web-application/src/main/java/org/eclipse/sirius/web/application/editingcontext/services/EditingContextSearchService.java +++ b/packages/sirius-web/backend/sirius-web-application/src/main/java/org/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 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/packages/sirius-web/backend/sirius-web-infrastructure/src/main/java/org/eclipse/sirius/web/infrastructure/configuration/graphql/GraphQLConfiguration.java b/packages/sirius-web/backend/sirius-web-infrastructure/src/main/java/org/eclipse/sirius/web/infrastructure/configuration/graphql/GraphQLConfiguration.java index 719c08a4cf..0bb2b14a91 100644 --- a/packages/sirius-web/backend/sirius-web-infrastructure/src/main/java/org/eclipse/sirius/web/infrastructure/configuration/graphql/GraphQLConfiguration.java +++ b/packages/sirius-web/backend/sirius-web-infrastructure/src/main/java/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 index 46d42d50c4..0bde6097b4 100644 --- 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 \ No newline at end of file +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 \ No newline at end of file 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 index e9cf89c6e7..0d0ac40d72 100644 --- 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 | 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 new file mode 100644 index 0000000000..0d93bad219 --- /dev/null +++ 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 | 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 index 3a9690f3d1..a171f7c4f0 100644 --- 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 = { - link, + link: apolloLink, cache, connectToDevTools: true, defaultOptions,