Import events with web-api :/api/36/events cause java.lang.OutOfMemoryError: Java heap space!

Support - Assistance technique
1

dhis -2.37，tomcat-9 :-Xms12000m,-Xmx12000m,
I do events import from a background task, every 5s import 20 events bulkily.

I use the post api :…api/36/events?orgUnitIdScheme=name&async=false ：
{“events”:[
{event},{event},…
]}

I have about 10k orgs. and the program assigned to all the orgs.

at first ,it’s ok ,few times later, there is no response for dhis2. and api calling timeout, got read timed out error. and can’t open login page in browser,
the catalina.out has no info ,some time say heap memory out of .

  • ERROR 2021-09-14T00:51:08,898 Unexpected exception occurred invoking async method: public void org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onDataValueChange(org.hisp.dhis.programrule.engine.DataValueUpdatedEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-12])
    java.lang.OutOfMemoryError: Java heap space
    at java.lang.StringUTF16.compress(StringUTF16.java:160) ~[?:?]
    at java.lang.String.(String.java:3214) ~[?:?]
    at java.lang.String.(String.java:276) ~[?:?]
    at com.fasterxml.jackson.core.util.TextBuffer.contentsAsString(TextBuffer.java:453) ~[jackson-core-2.12.1.jar:2.12.1]
    at com.fasterxml.jackson.core.io.SegmentedStringWriter.getAndClear(SegmentedStringWriter.java:85) ~[jackson-core-2.12.1.jar:2.12.1]
    at com.fasterxml.jackson.databind.ObjectWriter.writeValueAsString(ObjectWriter.java:1091) ~[jackson-databind-2.12.1.jar:2.12.1]
    at org.hisp.dhis.hibernate.jsonb.type.JsonEventDataValueSetBinaryType.convertObjectToJson(JsonEventDataValueSetBinaryType.java:101) ~[dhis-support-hibernate-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.hibernate.jsonb.type.JsonEventDataValueSetBinaryType.deepCopy(JsonEventDataValueSetBinaryType.java:75) ~[dhis-support-hibernate-2.37-SNAPSHOT.jar:?]
    at org.hibernate.type.CustomType.deepCopy(CustomType.java:190) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.type.TypeHelper.deepCopy(TypeHelper.java:55) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntityFromEntityEntryLoadedState(TwoPhaseLoad.java:369) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:183) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:151) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.performTwoPhaseLoad(AbstractRowReader.java:247) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.finishUp(AbstractRowReader.java:208) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl.extractResults(ResultSetProcessorImpl.java:96) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:105) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:87) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:710) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:76) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.internal.SessionImpl$$Lambda$703/0x0000000840e37840.accept(Unknown Source) ~[?:?]
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:93) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2163) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:589) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:585) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:149) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.PersistentSet.iterator(PersistentSet.java:188) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at java.util.Spliterators$IteratorSpliterator.estimateSize(Spliterators.java:1821) ~[?:?]
    at java.util.Spliterator.getExactSizeIfKnown(Spliterator.java:408) ~[?:?]
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:483) ~[?:?]
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[?:?]
  • ERROR 2021-09-14T00:51:08,891 Unexpected exception occurred invoking async method: public void org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onEventCompletion(org.hisp.dhis.programrule.engine.StageCompletionEvaluationEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-8])
    java.lang.OutOfMemoryError: Java heap space
    at java.util.LinkedHashMap.newNode(LinkedHashMap.java:256) ~[?:?]
    at java.util.HashMap.putVal(HashMap.java:626) ~[?:?]
    at java.util.HashMap.put(HashMap.java:607) ~[?:?]
    at org.hibernate.internal.util.collections.IdentityMap.put(IdentityMap.java:110) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.StatefulPersistenceContext.addCollection(StatefulPersistenceContext.java:915) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.StatefulPersistenceContext.addUninitializedCollection(StatefulPersistenceContext.java:886) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.type.CollectionType.getCollection(CollectionType.java:831) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.type.CollectionType.resolveKey(CollectionType.java:505) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.type.CollectionType.resolve(CollectionType.java:498) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntityEntryLoadedState(TwoPhaseLoad.java:249) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:182) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.engine.internal.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:151) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.performTwoPhaseLoad(AbstractRowReader.java:247) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.finishUp(AbstractRowReader.java:208) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl.extractResults(ResultSetProcessorImpl.java:96) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:105) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:87) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:710) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:76) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.internal.SessionImpl$$Lambda$703/0x0000000840e37840.accept(Unknown Source) ~[?:?]
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:93) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2163) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:589) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:585) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:149) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at org.hibernate.collection.internal.PersistentSet.iterator(PersistentSet.java:188) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
    at java.util.Spliterators$IteratorSpliterator.estimateSize(Spliterators.java:1821) ~[?:?]
    at java.util.Spliterator.getExactSizeIfKnown(Spliterator.java:408) ~[?:?]
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:483) ~[?:?]
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[?:?]
    at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913) ~[?:?]
3

java.lang.OutOfMemoryError: Java heap space

  • WARN 2021-09-15T21:43:26,392 HHH000100: Fail-safe cleanup (collections) : org.hibernate.engine.loading.internal.CollectionLoadContext@2875b94a<rs=com.mchange.v2.c3p0.impl.NewProxyResultSet@158e3c00 [wrapping: null]> (LoadContexts.java [taskScheduler-15])

  • WARN 2021-09-15T21:43:26,393 HHH000160: On CollectionLoadContext#cleanup, localLoadingCollectionKeys contained [1] entries (CollectionLoadContext.java [taskScheduler-15])

  • ERROR 2021-09-15T21:43:26,393 Unexpected exception occurred invoking async method: public void org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onEventCompletion(org.hisp.dhis.programrule.engine.StageCompletionEvaluationEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-15])
    java.lang.OutOfMemoryError: Java heap space

  • WARN 2021-09-15T21:43:26,447 HHH000100: Fail-safe cleanup (collections) : org.hibernate.engine.loading.internal.CollectionLoadContext@4aa3950c<rs=com.mchange.v2.c3p0.impl.NewProxyResultSet@711adfbf [wrapping: null]> (LoadContexts.java [taskScheduler-7])

  • WARN 2021-09-15T21:43:26,447 HHH000160: On CollectionLoadContext#cleanup, localLoadingCollectionKeys contained [1] entries (CollectionLoadContext.java [taskScheduler-7])

  • ERROR 2021-09-15T21:43:26,448 Unexpected exception occurred invoking async method: public void org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onDataValueChange(org.hisp.dhis.programrule.engine.DataValueUpdatedEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-7])
    java.lang.OutOfMemoryError: Java heap space

  • WARN 2021-09-15T21:43:26,331 AMQ212052: Packet PACKET(SessionBindingQueryResponseMessage_V4)[type=-15, channelID=11, responseAsync=false, requiresResponse=false, correlationID=-1, packetObject=SessionBindingQueryResponseMessage_V4, exists=true, queueNames=[54c97938-d869-4038-a7dd-ef06410d6788], autoCreateQueues=true, autoCreateAddresses=true, defaultPurgeOnNoConsumers=false, defaultMaxConsumers=-1, defaultExclusive=false, defaultLastValue=false, defaultLastValueKey=null, defaultNonDestructive=false, defaultConsumersBeforeDispatch=0, defaultDelayBeforeDispatch=-1] was answered out of sequence due to a previous server timeout and it’s being ignored (ChannelImpl.java [http-nio-10008-exec-126])
    java.lang.Exception: trace
    at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:510) ~[artemis-core-client-2.17.0.jar:2.17.0]
    at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:434) ~[artemis-core-client-2.17.0.jar:2.17.0]
    at org.apache.activemq.artemis.core.protocol.core.impl.ActiveMQSessionContext.sessionClose(ActiveMQSessionContext.java:616) ~[artemis-core-client-2.17.0.jar:2.17.0]
    at org.apache.activemq.artemis.core.client.impl.ClientSessionImpl.close(ClientSessionImpl.java:1336) ~[artemis-core-client-2.17.0.jar:2.17.0]
    at org.apache.activemq.artemis.jms.client.ActiveMQSession.close(ActiveMQSession.java:321) ~[artemis-jms-client-2.17.0.jar:2.17.0]
    at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:109) ~[spring-jms-5.3.6.jar:5.3.6]
    at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:510) ~[spring-jms-5.3.6.jar:5.3.6]
    at org.springframework.jms.core.JmsTemplate.send(JmsTemplate.java:584) ~[spring-jms-5.3.6.jar:5.3.6]
    at org.hisp.dhis.artemis.MessageManager.send(MessageManager.java:57) ~[dhis-support-artemis-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.artemis.audit.AuditProducerSupplier.publish(AuditProducerSupplier.java:69) ~[dhis-support-artemis-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.artemis.audit.AuditManager.send(AuditManager.java:127) ~[dhis-support-artemis-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.audit.AbstractEventAuditPostProcessor.process(AbstractEventAuditPostProcessor.java:63) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.EventProcessing$ProcessorRunner.run(EventProcessing.java:70) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.AbstractProcessorFactory.process(AbstractProcessorFactory.java:51) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.EventManager.addEvents(EventManager.java:166) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.EventImporter.importAll(EventImporter.java:103) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.importer.EventServiceFacade.addEventsJson(EventServiceFacade.java:101) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at org.hisp.dhis.dxf2.events.event.JacksonEventService.addEventsJson(JacksonEventService.java:208) ~[dhis-service-dxf2-2.37-SNAPSHOT.jar:?]
    at jdk.internal.reflect.GeneratedMethodAccessor750.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

  • INFO 2021-09-18T01:22:20,118 Import done: 00:00:00.715 (Clock.java [http-nio-10008-exec-3])

  • INFO 2021-09-18T01:22:36,498 Import done: 00:00:00.490 (Clock.java [http-nio-10008-exec-10])

  • INFO 2021-09-18T01:22:42,453 Import done: 00:00:00.829 (Clock.java [http-nio-10008-exec-1])

  • INFO 2021-09-18T01:22:55,715 Import done: 00:00:00.385 (Clock.java [http-nio-10008-exec-1])

  • INFO 2021-09-18T01:24:26,054 Import done: 00:01:30.125 (Clock.java [http-nio-10008-exec-2])

  • WARN 2021-09-18T01:24:51,865 AMQ212037: Connection failure to invm:0 has been detected: AMQ219014: Timed out after waiting 30,000 ms for response when sending packet 69 [code=CONNECTION_TIMEDOUT] (RemotingConnectionImpl.java [Thread-3 (ActiveMQ-client-global-threads)])

  • WARN 2021-09-18T01:29:58,082 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@13030d6e – APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1vwwur41t34nmg|541e0da9]-AdminTaskTimer])

4

Hey @linxd, are you using Java 11? If not then I recommend that you try using Java 11 and then see if you still face this issue. Thanks! (:

5

certainly, it’s jdk11.

1 Like
6
  • WARN 2021-09-19T22:35:31,637 Can’t find count for organisation unit UbuJzNqgiyc parsing expression ‘OUG{xEQ2t534Gr2}
    +OUG{UbuJzNqgiyc}+OUG{Wb3oPSYRtwY}+OUG{UsuXDzLTLUx}+OUG{Ugb4HGKHgET}+OUG{etnMn5oaL3s}’ (DefaultExpressionService.java [h
    ttp-nio-8080-exec-7])
  • WARN 2021-09-19T22:35:31,664 Can’t find count for organisation unit UbuJzNqgiyc parsing expression ‘OUG{xEQ2t534Gr2}
    +OUG{UbuJzNqgiyc}+OUG{Wb3oPSYRtwY}+OUG{UsuXDzLTLUx}+OUG{Ugb4HGKHgET}+OUG{etnMn5oaL3s}’ (DefaultExpressionService.java [h
    ttp-nio-8080-exec-7])
  • WARN 2021-09-19T22:53:40,060 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@7f5625de – APPARENT
    DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[i dentityToken->1bqydq9aj1yixw69y7md93|73353aa2]-AdminTaskTimer])
    [6491.733s][warning][gc,alloc] Thread-41 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerIm
    pl$6@7f0d082d): Retried waiting for GCLocker too often allocating 195048 words
7

I have a scheduler, call web api to import event periodly (period is about 1000ms) ,when the period decrease to 200ms, the polling thread will not get the response from api, and the catalina.out log: got this:

  • INFO 2021-09-20T12:13:52,248 Login attempt: api (TwoFactorAuthenticationProvider.java [http-nio-7008-exec-21])
  • WARN 2021-09-20T12:14:23,994 Authentication event: AuthenticationSuccessEvent; username: api; (AuthenticationLoggerListener.java [http-nio-7008-exec-21])
  • INFO 2021-09-20T12:14:23,995 ‘system-process’ update org.hisp.dhis.user.UserCredentials, name: 访问者 api, uid: wefpg43tCOu (AuditLogUtil.java [http-nio-7008-exec-21])
  • INFO 2021-09-20T12:15:11,348 Import done: 00:00:31.660 (Clock.java [http-nio-7008-exec-21])
  • INFO 2021-09-20T12:16:31,005 Login attempt: api (TwoFactorAuthenticationProvider.java [http-nio-7008-exec-11])
  • WARN 2021-09-20T12:19:06,223 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@733c4d3 – APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->z8kfsxaj1tozh7fovwvjk|5751c5a8]-AdminTaskTimer])
    Exception in thread “AsyncFileHandlerWriter-931919113” java.lang.OutOfMemoryError: Java heap space
    c
8

pgadmin4：

1632113036(1)
1632113036(1)1245×677 89.1 KB

1632113089(1)
1632113089(1)1217×746 90.4 KB

10

@linxd if you are not using program rules for notifications then try using skipNotification parameter in import options.

2 Likes
11

@linxd OR
you can completely disable backend rule-engine using
system.program_rule.server_execution=off in dhis2.conf

12

but there is no rule.

13

rule-engine will be triggered no matter if there are any rules or not.
So simple workaround is to disable rule-engine by setting this property.
system.program_rule.server_execution=off

1 Like
14

THANKS, till now , 10 events for each request take 300ms, 20 events/500ms, it’s quick.

1 Like