EMA :6: Finding Activation/Passivation Related Issues

Save point is a wonderful feature if used appropriately; otherwise it can bring down a server in no time. That’s what we faced once on SCM PIM. To triage these type of issues, EMA alone is not enough. Here I used thread dump in addition to heap dumps. When the server was going down, I was having no clue why it’s going down, and that’s when thread dumps helped me out, which were showing explicit save point calls, as shown in the following thread stacks snippet taken from the thread dump:

"[ACTIVE] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x4b466c00 nid=0x34ba runnable [0x4d000000]
   java.lang.Thread.State: RUNNABLE
        at oracle.jbo.server.ViewDefImpl.getAttributeDefImpls(ViewDefImpl.java:782)
        at oracle.jbo.server.ViewDefImpl.getAttributeDefs(ViewDefImpl.java:800)
        at oracle.jbo.server.ViewRowImpl.getAttributeNames(ViewRowImpl.java:2783)
        at oracle.apps.scm.productCatalogManagement.versions.protectedModel.view.ChangeVersionViewRowImpl.getAttributeInternal(ChangeVersionViewRowImpl.java:61)
        at oracle.apps.scm.productModel.items.protectedUiModel.view.ItemVORowImpl.getRedLineCurrentPhaseId(ItemVORowImpl.java:26485)
        at oracle.apps.scm.productModel.items.protectedUiModel.view.ItemVORowImpl$AttributesEnum$611.get(ItemVORowImpl.java:7993)
        at oracle.apps.scm.productModel.items.protectedUiModel.view.ItemVORowImpl.getAttrInvokeAccessor(ItemVORowImpl.java:21807)
        at oracle.jbo.server.ViewRowImpl.getAttribute(ViewRowImpl.java:830)
        at oracle.jbo.server.ViewRowImpl.renderAttributeInXMLElement(ViewRowImpl.java:4269)
        at oracle.jbo.server.ViewRowImpl.renderAttributeInXMLElement(ViewRowImpl.java:4298)
        at oracle.jbo.server.ViewObjectImpl.passivateTransients(ViewObjectImpl.java:16954)
        at oracle.jbo.server.ViewObjectImpl.passivateTransients(ViewObjectImpl.java:16890)
        at oracle.jbo.server.ViewObjectImpl.passivateState(ViewObjectImpl.java:16686)
        at oracle.jbo.server.ViewObjectImpl.passivateState(ViewObjectImpl.java:16626)
        at oracle.jbo.server.ViewObjectImpl.doPassivateSettings(ViewObjectImpl.java:18545)
        at oracle.jbo.server.ApplicationModuleImpl.passivateVOs(ApplicationModuleImpl.java:7556)
        at oracle.jbo.server.ApplicationModuleImpl.doPassivateState(ApplicationModuleImpl.java:7367)
        at oracle.jbo.server.ApplicationModuleImpl.doPassivateAMState(ApplicationModuleImpl.java:7358)
        at oracle.jbo.server.Serializer.passivate(Serializer.java:210)
        at oracle.jbo.server.DBSerializer.passivateRootAM(DBSerializer.java:290)
        at oracle.jbo.server.DBSerializer.passivateRootAM(DBSerializer.java:267)
        at oracle.jbo.server.ApplicationModuleImpl.passivateStateInternal(ApplicationModuleImpl.java:5820)
        - locked <0xad48c908> (a oracle.jbo.JboSyncLock)
        at oracle.jbo.server.ApplicationModuleImpl.passivateState(ApplicationModuleImpl.java:5681)
        at oracle.jbo.server.ApplicationModuleImpl.passivateStateForUndo(ApplicationModuleImpl.java:8641)
        - locked <0xad48c908> (a oracle.jbo.JboSyncLock)
        at oracle.adf.model.bc4j.DCJboDataControl.createSavepoint(DCJboDataControl.java:3143)
        at oracle.adf.model.dcframe.LocalTransactionHandler.createSavepoint(LocalTransactionHandler.java:73)
        at oracle.adf.model.dcframe.DataControlFrameImpl.createSavepoint(DataControlFrameImpl.java:529)
        at oracle.adfinternal.controller.util.model.DCFrameImpl.createSavepoint(DCFrameImpl.java:28)        at oracle.adfinternal.controller.activity.TaskFlowCallActivityLogic.initializeModel(TaskFlowCallActivityLogic.java:999)
        at oracle.adfinternal.controller.activity.TaskFlowCallActivityLogic.enterTaskFlow(TaskFlowCallActivityLogic.java:614)
        at oracle.adfinternal.controller.activity.TaskFlowCallActivityLogic.invokeLocalTaskFlow(TaskFlowCallActivityLogic.java:336)
        at oracle.adfinternal.controller.activity.TaskFlowCallActivityLogic.execute(TaskFlowCallActivityLogic.java:163)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.executeActivity(ControlFlowEngine.java:989)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.doRouting(ControlFlowEngine.java:878)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.doRouting(ControlFlowEngine.java:777)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.routeFromActivity(ControlFlowEngine.java:551)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.performControlFlow(ControlFlowEngine.java:147)
        at oracle.adfinternal.controller.application.NavigationHandlerImpl.handleAdfcNavigation(NavigationHandlerImpl.java:109)
        at oracle.adfinternal.controller.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:78)
. . .
 at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2202)
        at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2108)
        at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1432)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

"[ACTIVE] ExecuteThread: '14' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x45cc4c00 nid=0x1388 runnable [0x451fc000]

   java.lang.Thread.State: RUNNABLE
        at oracle.jbo.server.ViewDefImpl.getAttributeDefImpls(ViewDefImpl.java:782)
        at oracle.jbo.server.ViewDefImpl.getAttributeDefs(ViewDefImpl.java:800)
        at oracle.jbo.server.ViewRowImpl.getAttributeNames(ViewRowImpl.java:2783)
        at oracle.apps.scm.productCatalogManagement.versions.protectedModel.view.ChangeVersionViewRowImpl.getAttributeInternal(ChangeVersionViewRowImpl.java:61)
        at oracle.apps.scm.productModel.items.protectedUiModel.view.ItemVORowImpl.getTemplateItemFlag(ItemVORowImpl.java:22215)
        at oracle.apps.scm.productModel.items.protectedUiModel.view.ItemVORowImpl.isAttributeUpdateable(ItemVORowImpl.java:21848)
        at oracle.jbo.server.ViewRowImpl.readAttributeFromXMLElement(ViewRowImpl.java:4313)
        at oracle.jbo.server.ViewObjectImpl.activateTransientAttribute(ViewObjectImpl.java:17613)
        at oracle.jbo.server.ViewObjectImpl.activateTransients(ViewObjectImpl.java:17679)
        at oracle.jbo.server.ViewObjectImpl.activateTransients(ViewObjectImpl.java:17627)
        at oracle.jbo.server.ViewObjectImpl.activateState(ViewObjectImpl.java:17850)
        at oracle.jbo.server.ViewObjectImpl.activateState(ViewObjectImpl.java:17745)
        at oracle.jbo.server.ViewRowSetIteratorImpl.activateIteratorState(ViewRowSetIteratorImpl.java:3989)
        - locked <0xb0378e40> (a oracle.jbo.JboSyncLock)
        at oracle.jbo.server.ViewRowSetImpl.activateIteratorState(ViewRowSetImpl.java:6992)
        at oracle.jbo.server.ViewObjectImpl.activateIteratorState(ViewObjectImpl.java:18080)
        at oracle.jbo.server.ApplicationModuleImpl.activateVOs(ApplicationModuleImpl.java:8021)
        at oracle.jbo.server.ApplicationModuleImpl.doActivateState(ApplicationModuleImpl.java:7767)
        at oracle.jbo.server.ApplicationModuleImpl.doActivateAMState(ApplicationModuleImpl.java:7734)
        at oracle.jbo.server.Serializer.activate(Serializer.java:293)
        at oracle.jbo.server.DBSerializer.activateRootAM(DBSerializer.java:330)
        at oracle.jbo.server.ApplicationModuleImpl.activateFromStack(ApplicationModuleImpl.java:6306)
        at oracle.jbo.server.ApplicationModuleImpl.activateState(ApplicationModuleImpl.java:6166)
        - locked <0xb0378e40> (a oracle.jbo.JboSyncLock)
        at oracle.jbo.server.ApplicationModuleImpl.activateStateForUndo(ApplicationModuleImpl.java:8710)
        - locked <0xb0378e40> (a oracle.jbo.JboSyncLock)
        at oracle.adf.model.bc4j.DCJboDataControl.restoreSavepoint(DCJboDataControl.java:3149)
        at oracle.adf.model.dcframe.LocalTransactionHandler.restoreSavepoint(LocalTransactionHandler.java:108)
        at oracle.adf.model.dcframe.DataControlFrameImpl.restoreSavepoint(DataControlFrameImpl.java:545)
        at oracle.adfinternal.controller.util.model.DCFrameImpl.restoreSavepoint(DCFrameImpl.java:40)        at oracle.adfinternal.controller.activity.TaskFlowReturnActivityLogic.resolveTransaction(TaskFlowReturnActivityLogic.java:559)
        at oracle.adfinternal.controller.activity.TaskFlowReturnActivityLogic.execute(TaskFlowReturnActivityLogic.java:114)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.executeActivity(ControlFlowEngine.java:989)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.doRouting(ControlFlowEngine.java:878)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.doRouting(ControlFlowEngine.java:777)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.routeFromActivity(ControlFlowEngine.java:551)
        at oracle.adfinternal.controller.engine.ControlFlowEngine.performControlFlow(ControlFlowEngine.java:147)
        at oracle.adfinternal.controller.application.NavigationHandlerImpl.handleAdfcNavigation(NavigationHandlerImpl.java:109)
        at oracle.adfinternal.controller.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:78)
        at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:130)
 . . .
        at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2202)
        at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2108)
        at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1432)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

After checking the thread dump, I looked at the heap dump, and in the dominator tree, a lot of XML related objects were visible. This confirmed that because of inappropriate use of save point activity, a lot of activation/passivation was happening and because of which server was going OOM. After discussing this with Development team, came to know that they do have a save point call in their code but they missed setting the Restore Save Point property of task flow return activity to true.

The following images show how to look for XML objects in case of passivation issues. Before any run, this is how the XML Objects were in the heap, as shown in the following dominator tree:

We had 2 suspected flows, so we ran 5 iterations of the first suspected flow and checked the XML Objects growth again, as shown below:

And then we ran the second suspected flow for 5 iteration, and check the XML Objects growth, as shown below:

These images are for only single user scenario so imagine what can happen in case of multi user scenario with a lot of data is involved. In multi user scenario, the container went OOM and crashed multiple times before we deployed the application with correct value of the Restore Save Point property of task flow return activity.