IBM Support

Exposing a Memory Problem Using the System Property mxe.mbocount

Troubleshooting


Problem

This is part 2 of a 3 document series: Diagnosing JVM Memory Problems with the Maximo Application

Resolving The Problem

Exposing a Memory Problem Using the Maximo Debug Property MBOCount

The application fails or slows down due to the lack of memory and an increase in JVM garbage collection processes.

Maximo and other related products provide logging tools to assist with diagnosing memory related performance problems. The most valuable of these tools for memory utilization are the mxe.mbocount and mxe.db.fetchResultLogLimit properties found in the MXServer.properties (release 5), maximo.properties (release 6), or the properties application (release 7). For more information on how to set these properties, see System Properties to Monitor and Troubleshoot Performance.

The results of the mbocount property will generate once per minute in the log and will be similar to what shows below.

...
16 May 2016 16:29:31:692 [INFO] [UI13] [] ACTIONGROUP: mbosets (3), mbos (9)
16 May 2016 16:29:31:693 [INFO] [UI13] [] ALNDOMAIN: mbosets (11), mbos (72)
16 May 2016 16:29:31:693 [INFO] [UI13] [] APPDOCTYPE: mbosets (1), mbos (2)
16 May 2016 16:29:31:693 [INFO] [UI13] [] APPLICATIONAUTH: mbosets (40), mbos (2420)
16 May 2016 16:29:31:693 [INFO] [UI13] [] ASSET: mbosets (124), mbos (83)
16 May 2016 16:29:31:693 [INFO] [UI13] [] ASSETATTRIBUTE: mbosets (149), mbos (276)
16 May 2016 16:29:31:693 [INFO] [UI13] [] ASSETFEATURE: mbosets (10), mbos (null)
16 May 2016 16:29:31:693 [INFO] [UI13] [] ASSETUSERCUST: mbosets (28), mbos (28)
16 May 2016 16:29:31:693 [INFO] [UI13] [] AUTOKEY: mbosets (1), mbos (2)
16 May 2016 16:29:31:693 [INFO] [UI13] [] BBOARDAUDIENCE: mbosets (69), mbos (69)
16 May 2016 16:29:31:693 [INFO] [UI13] [] BULLETINBOARD: mbosets (40), mbos (61)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CI: mbosets (163), mbos (246)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLASSIFICATION: mbosets (362), mbos (718)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLASSPROBABILITY: mbosets (3), mbos (3)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLASSSPEC: mbosets (49), mbos (52)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLASSSPECUSEWITH: mbosets (30), mbos (30)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLASSSTRUCTURE: mbosets (1065), mbos (1293)
16 May 2016 16:29:31:693 [INFO] [UI13] [] CLIENTMATRIX: mbosets (1), mbos (null)
16 May 2016 16:29:31:693 [INFO] [UI13] [] COLLECTIONAUTH: mbosets (2), mbos (2)
16 May 2016 16:29:31:693 [INFO] [UI13] [] COMMLOG: mbosets (6), mbos (10)
16 May 2016 16:29:31:693 [INFO] [UI13] [] COMMLOGDOCS: mbosets (5), mbos (5)
...
16 May 2016 16:22:31:470 [INFO] [UI13] [] WOACTIVITY: mbosets (6), mbos (6)
16 May 2016 16:22:31:470 [INFO] [UI13] [] WORKLOG: mbosets (6), mbos (7)
16 May 2016 16:22:31:470 [INFO] [UI13] [] WORKORDER: mbosets (53), mbos (64863)
16 May 2016 16:22:31:470 [INFO] [UI13] [] WORKPERIOD: mbosets (7), mbos (142)
16 May 2016 16:22:31:471 [INFO] [UI13] [] WORKVIEW: mbosets (37), mbos (65)
16 May 2016 16:22:31:471 [INFO] [UI13] [] WOSERVICEADDRESS: mbosets (2), mbos (2)
16 May 2016 16:22:31:484 [INFO] [UI13] [] BMXAA6373I - No cron task is running for host name 10.128.50.174 server name UI13
16 May 2016 16:22:31:485 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.170. Server name: UI01. Number of users: 15
16 May 2016 16:22:31:485 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.170. Server name: UI02. Number of users: 9
16 May 2016 16:22:31:485 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.171. Server name: UI05. Number of users: 10
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.171. Server name: UI06. Number of users: 14
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.171. Server name: UI07. Number of users: 10
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.173. Server name: UI09. Number of users: 7
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.173. Server name: UI10. Number of users: 7
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.173. Server name: UI11. Number of users: 11
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.174. Server name: UI13. Number of users: 12. WebClientSessions: (12)
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.174. Server name: UI14. Number of users: 7
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.50.174. Server name: UI15. Number of users: 7
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.100.213. Server name: UI21. Number of users: 7
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.100.214. Server name: UI31. Number of users: 14
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.100.215. Server name: UI41. Number of users: 14
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.100.216. Server name: UI51. Number of users: 21
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6370I - Total number of users connected to the system: 165
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1948051224.
16 May 2016 16:22:45:704 [INFO] [UI13] [CID-MXREST-1353] Correlation started.

The log snippet above shows 2 possible problem areas.

While there is no magic number that demonstrates a memory leak, most operations will complete with less than 20,000 objects. Even more can be loaded for some operations but they will release hen the operation is complete (usually under 2 or 3 minutes). The fact that there are nearly 65,000 workorder objects in memory is an indicator that there may be a problem. If the mbocount workorder object is filtered out of the log, it would look as shown below and it demonstrates that the bulk of this problem occurred over a period of about 24 minutes when the workorder MBO went from 1800 to nearly 60,000 and was never released. This information can be helpful in determining what was being done at the time of the problem. In this case, a key contributing factor is that the workorder object is one of the largest of the MBOs so this is using a good deal of memory.

16 May 2016 16:21:39:991 [INFO] [UI13] [] WORKORDER: mbosets (48), mbos (59062)
16 May 2016 14:22:40:564 [INFO] [UI13] [] WORKORDER: mbosets (48), mbos (59180)
16 May 2016 16:22:31:470 [INFO] [UI13] [] WORKORDER: mbosets (53), mbos (64863)
16 May 2016 16:23:31:493 [INFO] [UI13] [] WORKORDER: mbosets (47), mbos (57163)
16 May 2016 16:24:31:503 [INFO] [UI13] [] WORKORDER: mbosets (42), mbos (40923)
16 May 2016 16:25:31:512 [INFO] [UI13] [] WORKORDER: mbosets (56), mbos (65003)
16 May 2016 16:26:31:522 [INFO] [UI13] [] WORKORDER: mbosets (53), mbos (60923)
16 May 2016 16:27:31:680 [INFO] [UI13] [] WORKORDER: mbosets (52), mbos (59112)
16 May 2016 16:28:31:688 [INFO] [UI13] [] WORKORDER: mbosets (41), mbos (30242)
16 May 2016 16:29:31:696 [INFO] [UI13] [] WORKORDER: mbosets (29), mbos (25002)
16 May 2016 16:30:31:705 [INFO] [UI13] [] WORKORDER: mbosets (39), mbos (51762)

Looking at it over time, you can see that even when mbosets drop to 29, there are still over 25,000 mbosets open This means that there are almost 25,000 empty mbosets. This is probably not a memory problem since they are empty sets, but it is an indication that these sets are not being properly closed and may cause a memory leak in the future.

Some of the helpful information that appears in the log when the mbocount property is enabled includes cron tasks and where they are running, number of users and what JVMs they are connected to, and total memory / available memory inside the JVM.

16 May 2016 16:22:31:484 [INFO] [UI13] [] BMXAA6373I - No cron task is running for host name 10.128.50.174 server name UI13
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6369I - Server host: 10.128.100.216. Server name: UI51. Number of users: 21
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA6370I - Total number of users connected to the system: 165
16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1948051224.
16 May 2016 16:22:45:704 [INFO] [UI13] [CID-MXREST-1353] Correlation started.

Notice that in this case, the four gigabytes of memory allocated to the JVM are over 50% used, with less than 2 gigabytes free. It is likely the garbage collection is running very frequently at this point, trying to free memory. Monitoring the processor will show very high utilization and users will be unable to work. In this case, the JVM ultimately failed and had to be restarted.

mbocount memory entries can be filtered in much the same way as the workorder object was above. This will show memory availability consistently dropping as workorder objects consistently increase.

16 May 2016 16:22:31:486 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1948051224.
16 May 2016 16:23:31:496 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1613399432.
16 May 2016 16:24:31:506 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1395289760.
16 May 2016 16:25:31:515 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 815014192.
16 May 2016 16:26:31:675 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 205073688.
16 May 2016 16:27:31:683 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 3315475648.
16 May 2016 16:28:31:691 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 2458019040.
16 May 2016 16:29:31:699 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1665701432.
16 May 2016 16:30:31:708 [INFO] [UI13] [] BMXAA7019I - The total memory is 4294967296 and the memory available is 1596630528.

As shown here, garbage collection is quite effective and actually recovered from less than 800 MB of available memory at one point. Ultimately, if the application does not release the memory, garbage collection cannot succeed.


Back to - LDAP Troubleshooting Master Dociument -
Forward to - J2EE server checks for J2EE security enabled -
Understanding Java Memory Management

[{"Product":{"code":"SSLKT6","label":"IBM Maximo Asset Management"},"Business Unit":{"code":"BU055","label":"Cognitive Applications"},"Component":"System Related","Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"Version Independent","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}},{"Product":{"code":"SSLKTY","label":"Maximo Asset Management for IT"},"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Component":" ","Platform":[{"code":"","label":""}],"Version":"","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}},{"Product":{"code":"SSWK4A","label":"Maximo Asset Management Essentials"},"Business Unit":{"code":"BU055","label":"Cognitive Applications"},"Component":" ","Platform":[{"code":"","label":""}],"Version":"","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}},{"Product":{"code":"SSKTXT","label":"Tivoli Change and Configuration Management Database"},"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Component":" ","Platform":[{"code":"","label":""}],"Version":"","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}},{"Product":{"code":"SS6HJK","label":"Tivoli Service Request Manager"},"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Component":" ","Platform":[{"code":"","label":""}],"Version":"","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}},{"Product":{"code":"SSWT9A","label":"IBM Control Desk"},"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Component":" ","Platform":[{"code":"","label":""}],"Version":"","Edition":"","Line of Business":{"code":"LOB59","label":"Sustainability Software"}}]

Document Information

Modified date:
17 June 2018

UID

swg21326803