My Oracle Support Banner

Rapid Plan Is Hanging/Performance is Pood - Engine Logs Provide Minimal Information (Doc ID 1916533.1)

Last updated on JULY 05, 2021

Applies to:

Oracle Rapid Planning - Version 12.1.3.9 and later
Information in this document applies to any platform.

Symptoms

On : 12.1.3.9 version, Planning Engine in SIT

Users are on VCP 12.1.3.9.1 Patch 17350769 - key RP files

engine.zip 120.46.12010000.248
RPAdmin.zip 120.0.12010000.6
ui.zip 120.65.12010000.325

They state they used to run RP plans in 15 minutes or less. Now they state they cannot get an RP plan to complete. All the concurrent requests in View/Requests form are complete relatively quickly (ie 10 - 15 minutes). Seems to be a problem in loading the plan into memory. From the logs for the managed servers (they have 8 managed servers total)

A. Don't see any issue in the AdminServer.log

B. Don't see any issue in the AdminServer Diag.log

C. In the EngineDomain.log I do see a lot of warnings like

####<Jun 18, 2014 3:51:39 PM EDT> <Warning> <WorkManager>
<EPS-Weblogic01.tervis.prv> <RP_Mserver1> <[ACTIVE] ExecuteThread: '1' for
queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <>
<1403121099606> <BEA-002919> <Unable to find a WorkManager with name
weblogic.wsee.mdb.DispatchPolicy. Dispatch policy
weblogic.wsee.mdb.DispatchPolicy will map to the default WorkManager for the
@ application rpws>
####<Jun 18, 2014 3:51:39 PM EDT> <Warning> <WorkManager>
<EPS-Weblogic01.tervis.prv> <RP_Mserver1> <[ACTIVE] ExecuteThread: '1' for
queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <>
<1403121099629> <BEA-002919> <Unable to find a WorkManager with name
weblogic.wsee.mdb.DispatchPolicy. Dispatch policy
weblogic.wsee.mdb.DispatchPolicy will map to the default WorkManager for the
@ application rpws>




D. In the Managed server.log see the following a couple of times

#### <> <> <> ", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:
java.util.LinkedList.addAll(LinkedList.java:247)
oracle.apps.msc.orp.engine.solver.Planner.append(Planner.java:2267)
oracle.apps.msc.orp.engine.solver.SimpleOperationPlanner.plan(SimpleOperationPlanner.java:179)
oracle.apps.msc.orp.engine.solver.Planner.planOperationOneChunk(Planner.java:4840)
oracle.apps.msc.orp.engine.solver.Planner.planOperation(Planner.java:968)

This type of problem we typically associate with a plan that got closed after it was loaded into memory. But in this case the plan is still running

E. In the Managed server .out file we can see the plan is running and it just shows

6/20/14 00:00:00 06/23/14 00:00:00 06/24/14 00:00:00 06/25/14 00:00:00 06/26/14 00:00:00 06/27/14 00:00:00 06/30/14 00:00:00 07/01/14 00:00:00 07/02/14 00:00:00 07/03/14 00:00:00 07/04/14 00:00:00 07/07/14 00:00:00 07/08/14 00:00:00 07/09/14 00:00:00 07/10/14 00:00:00 07/11/14 00:00:00 07/14/14 00:00:00 07/15/14 00:00:00 07/16/14 00:00:00 07/17/14 00:00:00 07/18/14 00:00:00 07/21/14 00:00:00 07/22/14 00:00:00 07/23/14 00:00:00 07/24/14 00:00:00 07/25/14 00:00:00 07/28/14 00:00:00 07/29/14 00:00:00 07/30/14 00:00:00 07/31/14 00:00:00 08/01/14 00:00:00 08/04/14 00:00:00 08/05/14 00:00:00 08/06/14 00:00:00 08/07/14 00:00:00 08/08/14 00:00:00 08/11/14 00:00:00 08/12/14 00:00:00 08/13/14 00:00:00 08/14/14 00:00:00 08/15/14 00:00:00 08/18/14 00:00:00 08/19/14 00:00:00 08/20/14 00:00:00 08/21/14 00:00:00 08/22/14 00:00:00 08/25/14 00:00:00 08/26/14 00:00:00 08/27/14 00:00:00 08/28/14 00:00:00 08/29/14 00:00:00 09/01/14 00:00:00 09/02/14 00:00:00 09/03/14 00:00:00 09/04/14 00:00:00 09/05/14 00:00:00 09/08/14 00:00:00 09/09/14 00:00:00 09/10/14 00:00:00 09/11/14 00:00:00 09/12/14 00:00:00 09/15/14 00:00:00 09/16/14 00:00:00 09/17/14 00:00:00 09/18/14 00:00:00 09/19/14 00:00:00 09/22/14 00:00:00 09/23/14 00:00:00 09/24/14 00:00:00 09/25/14 00:00:00 09/26/14 00:00:00 09/29/14 00:00:00 09/30/14 00:00:00 10/01/14 00:00:00 10/02/14 00:00:00 10/03/14 00:00:00 10/06/14 00:00:00 10/07/14 00:00:00 10/08/14 00:00:00 10/09/14 00:00:00 10/10/14 00:00:00 10/13/14 00:00:00 10/14/14 00:00:00 10/15/14 00:00:00 10/16/14 00:00:00 7 For item 31159_84_1 Need to update the FDS Map because demandDate: 1436 is less than first fds date 1440

  7 For item 31159_84_1 Need to update the FDS Map because demandDate: 1436 is less than first fds date 1440

  7
 Old FDSDates : [1440, 5760, 7200, 8640, 10080, 11520, 15840, 17280, 18720, 20160, 21600, 25920, 27360, 28800, 30240, 31680, 36000, 37440, 38880, 40320, 41760, 46080, 47520, 48960, 50400, 51840, 56160, 57600, 59040, 60480, 61920, 66240, 67680, 69120, 70560, 72000, 76320, 77760, 79200, 80640, 82080, 86400, 87840, 89280, 90720, 92160, 96480, 97920, 99360, 100800, 102240, 106560, 108000, 109440, 110880, 112320, 116640, 118080, 119520, 120960, 122400, 126720, 128160, 129600, 131040, 132480, 136800, 138240, 139680, 141120, 142560, 146880, 148320, 149760, 151200, 152640, 156960, 158400, 159840, 161280, 162720, 167040, 168480, 169920, 171360]

  7
 Old FDSDates : [1440, 5760, 7200, 8640, 10080, 11520, 15840, 17280, 18720, 20160, 21600, 25920, 27360, 28800, 30240, 31680, 36000, 37440, 38880, 40320, 41760, 46080, 47520, 48960, 50400, 51840, 56160, 57600, 59040, 60480, 61920, 66240, 67680, 69120, 70560, 72000, 76320, 77760, 79200, 80640, 82080, 86400, 87840, 89280, 90720, 92160, 96480, 97920, 99360, 100800, 102240, 106560, 108000, 109440, 110880, 112320, 116640, 118080, 119520, 120960, 122400, 126720, 128160, 129600, 131040, 132480, 136800, 138240, 139680, 141120, 142560, 146880, 148320, 149760, 151200, 152640, 156960, 158400, 159840, 161280, 162720, 167040, 168480, 169920, 171360]

  7 New FDSDates : [1440, 5760, 7200, 8640, 10080, 11520, 15840, 17280, 18720, 20160, 21600, 25920, 27360, 28800, 30240, 31680, 36000, 37440, 38880, 40320, 41760, 46080, 47520, 48960, 50400, 51840, 56160, 57600, 59040, 60480, 61920, 66240, 67680, 69120, 70560, 72000, 76320, 77760, 79200, 80640, 82080, 86400, 87840, 89280, 90720, 92160, 96480, 97920, 99360, 100800, 102240, 106560, 108000, 109440, 110880, 112320, 116640, 118080, 119520, 120960, 122400, 126720, 128160, 129600, 131040, 132480, 136800, 138240, 139680, 141120, 142560, 146880, 148320, 149760, 151200, 152640, 156960, 158400, 159840, 161280, 162720, 167040, 168480, 169920, 171360]

  7 New FDSDates : [1440, 5760, 7200, 8640, 10080, 11520, 15840, 17280, 18720, 20160, 21600, 25920, 27360, 28800, 30240, 31680, 36000, 37440, 38880, 40320, 41760, 46080, 47520, 48960, 50400, 51840, 56160, 57600, 59040, 60480, 61920, 66240, 67680, 69120, 70560, 72000, 76320, 77760, 79200, 80640, 82080, 86400, 87840, 89280, 90720, 92160, 96480, 97920, 99360, 100800, 102240, 106560, 108000, 109440, 110880, 112320, 116640, 118080, 119520, 120960, 122400, 126720, 128160, 129600, 131040, 132480, 136800, 138240, 139680, 141120, 142560, 146880, 148320, 149760, 151200, 152640, 156960, 158400, 159840, 161280, 162720, 167040, 168480, 169920, 171360]

06/20/14 00:00:00 06/23/14 00:00:00 06/24/14 00:00:00 06/25/14 00:00:00 06/26/14 00:00:00 06/27/14 00:00:00 06/30/14 00:00:00 07/01/14 00:00:00 07/02/14 00:00:00 07/03/14 00:00:00 07/04/14 00:00:00 07/07/14 00:00:00 07/08/14 00:00:00 07/09/14 00:00:00 07/10/14 00:00:00 07/11/14 00:00:00 07/14/14 00:00:00 07/15/14 00:00:00 07/16/14 00:00:00 07/17/14 00:00:00 07/18/14 00:00:00 07/21/14 00:00:00 07/22/14 00:00:00 07/23/14 00:00:00 07/24/14 00:00:00 07/25/14 00:00:00 07/28/14 00:00:00 07/29/14 00:00:00 07/30/14 00:00:00 07/31/14 00:00:00 08/01/14 00:00:00 08/04/14 00:00:00 08/05/14 00:00:00 08/06/14 00:00:00 08/07/14 00:00:00 08/08/14 00:00:00 08/11/14 00:00:00 08/12/14 00:00:00 08/13/14 00:00:00 08/14/14 00:00:00 08/15/

and

06/20/14 00:00:00 06/23/14 00:00:00 06/24/14 00:00:00 06/25/14 00:00:00 06/26/14 00:00:00 06/27/14 00:00:00 06/30/14 00:00:00 07/01/14 00:00:00 07/02/14 00:00:00 07/03/14 00:00:00 07/04/14 00:00:00 07/07/14 00:00:00 07/08/14 00:00:00 07/09/14 00:00:00 07/10/14 00:00:00 07/11/14 00:00:00 07/14/14 00:00:00 07/15/14 00:00:00 07/16/14 00:00:00 07/17/14 00:00:00 07/18/14 00:00:00 07/21/14 00:00:00 07/22/14 00:00:00 07/23/14 00:00:00 07/24/14 00:00:00 07/25/14 00:00:00 07/28/14 00:00:00 07/29/14 00:00:00 07/30/14 00:00:00 07/31/14 00:00:00 08/01/14 00:00:00 08/04/14 00:00:00 08/05/14 00:00:00 08/06/14 00:00:00 08/07/14 00:00:00 08/08/14 00:00:00 08/11/14 00:00:00 08/12/14 00:00:00 08/13/14 00:00:00 08/14/14 00:00:00 08/15/14 00:00:00 08/18/14 00:00:00 08/19/14 00:00:00 08/20/14 00:00:00 08/21/14 00:00:00 08/22/14 00:00:00 08/25/14 00:00:00 08/26/14 00:00:00 08/27/14 00:00:00 08/28/14 00:00:00 08/29/14 00:00:00 09/01/14 00:00:00 09/02/14 00:00:00 09/03/14 00:00:00 09/04/14 00:00:00 09/05/14 00:00:00 09/08/14 00:00:00 09/09/14 00:00:00 09/10/14 00:00:00 09/11/14 00:00:00 09/12/14 00:00:00 09/15/14 00:00:00 09/16/14 00:00:00 09/17/14 00:00:00 09/18/14 00:00:00 09/19/14 00:00:00 09/22/14 00:00:00 09/23/14 00:00:00 09/24/14 00:00:00 09/25/14 00:00:00 09/26/14 00:00:00 09/29/14 00:00:00 09/30/14 00:00:00 10/01/14 00:00:00 10/02/14 00:00:00 10/03/14 00:00:00 10/06/14 00:00:00 10/07/14 00:00:00 10/08/14 00:00:00 10/09/14 00:00:00 10/10/14 00:00:00 10/13/14 00:00:00 10/14/14 00:00:00 10/15/14 00:00:00 10/16/14 00:00:00 ", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:
java.util.LinkedList.addAll(LinkedList.java:247)
oracle.apps.msc.orp.engine.solver.Planner.append(Planner.java:2267)
oracle.apps.msc.orp.engine.solver.SimpleOperationPlanner.plan(SimpleOperationPlanner.java:179)
oracle.apps.msc.orp.engine.solver.Planner.planOperationOneChunk(Planner.java:4840)

G. top command shows the following while 4 plans running
61 gig physical used 48 gig free 13 gig

In Engine WLS Console
-RP_Mserver1
Heap size current = 6174015488
Heap free current - 2279106368
Heap free percent = 36
Heap size max = 6174015488

-RP_Mserver2
Heap size current = 6174015488
Heap free current - 2062155944
Heap free percent = 33
Heap size max = 6174015488

-RP_Mserver3
Heap size current = 6174015488
Heap free current - 4621232216
Heap free percent = 74
Heap size max = 6174015488

-RP_Mserver4
Heap size current = 6174015488
Heap free current - 4653503920
Heap free percent = 75
Heap size max = 6174015488

So looks like plenty of available free memory

F. Bouncing everything does not help even if only running 1 plan. They can load the plan first which has the previous data so there appears to be something making these plans hang in the more newly collected data


EXPECTED BEHAVIOR
-----------------------
Expect RP plan to run and complete successfully in 15 minutes

STEPS
-----------------------
The issue can be reproduced at will with the following steps:
1. Run RP plan
2. Plan hangs and will not complete

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


In this Document
Symptoms
Cause
Solution
References


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.