Delete > 500.000 records > out of memory

3
Hi everybody, On a Mendix-hosted environment, we have deployed an ap that uses the logging module of the app-store. We however face the problem that there are a lot of entries in written to the db (over 500.000) and clicking the "delete all" button shows the "in progress" screen but after 30? seconds the screen freezes and the logging shows the exception below. After restarting m2ee and trying again, deleting doesn't work (same problem) or only partitially works. I pasted the stacktrace and the delete-java-action-code below. My question is how I can fix the out of memory. Is just the batchsize too high (10.000) Or would it at all be impossible to delete this amount of records with 1 buttonpress (meaning that the action should be changed, by letting only delete 50.000? records for e.g.)? Stacktrace Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: An error has occurred while handling the request. [User 'gcoroberto@greencloudsonline.com' with roles 'GreenClouds_Operations'] Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (1/102) com.mendix.core.CoreException: Exception occurred in action 'Microflow [Logging.DeleteMessages]', all database changes executed by this action were rolled back Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (2/102) at com.mendix.core.actionmanagement.CoreAction.d(SourceFile:553) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (3/102) Caused by: com.mendix.core.CoreException: Exception occurred in microflow 'Logging.DeleteMessages' for activity 'batch delete all records Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (4/102) ', all database changes executed by this microflow were rolled back Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (5/102) at kM.b(SourceFile:252) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (6/102) Caused by: com.mendix.core.CoreException: af: An exception has occurred for the following request(s): Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (7/102) jF (depth = 0, amount = 10000): //Logging.Message Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (8/102) at it.b(SourceFile:167) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (9/102) Caused by: af: An exception has occurred for the following request(s): Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (10/102) jF (depth = 0, amount = 10000): //Logging.Message Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (11/102) Caused by: af: Exception occurred while retrieving data. (SQL State: 53200, Error Code: 0) Detail Message: java.lang.OutOfMemoryError: Java heap space, org.postgresql.util.PSQLException: Ran out of memory retrieving query results., java.lang.OutOfMemoryError: Java heap space, org.postgresql.util.PSQLException: Ran out of memory retrieving query results., java.lang.OutOfMemoryError: Java heap space, org.postgresql.util.PSQLException: Ran out of memory retrieving query results., java.lang.OutOfMemoryError: Java heap space Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (12/102) Caused by: org.postgresql.util.PSQLException: Ran out of memory retrieving query results. Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (13/102) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1817) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (14/102) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (15/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (16/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (17/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (18/102) at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (19/102) at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (20/102) at aA.a(SourceFile:341) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (21/102) at aA.a(SourceFile:240) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (22/102) at aA.a(SourceFile:190) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (23/102) at aA.a(SourceFile:179) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (24/102) at iB.a(SourceFile:47) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (25/102) at go.a(SourceFile:182) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (26/102) at go.a(SourceFile:140) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (27/102) at go.a(SourceFile:88) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (28/102) at lw.a(SourceFile:69) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (29/102) at jD.a(SourceFile:47) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (30/102) at jm.a(SourceFile:222) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (31/102) at fJ.b(SourceFile:121) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (32/102) at fJ.a(SourceFile:63) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (33/102) at iu.a(SourceFile:58) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (34/102) at iu.executeAction(SourceFile:20) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (35/102) at com.mendix.systemwideinterfaces.core.UserAction.execute(SourceFile:49) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (36/102) at com.mendix.core.actionmanagement.CoreAction.call(SourceFile:473) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (37/102) at it.b(SourceFile:155) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (38/102) at com.mendix.core.Core.retrieveXPathQuery(SourceFile:819) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (39/102) at com.mendix.core.Core.retrieveXPathQueryEscaped(SourceFile:992) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (40/102) at logging.actions.BatchDeleteAllMessages.executeAction(BatchDeleteAllMessages.java:48) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (41/102) at logging.actions.BatchDeleteAllMessages.executeAction(BatchDeleteAllMessages.java:27) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (42/102) at com.mendix.systemwideinterfaces.core.UserAction.execute(SourceFile:49) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (43/102) at com.mendix.core.actionmanagement.CoreAction.call(SourceFile:473) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (44/102) at it.b(SourceFile:155) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (45/102) at com.mendix.core.Core.execute(SourceFile:191) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (46/102) at hi.a(SourceFile:70) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (47/102) at kM.a(SourceFile:67) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (48/102) at eR.executeAction(SourceFile:96) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (49/102) at com.mendix.systemwideinterfaces.core.UserAction.execute(SourceFile:49) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (50/102) at com.mendix.core.actionmanagement.CoreAction.call(SourceFile:473) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (51/102) at it.b(SourceFile:155) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (52/102) at com.mendix.core.Core.execute(SourceFile:191) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (53/102) at dA.execute(SourceFile:183) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (54/102) at ju.a(SourceFile:299) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (55/102) at ju.a(SourceFile:230) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (56/102) at ju.processRequest(SourceFile:174) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (57/102) at fF.a(SourceFile:71) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (58/102) at com.mendix.core.MxRuntime.processRequest(SourceFile:924) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (59/102) at com.mendix.m2ee.server.handler.RuntimeHandler.handle(RuntimeHandler.java:42) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (60/102) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:113) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (61/102) at org.eclipse.jetty.server.Server.handle(Server.java:334) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (62/102) at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:559) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (63/102) at org.eclipse.jetty.server.HttpConnection$RequestHandler.content(HttpConnection.java:1007) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (64/102) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:747) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (65/102) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:209) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (66/102) at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:406) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (67/102) at org.eclipse.jetty.server.nio.BlockingChannelConnector$ConnectorEndPoint.run(BlockingChannelConnector.java:187) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (68/102) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (69/102) at java.lang.Thread.run(Thread.java:662) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (70/102) Caused by: java.lang.OutOfMemoryError: Java heap space Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (71/102) at org.postgresql.core.PGStream.ReceiveTupleV3(PGStream.java:364) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (72/102) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1814) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (73/102) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (74/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (75/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (76/102) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (77/102) at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (78/102) at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (79/102) at aA.a(SourceFile:341) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (80/102) at aA.a(SourceFile:240) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (81/102) at aA.a(SourceFile:190) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (82/102) at aA.a(SourceFile:179) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (83/102) at iB.a(SourceFile:47) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (84/102) at go.a(SourceFile:182) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (85/102) at go.a(SourceFile:140) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (86/102) at go.a(SourceFile:88) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (87/102) at lw.a(SourceFile:69) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (88/102) at jD.a(SourceFile:47) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (89/102) at jm.a(SourceFile:222) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (90/102) at fJ.b(SourceFile:121) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (91/102) at fJ.a(SourceFile:63) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (92/102) at iu.a(SourceFile:58) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (93/102) at iu.executeAction(SourceFile:20) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (94/102) at com.mendix.systemwideinterfaces.core.UserAction.execute(SourceFile:49) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (95/102) at com.mendix.core.actionmanagement.CoreAction.call(SourceFile:473) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (96/102) at it.b(SourceFile:155) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (97/102) at com.mendix.core.Core.retrieveXPathQuery(SourceFile:819) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (98/102) at com.mendix.core.Core.retrieveXPathQueryEscaped(SourceFile:992) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (99/102) at logging.actions.BatchDeleteAllMessages.executeAction(BatchDeleteAllMessages.java:48) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (100/102) at logging.actions.BatchDeleteAllMessages.executeAction(BatchDeleteAllMessages.java:27) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (101/102) at com.mendix.systemwideinterfaces.core.UserAction.execute(SourceFile:49) Sep 12 16:38:22 127.0.0.1 greprod: ERROR - Connector: (102/102) at com.mendix.core.actionmanagement.CoreAction.call(SourceFile:473) Code delete-action final IContext context = this.getContext(); final Map<String, String> sortOrder = new HashMap<String, String>(); final IRemoveBatch batch = Core.removeBatch(context, Message.entityName, 10000, false, false); List<IMendixObject> objectList; boolean done = false; while (!done) { objectList = Core.retrieveXPathQueryEscaped(context, "//%s", 10000, 0, sortOrder, 0, Message.entityName); if (!objectList.isEmpty()) { for (final IMendixObject object : objectList) { batch.removeObject(object); } batch.commit(); objectList.clear(); } else { done = true; } } this.addRefreshClass(Message.entityName); return Boolean.TRUE; I'd like to hear!
asked
4 answers
3

Hi Roberto,

Note that delete behavior has serious impact on the speed of deletion, so consider removing delete behavior of that entity (if any).

Did you try the deleteAll method of the communitycommons package? I'm pretty curious whether that one is working better on this set of objects. It uses an DB retrieval schema instead of retrieveXPath, so I expect it is a bit more efficient in memory usage.

Its batchsize is 10.000 as well, that worked for me before.

answered
1

500.000 is really too many records for a logging module. On what setting did you set the log level? From the documentation:

Writing all log messages to the database can have a negative impact on the performance of your application, depending on the number of messages. In a production environment, it is recommended to log only messages of level WARNING and higher.

So that's a point to start with. If you're app is logging too many logging records, you should consider a cleanup scheduled event which removes old (for instance all records older than a week)logging records.

To solve this issue, you really should delete in smaller batches. Deleting 500000 objects with a microflow could cause trouble, but with a java-action it should work. Although it could take some time. Best way is to delete in batches, 50000 is a safe amount of objects. After doing this, you should really log less or cleanup.

answered
0

@Samet Sure I could try. What I wonder about is if anyone can predict if only a smaller batch-size would help, or if I have to limit the amount of records that are deleted (to lets say 50.000)

Regarding the java-code I would not expect a big difference (regarding the (out of) memory) for deleting 10.000 records and 500.000 records, because a list of 10.000 records is retrieved (in objectList) and after committing the batch this is cleared and filled again... Should perhaps the Core.removeBatch also be called everytime inside the loop?

I'd like to hear some advice on

  • [1] If only limiting the batch-size would help enough
  • [2] Or if it is necesary to have a limit on a max # records
  • [3] What would be an advisable batch-size?
answered
0

Update (in a new answer, because I think that is clearer than editing the (large) openingspost):

TOday I tested extensively with the deleteAll java-action from the community commons package.

1: I tried 10.000 as BATCHSIZEREMOVE, 4.000, 1000 but all gave me out of mem (on hosted env). 2: Locally I only tested with 10.000 and gave me out of mem as well 3: BATCHSIZEREMOVE set to 500 worked more or less locally and remote, but with a strange side-effect: it didn't delete all my records, but only about 50% each time.

I started with 285.725 records, and it went from

  • 285.725 to
  • 142.726 to
  • 71.228 to
  • 35.501 to
  • 17.502 to
  • 8.503 to
  • 4005 to
  • 2001 to
  • 1001 to
  • 501 to
  • 2 to
  • 2 to
  • 0

I tried to check and debug the java-code but no luck: I don't understand why it only deletes (about) 50%.

What I do see in the logging every time te java-action finished was a (warning) message like this:

[deleteAll] After delete all there are 35501 objects remaining. This might be a result of the configured security or deletebehavior.

But: the object I try to deleteAll, doesn't have associations (and thus no delete behavior). And the userrole is allowed to delete.

Anyone ideas why this strange "I'll only delete 50% of your records" behavior occurs?

Of course I could switch back to the "old delete-all option" with a low batch-size; for that I didn't have time today (maybe later), but this one seems to be more efficient (as it only retrieves the IDs of the records to delete...

answered