Error in execution of monitored action poll_background_job

1
I hope somebody from Mendix can give a pointer on how to solve this one. We have a (very) large import action of data. Three minutes after the whole import (which last for about 4 hours) is finished we get this out of memory action. Strange though that this happens after all the work has been done and the import microflow has finished. Looks like some cache clearing action that runs out of memory. Regards, Ronald Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: Error in execution of monitored action 'poll_background_job' (execution id: 1fdcdd76202a700, execution type: CLIENT Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (1/33) java.lang.OutOfMemoryError: GC overhead limit exceeded Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (2/33) at java.util.HashMap.addEntry(HashMap.java:753) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (3/33) at java.util.HashMap.put(HashMap.java:385) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (4/33) at com.mendix.core.objectmanagement.MendixObject.getMembers(MendixObject.java:118) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (5/33) at com.mendix.core.objectmanagement.SchemeManager.getInstance(SchemeManager.java:983) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (6/33) at com.mendix.core.action.user.Retriever$class.com$mendix$core$action$user$Retriever$$buildObject(Retriever.scala:59) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (7/33) at com.mendix.core.action.user.Retriever$$anonfun$buildObjects$1.apply(Retriever.scala:54) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (8/33) at com.mendix.core.action.user.Retriever$$anonfun$buildObjects$1.apply(Retriever.scala:53) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (9/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (10/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (11/33) at scala.collection.Iterator$class.foreach(Iterator.scala:772) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (12/33) at scala.collection.JavaConversions$JIteratorWrapper.foreach(JavaConversions.scala:573) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (13/33) at scala.collection.IterableLike$class.foreach(IterableLike.scala:73) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (14/33) at scala.collection.JavaConversions$JListWrapper.foreach(JavaConversions.scala:615) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (15/33) at scala.collection.TraversableLike$class.map(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (16/33) at scala.collection.JavaConversions$JListWrapper.map(JavaConversions.scala:615) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (17/33) at com.mendix.core.action.user.Retriever$class.buildObjects(Retriever.scala:53) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (18/33) at com.mendix.core.action.user.Retriever$class.retrieveFromDatabase(Retriever.scala:35) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (19/33) at com.mendix.core.action.user.RetrieveIdListAction.retrieveFromDatabase(RetrieveIdListAction.scala:15) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (20/33) at com.mendix.core.action.user.RetrieveIdListAction.com$mendix$core$action$user$RetrieveIdListAction$$retrieve(RetrieveIdListAction.scala:51) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (21/33) at com.mendix.core.action.user.RetrieveIdListAction$$anonfun$7.apply(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (22/33) at com.mendix.core.action.user.RetrieveIdListAction$$anonfun$7.apply(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (23/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (24/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (25/33) at scala.collection.immutable.Map$Map3.foreach(Map.scala:164) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (26/33) at scala.collection.TraversableLike$class.map(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (27/33) at scala.collection.immutable.Map$Map3.map(Map.scala:144) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (28/33) at com.mendix.core.action.user.RetrieveIdListAction.executeAction(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (29/33) at com.mendix.core.action.user.RetrieveIdListAction.executeAction(RetrieveIdListAction.scala:15) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (30/33) at com.mendix.systemwideinterfaces.core.UserAction.execute(UserAction.java:57) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (31/33) at com.mendix.core.actionmanagement.CoreAction.doCall(CoreAction.java:478) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (32/33) at com.mendix.core.actionmanagement.CoreAction.call(CoreAction.java:463) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (33/33) at com.mendix.core.actionmanagement.ActionManager.executeSync(ActionManager.java:198) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: An unhandled error occurred in the MxRuntime. Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (1/33) java.lang.OutOfMemoryError: GC overhead limit exceeded Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (2/33) at java.util.HashMap.addEntry(HashMap.java:753) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (3/33) at java.util.HashMap.put(HashMap.java:385) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (4/33) at com.mendix.core.objectmanagement.MendixObject.getMembers(MendixObject.java:118) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (5/33) at com.mendix.core.objectmanagement.SchemeManager.getInstance(SchemeManager.java:983) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (6/33) at com.mendix.core.action.user.Retriever$class.com$mendix$core$action$user$Retriever$$buildObject(Retriever.scala:59) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (7/33) at com.mendix.core.action.user.Retriever$$anonfun$buildObjects$1.apply(Retriever.scala:54) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (8/33) at com.mendix.core.action.user.Retriever$$anonfun$buildObjects$1.apply(Retriever.scala:53) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (9/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (10/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (11/33) at scala.collection.Iterator$class.foreach(Iterator.scala:772) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (12/33) at scala.collection.JavaConversions$JIteratorWrapper.foreach(JavaConversions.scala:573) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (13/33) at scala.collection.IterableLike$class.foreach(IterableLike.scala:73) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (14/33) at scala.collection.JavaConversions$JListWrapper.foreach(JavaConversions.scala:615) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (15/33) at scala.collection.TraversableLike$class.map(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (16/33) at scala.collection.JavaConversions$JListWrapper.map(JavaConversions.scala:615) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (17/33) at com.mendix.core.action.user.Retriever$class.buildObjects(Retriever.scala:53) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (18/33) at com.mendix.core.action.user.Retriever$class.retrieveFromDatabase(Retriever.scala:35) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (19/33) at com.mendix.core.action.user.RetrieveIdListAction.retrieveFromDatabase(RetrieveIdListAction.scala:15) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (20/33) at com.mendix.core.action.user.RetrieveIdListAction.com$mendix$core$action$user$RetrieveIdListAction$$retrieve(RetrieveIdListAction.scala:51) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (21/33) at com.mendix.core.action.user.RetrieveIdListAction$$anonfun$7.apply(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (22/33) at com.mendix.core.action.user.RetrieveIdListAction$$anonfun$7.apply(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (23/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (24/33) at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (25/33) at scala.collection.immutable.Map$Map3.foreach(Map.scala:164) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (26/33) at scala.collection.TraversableLike$class.map(TraversableLike.scala:233) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (27/33) at scala.collection.immutable.Map$Map3.map(Map.scala:144) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (28/33) at com.mendix.core.action.user.RetrieveIdListAction.executeAction(RetrieveIdListAction.scala:42) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (29/33) at com.mendix.core.action.user.RetrieveIdListAction.executeAction(RetrieveIdListAction.scala:15) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (30/33) at com.mendix.systemwideinterfaces.core.UserAction.execute(UserAction.java:57) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (31/33) at com.mendix.core.actionmanagement.CoreAction.doCall(CoreAction.java:478) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (32/33) at com.mendix.core.actionmanagement.CoreAction.call(CoreAction.java:463) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - M2EE: (33/33) at com.mendix.core.actionmanagement.ActionManager.executeSync(ActionManager.java:198) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: Error in execution of monitored action 'null' (execution id: 8a229cff-7bf1-45f9-a201-86efeb95d3ec, execution type: SCHEDULED_EVENT Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (1/18) java.lang.OutOfMemoryError: GC overhead limit exceeded Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (2/18) at akka.actor.LocalActorRef.postMessageToMailbox(ActorRef.scala:870) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (3/18) at akka.actor.ScalaActorRef$class.forward(ActorRef.scala:1486) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (4/18) at akka.actor.LocalActorRef.forward(ActorRef.scala:605) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (5/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher$$anonfun$receive$1.apply(RequestDispatching.scala:132) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (6/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher$$anonfun$receive$1.apply(RequestDispatching.scala:124) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (7/18) at akka.actor.Actor$class.apply(Actor.scala:545) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (8/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher.apply(RequestDispatching.scala:115) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (9/18) at akka.actor.LocalActorRef.invoke(ActorRef.scala:910) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (10/18) at akka.dispatch.MessageInvocation.invoke(MessageHandling.scala:25) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (11/18) at akka.dispatch.ExecutableMailbox$class.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:223) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (12/18) at akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$4.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:123) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (13/18) at akka.dispatch.ExecutableMailbox$class.run(ExecutorBasedEventDrivenDispatcher.scala:195) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (14/18) at akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$4.run(ExecutorBasedEventDrivenDispatcher.scala:123) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (15/18) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (16/18) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (17/18) at java.lang.Thread.run(Thread.java:662) Jun 22 13:03:10 127.0.0.1 propersa: CRITICAL - ActionManager: (18/18) at akka.dispatch.MonitorableThread.run(ThreadPoolBuilder.scala:192) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: Error occurred while running scheduled event 'BackgroundJobChecker' Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (1/18) java.lang.OutOfMemoryError: GC overhead limit exceeded Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (2/18) at akka.actor.LocalActorRef.postMessageToMailbox(ActorRef.scala:870) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (3/18) at akka.actor.ScalaActorRef$class.forward(ActorRef.scala:1486) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (4/18) at akka.actor.LocalActorRef.forward(ActorRef.scala:605) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (5/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher$$anonfun$receive$1.apply(RequestDispatching.scala:132) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (6/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher$$anonfun$receive$1.apply(RequestDispatching.scala:124) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (7/18) at akka.actor.Actor$class.apply(Actor.scala:545) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (8/18) at com.mendix.externalinterface.connector.RequestDispatching$RequestDispatcher.apply(RequestDispatching.scala:115) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (9/18) at akka.actor.LocalActorRef.invoke(ActorRef.scala:910) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (10/18) at akka.dispatch.MessageInvocation.invoke(MessageHandling.scala:25) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (11/18) at akka.dispatch.ExecutableMailbox$class.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:223) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (12/18) at akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$4.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:123) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (13/18) at akka.dispatch.ExecutableMailbox$class.run(ExecutorBasedEventDrivenDispatcher.scala:195) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (14/18) at akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$4.run(ExecutorBasedEventDrivenDispatcher.scala:123) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (15/18) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (16/18) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (17/18) at java.lang.Thread.run(Thread.java:662) Jun 22 13:03:10 127.0.0.1 propersa: ERROR - ActionManager: (18/18) at akka.dispatch.MonitorableThread.run(ThreadPoolBuilder.scala:192)
asked
2 answers
1

There are two types of memory errors and both require a different solution.
The most common error: "java.lang.OutOfMemoryError". This problem is relatively easy to find and often the stacktrace even mentions the cause. There is one or many processes that consume a large amount of data, so large that it can not add more to the Java Heap (memory).
Most often the microflow is retrieving/evaluating to much data and is running out of memory.


The error you are having is the "GC overhead limit exceeded". Unlike the out of memory error, this does not necessarily indicate that you have to many records in your cache.
Unfortunately this is the most difficult problem to trace or solve. You will need to analyze the memory usage graphs and identify what is causing the problem.

The GC limit is a statistic that Java keeps track of. You are getting this error if Java is spending about 98% of the time actively garbage collecting. This can have many different causes, I'm just going to give a few simple examples here. But as I said you'll have to compare your memory usage statistics with the processes that run at a specific time to draw the right conclusion and act accordingly.

Potential causes

  • You are executing an extremely high volume of microflows that use many objects that have to live in memory for a short period of time. If the nr of microflows and the nr of objects is high enough, it could cause memory to grow faster than it can be collected.
       - Solution 1: Increase the interval so the garbage collector has time to garbage collect between microflows
       - Solution 2: Improve memory usage and use batches / improve efficiency of the microflow

  • There is or are several microflows that execute for a long time, and consume most of the available memory. This leaves only a small percentage of the Java Heap for all other processes, such as interaction with the client, Mx background jobs, etc.
       - Solution: Improve memory usage and use batches / improve efficiency of the microflow
       - Additional action: Increase the available memory for the server

  • There are several users active on the system all working with semi-large data sets. The nr of actions, and thus the nr of objects in memory is so high and changing so frequently that Java can't keep up with garbage collection before risking to run out of memory.
       - Solution: Increase the available memory for the server. This will give Java more time to garbage collect before the Java Heap is full again.

  • The memory usage of the application is slowly increasing over time. In the memory graph it shows that the garbage collection doesn't completely free up all used space. Which indicates a memory leak.
       - Solution: Search through the records that are in the object cache and several random points in time. Identify the objects and session that is keeping the objects. Identify the potential microflows, etc.. and try and solve the memory leak.


One last thing about these errors and their stacktraces, the processes mentioned in these stacktraces are usually not the culprit of these problems. Especially the garbage collection problem, the error happens while initiating a new garbage collection action. GC never starts while running or finishing an activity. Since a microflow can't start a GC action, the cause of your problem (the microflow) will never show in the stacktrace.
The same can also apply to the out of memory error, it can also be that last datagrid with just 5 records in it that is opened by the user. If those 5 objects no longer fit in memory that is what you will see in the stacktrace, not the microflow that might be retrieving a million objects.

See also this Oracle page on the difference between the two errors: https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/memleaks002.html (FYI, i

answered
0

Could it be that the import doesn't use all the resources, but when trying to clean up, it actually runs out of memory? You could try to increase the heapsize using, for example, "-Xmx1024m"

answered