Information Steward Purge utility failing

system · July 19, 2018, 8:40am

Hi there. Running IS 14.2.5.756 and SAP BusinessObjects BI Platform 4.1 Support Pack 5. The daily Purge utility to remove old failed data suddenly started failing every day a few months back. The following error is logged in the file E:\IPS\InformationSteward\MM\log\InformationSteward.SchedulingService.log:

[C] 2018-07-18 20:00:20.953 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Initializing environment from EnterpriseNode 789.
[E] 2018-07-18 20:00:20.981 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Process ID = 10352 on machine sapbdpdb1.sap.shoprite.co.za.
[E] 2018-07-18 20:00:20.981 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Processing [object id=622577] (SCH-10001)
[E] 2018-07-18 20:00:21.037 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Unable to retrieve integrator defined JVM Arguments: while trying to invoke the method com.bobj.mm.integratorSchema.UtilityDocument.getUtility() of a null object loaded from local variable ‘document’ (SCH-10012)
[E] 2018-07-18 20:00:21.043 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Job launch command: “E:/IPS/SAP BusinessObjects Enterprise XI 4.0/win64_x64/sapjvm/jre/bin/java” -Xms256m -Xmx1024m -cp E:/IPS/InformationSteward/MM/lib/MMLoader.jar; -Djava.system.class.loader=com.bobj.ConfigurableClassLoader -Dclassloader.properties=E:/IPS/InformationSteward/MM/config/classloader.properties -Dtracelog.configfile=E:/IPS/InformationSteward/MM/config/tracelog.ini -Dlib=E:/IPS/InformationSteward/MM/lib -Dext=E:/IPS/InformationSteward/MM/lib/ext -Dbo_home=E:/IPS/ -Dboe_sdk=“E:/IPS/SAP BusinessObjects Enterprise XI 4.0/java/lib/” -DWEBAPPDIR=E:/IPS/InformationSteward/ -DINSTALLDIR=E:/IPS/InformationSteward/ -DLOG.DIRECTORY=E:/IPS/InformationSteward//MM/log/ -DLOG.FILENAME=PurgeUtility_622577.log -Druntime_files=E:/IPS/InformationSteward/MM/temp/622577 -DBOEDLLDIR=“E:/IPS/SAP BusinessObjects Enterprise XI 4.0/win64_x64/” -Dbusinessobjects.connectivity.directory -Dicc_resources=E:/IPS/InformationSteward//MM/resources -XX:MaxPermSize=256m -Xmx1024m com.bobj.mm.utility.Utility com.sap.icc.utility.PurgeUtility -c MM.properties -configurationObject 622577 boeLogonToken ************* boeSystemSession *************
[E] 2018-07-18 20:00:21.451 [SchedulingService][Thread-5] Output>Extracting arguments from E:\IPS\InformationSteward\MM\bin…\config\MM.properties.
[E] 2018-07-18 20:00:24.196 [SchedulingService][Thread-5] Output>Initializing environment from EnterpriseNode 789.
[E] 2018-07-18 20:00:24.249 [SchedulingService][Thread-5] Output>Extracting arguments from E:\IPS\InformationSteward\MM\bin…\config\MM.properties.
[E] 2018-07-18 20:00:26.548 [SchedulingService][Thread-4] Error>18 Jul 2018 8:00:26 PM com.acta.db.ActaDbManager addDBConnectionFactory
[E] 2018-07-18 20:00:26.548 [SchedulingService][Thread-4] Error>SEVERE: Unable to create connection factory for Oracle:com.acta.db.ActaOracleConnectionFactory. null (BODI-3013019)
[E] 2018-07-18 20:00:26.551 [SchedulingService][Thread-4] Error>18 Jul 2018 8:00:26 PM com.acta.db.ActaDbManager addDBConnectionFactory
[E] 2018-07-18 20:00:26.551 [SchedulingService][Thread-4] Error>SEVERE: Unable to create connection factory for MySQL:com.acta.db.ActaMySqlConnectionFactory. null (BODI-3013019)
[E] 2018-07-18 20:00:26.552 [SchedulingService][Thread-4] Error>18 Jul 2018 8:00:26 PM com.acta.db.ActaDbManager addDBConnectionFactory
[E] 2018-07-18 20:00:26.552 [SchedulingService][Thread-4] Error>SEVERE: Unable to create connection factory for HANA:com.acta.db.ActaHANAConnectionFactory. null (BODI-3013019)
[E] 2018-07-18 20:00:26.553 [SchedulingService][Thread-4] Error>18 Jul 2018 8:00:26 PM com.acta.db.ActaDbManager addDBConnectionFactory
[E] 2018-07-18 20:00:26.553 [SchedulingService][Thread-4] Error>SEVERE: Unable to create connection factory for SQL_Anywhere:com.acta.db.ActaSQLAnywhereConnectionFactory. null (BODI-3013019)
[E] 2018-07-18 20:00:26.554 [SchedulingService][Thread-4] Error>18 Jul 2018 8:00:26 PM com.acta.db.ActaDbManager init
[E] 2018-07-18 20:00:26.554 [SchedulingService][Thread-4] Error>INFO: Delaying the loading of DB2 JDBC driver classes. (BODI-3013011)
[E] 2018-07-18 20:01:04.784 [SchedulingService][Thread-4] Error>Exception in thread “main” java.lang.OutOfMemoryError: GC overhead limit exceeded
[E] 2018-07-18 20:01:04.856 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.TDSReader.mark(IOBuffer.java:4918)
[E] 2018-07-18 20:01:04.856 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.ServerDTVImpl.getValuePrep(dtv.java:2444)
[E] 2018-07-18 20:01:04.857 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.ServerDTVImpl.skipValue(dtv.java:2356)
[E] 2018-07-18 20:01:04.857 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.DTV.skipValue(dtv.java:104)
[E] 2018-07-18 20:01:04.857 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.Column.skipValue(Column.java:86)
[E] 2018-07-18 20:01:04.858 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.skipColumns(SQLServerResultSet.java:156)
[E] 2018-07-18 20:01:04.858 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.discardCurrentRow(SQLServerResultSet.java:1716)
[E] 2018-07-18 20:01:04.858 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.fetchBufferNext(SQLServerResultSet.java:1774)
[E] 2018-07-18 20:01:04.858 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.discardFetchBuffer(SQLServerResultSet.java:5014)
[E] 2018-07-18 20:01:04.859 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.closeInternal(SQLServerResultSet.java:581)
[E] 2018-07-18 20:01:04.859 [SchedulingService][Thread-4] Error> at com.microsoft.sqlserver.jdbc.SQLServerResultSet.close(SQLServerResultSet.java:597)
[E] 2018-07-18 20:01:04.859 [SchedulingService][Thread-4] Error> at com.acta.repo.ALRepoObject.executeQuery(ALRepoObject.java:542)
[E] 2018-07-18 20:01:04.859 [SchedulingService][Thread-4] Error> at com.acta.repo.ALHistories.getHistory(ALHistories.java:199)
[E] 2018-07-18 20:01:04.860 [SchedulingService][Thread-4] Error> at com.acta.repo.ALHistories.getHistory(ALHistories.java:116)
[E] 2018-07-18 20:01:04.860 [SchedulingService][Thread-4] Error> at com.sap.icc.dataservices.DSJobHelper.cleanUpLogFiles(DSJobHelper.java:319)
[E] 2018-07-18 20:01:04.860 [SchedulingService][Thread-4] Error> at com.sap.icc.utility.PurgeUtility.cleanupLogs(PurgeUtility.java:245)
[E] 2018-07-18 20:01:04.861 [SchedulingService][Thread-4] Error> at com.sap.icc.utility.PurgeUtility.execute(PurgeUtility.java:128)
[E] 2018-07-18 20:01:04.861 [SchedulingService][Thread-4] Error> at com.bobj.mm.utility.Utility.runExecute(Utility.java:454)
[E] 2018-07-18 20:01:04.861 [SchedulingService][Thread-4] Error> at com.bobj.mm.core.Main.run(Main.java:1265)
[E] 2018-07-18 20:01:04.861 [SchedulingService][Thread-4] Error> at com.bobj.mm.core.Main.main(Main.java:242)
[E] 2018-07-18 20:01:05.261 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Job failed with error code: 1 (SCH-10003)

So from that I think this is the reason for the failure:

[E] 2018-07-18 20:01:04.784 [SchedulingService][Thread-4] Error>Exception in thread “main” java.lang.OutOfMemoryError: GC overhead limit exceeded

And from the below bit I can see that the initial and maximum memory allocations for the JVM are set to 256Mb and 1024Mb :

[E] 2018-07-18 20:00:21.043 [SchedulingService][ORBacus:ThreadPerRequest:Dispatcher] Job launch command: “E:/IPS/SAP BusinessObjects Enterprise XI 4.0/win64_x64/sapjvm/jre/bin/java” -Xms256m -Xmx1024m -cp E:/IPS/InformationSteward/MM/lib/MMLoader.jar; -Djava.system.class.loader=com.bobj.ConfigurableClassLoader -Dclassloader.properties=E:/IPS/InformationSteward/MM/config/classloader.properties -Dtracelog.configfile=E:/IPS/InformationSteward/MM/config/tracelog.ini -Dlib=E:/IPS/InformationSteward/MM/lib -Dext=E:/IPS/InformationSteward/MM/lib/ext -Dbo_home=E:/IPS/ -Dboe_sdk=“E:/IPS/SAP BusinessObjects Enterprise XI 4.0/java/lib/” -DWEBAPPDIR=E:/IPS/InformationSteward/ -DINSTALLDIR=E:/IPS/InformationSteward/ -DLOG.DIRECTORY=E:/IPS/InformationSteward//MM/log/ -DLOG.FILENAME=PurgeUtility_622577.log -Druntime_files=E:/IPS/InformationSteward/MM/temp/622577 -DBOEDLLDIR=“E:/IPS/SAP BusinessObjects Enterprise XI 4.0/win64_x64/” -Dbusinessobjects.connectivity.directory -Dicc_resources=E:/IPS/InformationSteward//MM/resources -XX:MaxPermSize=256m -Xmx1024m com.bobj.mm.utility.Utility com.sap.icc.utility.PurgeUtility -c MM.properties -configurationObject 622577 boeLogonToken ************* boeSystemSession *************

So now I want to try changing the maximum memory allocation (-Xmx1024m) to a higher value but cannot find where this is set. I have checked the properties of all the servers running in the CMC and none have that value set for -Xmx.

I did manage to find a file named IS_JVM_Config.txt in E:\IPS\InformationSteward\MM\config which has one line in it as follows:

-Xms256m -Xmx1024m

Which is exactly what I’m seeing in the log, however when I change the -Xmx value in this file and reboot the server, I don’t see any change in -Xmx value in the error log. Any assistance appreciated.

ClintL (BOB member since 2011-01-06)

system · July 20, 2018, 7:54am

UPDATE: I have resolved the issue. In case anyone experiences the same problem here is what I did.

Firstly I found SAP note 2181988 which describes the issue exactly, however the resolution is to apply patch 1 to our version. This means the memory settings are not configurable (or at least not in our version).

But the note does say “This error happens when deleting large amount of task execution history from the repository tables, the history information is cached, and, due to the large volume of data, the default allocated memory for the Purge utility process is not sufficient, resulting in a Java Heap Space Exception.”

So I decided to try manually deleting some history from some of the tables directly to reduce the memory requirement. I deleted all data older than 6 months from the following tables in the IS repo : AL_HISTORY, AL_HISTORY_INFO and AL_STATISTICS. The END_TIME field in AL_HISTORY can be used for the date, and then all three tables share the same key field, OBJECT_KEY, so that can be used to delete the records in the other two tables where the OBJECT_KEY no longer exists in AL_HISTORY.

NB: I backed up these three tables before I started and then dropped the backup tables once I confirmed IS was still working fine after the deletes.

Then I tried running the Purge utility again with the data retention periods set to 150 days (± 5 months) and it worked. But just a word of caution, the Purge utility took 6 hours to run because of the large volume of history in the many other tables that it deletes from.

ClintL (BOB member since 2011-01-06)