The time to commit metadata changes increases dramatically with the amount of metadata present in the system

[connoratrug]

How to Reproduce

Import a lot of metadata like the c6 questionnaire (see questionnaire test plan)
In the metadata editor, update a single attribute description
Save your changes

Expected behavior

Changes are saved quickly

Observed behavior

Takes around 6 seconds for the update to be saved

[dennishendriksen]

Cannot reproduce on my local machine. What are the max_locks_per_transaction and shared_buffers values of the PostgreSQL database of this MOLGENIS instance? Should be 1024 and 1GB.

[connoratrug]

checked in rancher; max_locks_per_transaction is set to 1024
shared_buffers is not set in rancher, so i assume some default is used

[fdlk]

On a clean rollout of 8.2.0 in rancher I cannot reproduce, on the test server I can.

[fdlk]

The platform transaction manager commits, calls the transaction listeners. The index manager wants to determine what needs to be done. It fetches all entity types with a method that is intended to be cached. The entity manager then ends up selecting lots of references.

What is special about the test server is that the questionnaire got loaded so there is an entity with a lot of attributes and there are in total 2213 attributes present in the metadata.

[fdlk]

also happens when I simply update an attribute label

[fdlk]

"http-nio-8080-exec-10" #89 daemon prio=5 os_prio=0 cpu=608226.35ms elapsed=184036.60s tid=0x00007f99c4641800 nid=0x66 runnable  [0x00007f98da1ec000] 
   java.lang.Thread.State: RUNNABLE 
	at java.net.SocketInputStream.socketRead0([email protected]/Native Method) 
	at java.net.SocketInputStream.socketRead([email protected]/SocketInputStream.java:115) 
	at java.net.SocketInputStream.read([email protected]/SocketInputStream.java:168) 
	at java.net.SocketInputStream.read([email protected]/SocketInputStream.java:140) 
	at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140) 
	at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109) 
	at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:191) 
	at java.io.InputStream.read([email protected]/InputStream.java:205) 
	at org.postgresql.core.PGStream.receiveInteger4(PGStream.java:335) 
	at org.postgresql.core.PGStream.receiveTupleV3(PGStream.java:432) 
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2174) 
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:309) 
	- locked <0x00000007407fd0d0> (a org.postgresql.core.v3.QueryExecutorImpl) 
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:446) 
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:370) 
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:149) 
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:108) 
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:379) 
	at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:677) 
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:616) 
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:668) 
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:699) 
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:711) 
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:762) 
	at org.molgenis.data.postgresql.PostgreSqlRepository$1.getBatch(PostgreSqlRepository.java:463) 
	at org.molgenis.data.support.BatchingQueryResult.getBatch(BatchingQueryResult.java:29) 
	at org.molgenis.data.support.BatchingQueryResult.getBatch(BatchingQueryResult.java:13) 
	at org.molgenis.data.util.BatchingIterable$1.nextBatch(BatchingIterable.java:103) 
	at org.molgenis.data.util.BatchingIterable$1.hasNext(BatchingIterable.java:45) 
	at java.util.Spliterators$IteratorSpliterator.tryAdvance([email protected]/Spliterators.java:1811) 
	at java.util.Spliterators$1Adapter.hasNext([email protected]/Spliterators.java:681) 
	at com.google.common.collect.Maps.uniqueIndex(Maps.java:1338) 
	at org.molgenis.data.support.AbstractRepository.findAllBatched(AbstractRepository.java:110) 
	at org.molgenis.data.support.AbstractRepository.lambda$findAll$1(AbstractRepository.java:101) 
	at org.molgenis.data.support.AbstractRepository$$Lambda$1415/0x0000000840f71040.apply(Unknown Source) 
	at java.util.stream.ReferencePipeline$7$1.accept([email protected]/ReferencePipeline.java:271) 
	at java.util.Spliterators$IteratorSpliterator.tryAdvance([email protected]/Spliterators.java:1812) 
	at java.util.stream.StreamSpliterators$WrappingSpliterator.lambda$initPartialTraversalState$0([email protected]/StreamSpliterators.java:294) 
	at java.util.stream.StreamSpliterators$WrappingSpliterator$$Lambda$1285/0x0000000840f2b040.getAsBoolean([email protected]/Unknown Source) 
	at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.fillBuffer([email protected]/StreamSpliterators.java:206) 
	at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.doAdvance([email protected]/StreamSpliterators.java:161) 
	at java.util.stream.StreamSpliterators$WrappingSpliterator.tryAdvance([email protected]/StreamSpliterators.java:300) 
	at java.util.Spliterators$1Adapter.hasNext([email protected]/Spliterators.java:681) 
	at com.google.common.collect.Iterators$4.hasNext(Iterators.java:602) 
	at java.util.Iterator.forEachRemaining([email protected]/Iterator.java:132) 
	at java.util.Spliterators$IteratorSpliterator.forEachRemaining([email protected]/Spliterators.java:1801) 
	at java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:484) 
	at java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474) 
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential([email protected]/ReduceOps.java:913) 
	at java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234) 
	at java.util.stream.ReferencePipeline.collect([email protected]/ReferencePipeline.java:578) 
	at org.molgenis.data.EntityManagerImpl.resolveReferences(EntityManagerImpl.java:196) 
	at org.molgenis.data.EntityManagerImpl.lambda$resolveReferences$1(EntityManagerImpl.java:143) 
	at org.molgenis.data.EntityManagerImpl$$Lambda$1502/0x0000000840f99840.apply(Unknown Source) 
	at java.util.stream.ReferencePipeline$7$1.accept([email protected]/ReferencePipeline.java:271) 
	at java.util.Iterator.forEachRemaining([email protected]/Iterator.java:133) 
	at java.util.Spliterators$IteratorSpliterator.forEachRemaining([email protected]/Spliterators.java:1801) 
	at java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:484) 
	at java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474) 
	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential([email protected]/ForEachOps.java:150) 
	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential([email protected]/ForEachOps.java:173) 
	at java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234) 
	at java.util.stream.ReferencePipeline.forEach([email protected]/ReferencePipeline.java:497) 
	at org.molgenis.data.index.IndexActionRegisterServiceImpl.getEntityTypes(IndexActionRegisterServiceImpl.java:183) 
	at org.molgenis.data.index.IndexActionRegisterServiceImpl.createIndexDependencyModel(IndexActionRegisterServiceImpl.java:148) 
	at org.molgenis.data.index.IndexActionRegisterServiceImpl.storeIndexActions(IndexActionRegisterServiceImpl.java:124) 
	at org.molgenis.data.index.IndexActionRegisterServiceImpl$$FastClassBySpringCGLIB$$501b3016.invoke(<generated>) 
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) 
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749) 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) 
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) 
	at org.molgenis.security.core.runas.RunAsSystemAspect$$Lambda$1197/0x0000000840ece440.run(Unknown Source) 
	at org.molgenis.security.core.runas.RunAsSystemAspect.runAsSystem(RunAsSystemAspect.java:38) 
	at org.molgenis.security.core.runas.RunAsSystemAspect.aroundAdvice(RunAsSystemAspect.java:20) 
	at jdk.internal.reflect.GeneratedMethodAccessor141.invoke(Unknown Source) 
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke([email protected]/DelegatingMethodAccessorImpl.java:43) 
	at java.lang.reflect.Method.invoke([email protected]/Method.java:566) 
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) 
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) 
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) 
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) 
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) 
	at org.molgenis.data.index.IndexActionRegisterServiceImpl$$EnhancerBySpringCGLIB$$4b8b5f70.storeIndexActions(<generated>) 
	at org.molgenis.data.index.transaction.IndexTransactionListener.commitTransaction(IndexTransactionListener.java:26) 
	at org.molgenis.data.postgresql.transaction.PostgreSqlTransactionManager.lambda$doCommit$1(PostgreSqlTransactionManager.java:110) 
	at org.molgenis.data.postgresql.transaction.PostgreSqlTransactionManager$$Lambda$1496/0x0000000840f9b040.accept(Unknown Source) 
	at java.util.ArrayList.forEach([email protected]/ArrayList.java:1540) 
	at org.molgenis.data.postgresql.transaction.PostgreSqlTransactionManager.doCommit(PostgreSqlTransactionManager.java:110) 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:534) 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:305) 
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98) 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) 
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) 
	at org.molgenis.data.meta.MetaDataServiceImpl$$EnhancerBySpringCGLIB$$679334f1.upsertEntityTypes(<generated>) 
	at org.molgenis.metadata.manager.service.MetadataManagerServiceImpl.upsertEntityType(MetadataManagerServiceImpl.java:71) 
	at org.molgenis.metadata.manager.controller.MetadataManagerController.upsertEntityType(MetadataManagerController.java:79) 
	[...]

[fdlk]

Tested on 7.4.8 and is also present there.

[mswertz]

Is this still present in 8.2RC?

[dennishendriksen]

Is this still present in 8.2RC?

Yes