My Oracle Support Banner

Publication Jobs Running Indefinitely Until Exceeding Thread Pool Duration (Doc ID 2983678.1)

Last updated on NOVEMBER 02, 2023

Applies to:

Primavera P6 Enterprise Project Portfolio Management - Version 21.12.13.0 to 21.12.15.0 [Release 21.12]
Primavera P6 Enterprise Project Portfolio Management - Version 22.12 to 22.12.8.0 [Release 22.12]
Primavera P6 Enterprise Project Portfolio Management Cloud Service - Version 21.12.13.0 to 23.9 [Release 21.12 to 23.9]
Information in this document applies to any platform.

Symptoms

1.  Project Publication service is failing after exceeding thread pool parameters.

2.  Step 23 is taking an extended time to run (and is the step that is actually failing).

Note the items in bold below.  For example, 2023-10-24 06:51:06:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 113; Load time: 00:23:46.889.  This shows that it took 23 mins 46 secs to process 113 rows.

SEVERE: 2023-10-24 08:03:28:[SERVICE]:[PxService]: null
java.lang.InterruptedException
    at java.base/java.lang.Object.wait(Native Method)
    at java.base/java.lang.Object.wait(Object.java:328)
    at com.primavera.infr.threadpool.Future.get(Future.java:27)
    at com.primavera.px.common.PxService.a(PxService.java:484)
    at com.primavera.px.common.PxService.runJob(PxService.java:273)
    at com.primavera.jobsvc.common.JobServiceExecutable.c(JobServiceExecutable.java:460)
    at com.primavera.jobsvc.common.JobServiceExecutable.a(JobServiceExecutable.java:266)
    at com.primavera.jobsvc.common.JobServiceExecutable.execute(JobServiceExecutable.java:197)
    at com.primavera.infr.threadpool.ThreadPoolImpl.run(ThreadPoolImpl.java:343)
    at java.base/java.lang.Thread.run(Thread.java:834)
2023-10-24 08:03:28:[SERVICE]:[PxService]: Job End Time: 2023-10-24 08:03:28
2023-10-24 08:03:28:[SERVICE]:[PxService]: Job Elapsed Time: 02:20:40.626
SEVERE: 2023-10-24 08:03:28:[SERVICE]:[PxService]: Job Status: Failed
2023-10-24 08:03:28:[SERVICE]:[PxService]: END: Px Service Job


DEBUG LOG

2023-10-24 06:27:11:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 113; Load time: 00:24:06.912
2023-10-24 06:27:11:[TASK]:[Activity]: [23] CORE(BRE): Writer is processing 113 Activity(s)...
2023-10-24 06:27:11:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Update
2023-10-24 06:27:13:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 06:27:19:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 06:27:19:[TASK]:[Activity]: [23] CORE(BRE): Writer processes 113 Activity(s) completed
2023-10-24 06:27:19:[TASK]:[PxServiceActivityReader]: [23] CORE(BRE): (Class: Activity) (Filter: ((ProjectId = 419)) AND (ActivityId >= 39750) and (ActivityId <= 39862)  ORDER BY ActivityId) (Fields: Var1NonLaborUnits,UnitsPercentComplete,AtCompletionExpenseCost,PlannedValueLaborUnits,PrimaryResourceName,Var1ExpenseCost,PlannedValueCost,Var1MaterialCost,DurationPercentOfPlanned,BL1LateStart,ActualExpenseCost,NonLaborUnitsCompletePercent,PlannedMaterialCost,VarCost,BL1LateFinish,BLPlannedNonLaborUnits,ScheduleVarianceLaborUnits,RemainingMaterialCost,BLPlannedMaterialCost,NonLaborCostPercentComplete,VarianceAtCompletionLaborUnits,RemainingUnits,ActualNonLaborCost,BLStartDate,ActivityId,VarLaborCost,ActualLaborCost,VarExpenseCost,VarNonLaborUnits,ScheduleVarIndexLaborUnits,OwnerId,EstimateToComplete,VarStartDate,RemainingLaborCost,WbsName,WbsShortName,EstimateAtCompletionLaborUnits,DurationPercentComplete,AtCompletionDuration,FinishDate,ActualCost,EarnedValueLaborUnits,PercentComplete,ActualMaterialCost,CostVariance,BLLateFinish,PlannedUnits,ScheduleVariance,VarianceAtCompletion,ActualThisPeriodNonLaborCost,ActualThisPeriodMaterialCost,ExpenseCostPercentComplete,BLPlannedLaborCost,LastUpdateDate,BLPlannedDuration,RemainingFloat,BLPlannedCost,AtCompletionLaborCost,Critical,PlannedLaborCost,EarnedValueCost,CreateDate,StartDate,Var1NonLaborCost,AtCompletionNonLaborUnits,ActualThisPeriodLaborCost,CostVarianceIndexLaborUnits,RemainingExpenseCost,PlannedCost,AccountingVarianceLaborUnits,PerformancePercentComplete,BLDuration,SchedulePercentComplete,ToCompletePerformanceIndex,CostPercentOfPlanned,PhysicalPercentComplete,ActualUnits,PlannedNonLaborCost,CostVarianceIndex,PrimaryResourceShortName,AtCompletionMaterialCost,AtCompletionUnits,AtCompletionLaborUnits,ActualDuration,RemainingNonLaborCost,EstimateToCompletionLaborUnits,SchedulePerfIndexLaborUnits,CostPercentComplete,ActualProgressDate,BLPlannedNonLaborCost,CostVarianceLaborUnits,OwnerName,RemainingCost,CostPerformanceIndex,CalendarName,Var1Cost,AtCompletionNonLaborCost,VarFinishDate,VarLaborUnits,BLFinishDate,SchedulePerformanceIndex,BudgetAtCompletion,Var1LaborCost,PlannedExpenseCost,MaterialCostPercentComplete,BLLateStart,BLPlannedLaborUnits,CostPerformanceIndexLaborUnits,DataDate,EstimateAtCompletionCost,VarNonLaborCost,AtCompletionCost,ScheduleVarianceIndex,AccountingVariance,VarMaterialCost,BLPlannedExpenseCost,VarDuration,Var1LaborUnits,Var1StartDate,Var1FinishDate,LaborUnitsCompletePercent,LaborCostPercentComplete,Var1Duration)
2023-10-24 06:51:06:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 113; Load time: 00:23:46.889
2023-10-24 06:51:06:[TASK]:[Activity]: [23] CORE(BRE): Writer is processing 113 Activity(s)...
2023-10-24 06:51:06:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Update
2023-10-24 06:51:07:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 06:51:09:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 06:51:09:[TASK]:[Activity]: [23] CORE(BRE): Writer processes 113 Activity(s) completed
Var1NonLaborUnits,UnitsPercentComplete,AtCompletionExpenseCost,PlannedValueLaborUnits,PrimaryResourceName,Var1ExpenseCost,PlannedValueCost,Var1MaterialCost,DurationPercentOfPlanned,BL1LateStart,ActualExpenseCost,NonLaborUnitsCompletePercent,PlannedMaterialCost,VarCost,BL1LateFinish,BLPlannedNonLaborUnits,ScheduleVarianceLaborUnits,RemainingMaterialCost,BLPlannedMaterialCost,NonLaborCostPercentComplete,VarianceAtCompletionLaborUnits,RemainingUnits,ActualNonLaborCost,BLStartDate,ActivityId,VarLaborCost,ActualLaborCost,VarExpenseCost,VarNonLaborUnits,ScheduleVarIndexLaborUnits,OwnerId,EstimateToComplete,VarStartDate,RemainingLaborCost,WbsName,WbsShortName,EstimateAtCompletionLaborUnits,DurationPercentComplete,AtCompletionDuration,FinishDate,ActualCost,EarnedValueLaborUnits,PercentComplete,ActualMaterialCost,CostVariance,BLLateFinish,PlannedUnits,ScheduleVariance,VarianceAtCompletion,ActualThisPeriodNonLaborCost,ActualThisPeriodMaterialCost,ExpenseCostPercentComplete,BLPlannedLaborCost,LastUpdateDate,BLPlannedDuration,RemainingFloat,BLPlannedCost,AtCompletionLaborCost,Critical,PlannedLaborCost,EarnedValueCost,CreateDate,StartDate,Var1NonLaborCost,AtCompletionNonLaborUnits,ActualThisPeriodLaborCost,CostVarianceIndexLaborUnits,RemainingExpenseCost,PlannedCost,AccountingVarianceLaborUnits,PerformancePercentComplete,BLDuration,SchedulePercentComplete,ToCompletePerformanceIndex,CostPercentOfPlanned,PhysicalPercentComplete,ActualUnits,PlannedNonLaborCost,CostVarianceIndex,PrimaryResourceShortName,AtCompletionMaterialCost,AtCompletionUnits,AtCompletionLaborUnits,ActualDuration,RemainingNonLaborCost,EstimateToCompletionLaborUnits,SchedulePerfIndexLaborUnits,CostPercentComplete,ActualProgressDate,BLPlannedNonLaborCost,CostVarianceLaborUnits,OwnerName,RemainingCost,CostPerformanceIndex,CalendarName,Var1Cost,AtCompletionNonLaborCost,VarFinishDate,VarLaborUnits,BLFinishDate,SchedulePerformanceIndex,BudgetAtCompletion,Var1LaborCost,PlannedExpenseCost,MaterialCostPercentComplete,BLLateStart,BLPlannedLaborUnits,CostPerformanceIndexLaborUnits,DataDate,EstimateAtCompletionCost,VarNonLaborCost,AtCompletionCost,ScheduleVarianceIndex,AccountingVariance,VarMaterialCost,BLPlannedExpenseCost,VarDuration,Var1LaborUnits,Var1StartDate,Var1FinishDate,LaborUnitsCompletePercent,LaborCostPercentComplete,Var1Duration)
2023-10-24 07:14:50:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 113; Load time: 00:23:40.728
2023-10-24 07:14:50:[TASK]:[Activity]: [23] CORE(BRE): Writer is processing 113 Activity(s)...
2023-10-24 07:14:50:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Update
2023-10-24 07:14:51:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 07:14:52:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 07:14:52:[TASK]:[Activity]: [23] CORE(BRE): Writer processes 113 Activity(s) completed
Var1NonLaborUnits,UnitsPercentComplete,AtCompletionExpenseCost,PlannedValueLaborUnits,PrimaryResourceName,Var1ExpenseCost,PlannedValueCost,Var1MaterialCost,DurationPercentOfPlanned,BL1LateStart,ActualExpenseCost,NonLaborUnitsCompletePercent,PlannedMaterialCost,VarCost,BL1LateFinish,BLPlannedNonLaborUnits,ScheduleVarianceLaborUnits,RemainingMaterialCost,BLPlannedMaterialCost,NonLaborCostPercentComplete,VarianceAtCompletionLaborUnits,RemainingUnits,ActualNonLaborCost,BLStartDate,ActivityId,VarLaborCost,ActualLaborCost,VarExpenseCost,VarNonLaborUnits,ScheduleVarIndexLaborUnits,OwnerId,EstimateToComplete,VarStartDate,RemainingLaborCost,WbsName,WbsShortName,EstimateAtCompletionLaborUnits,DurationPercentComplete,AtCompletionDuration,FinishDate,ActualCost,EarnedValueLaborUnits,PercentComplete,ActualMaterialCost,CostVariance,BLLateFinish,PlannedUnits,ScheduleVariance,VarianceAtCompletion,ActualThisPeriodNonLaborCost,ActualThisPeriodMaterialCost,ExpenseCostPercentComplete,BLPlannedLaborCost,LastUpdateDate,BLPlannedDuration,RemainingFloat,BLPlannedCost,AtCompletionLaborCost,Critical,PlannedLaborCost,EarnedValueCost,CreateDate,StartDate,Var1NonLaborCost,AtCompletionNonLaborUnits,ActualThisPeriodLaborCost,CostVarianceIndexLaborUnits,RemainingExpenseCost,PlannedCost,AccountingVarianceLaborUnits,PerformancePercentComplete,BLDuration,SchedulePercentComplete,ToCompletePerformanceIndex,CostPercentOfPlanned,PhysicalPercentComplete,ActualUnits,PlannedNonLaborCost,CostVarianceIndex,PrimaryResourceShortName,AtCompletionMaterialCost,AtCompletionUnits,AtCompletionLaborUnits,ActualDuration,RemainingNonLaborCost,EstimateToCompletionLaborUnits,SchedulePerfIndexLaborUnits,CostPercentComplete,ActualProgressDate,BLPlannedNonLaborCost,CostVarianceLaborUnits,OwnerName,RemainingCost,CostPerformanceIndex,CalendarName,Var1Cost,AtCompletionNonLaborCost,VarFinishDate,VarLaborUnits,BLFinishDate,SchedulePerformanceIndex,BudgetAtCompletion,Var1LaborCost,PlannedExpenseCost,MaterialCostPercentComplete,BLLateStart,BLPlannedLaborUnits,CostPerformanceIndexLaborUnits,DataDate,EstimateAtCompletionCost,VarNonLaborCost,AtCompletionCost,ScheduleVarianceIndex,AccountingVariance,VarMaterialCost,BLPlannedExpenseCost,VarDuration,Var1LaborUnits,Var1StartDate,Var1FinishDate,LaborUnitsCompletePercent,LaborCostPercentComplete,Var1Duration)
2023-10-24 07:38:42:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 115; Load time: 00:23:49.811
2023-10-24 07:38:42:[TASK]:[Activity]: [23] CORE(BRE): Writer is processing 115 Activity(s)...
2023-10-24 07:38:42:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Update
2023-10-24 07:38:43:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 07:38:45:[TASK]:[PxBusinessObjectSqlWriter]: [23] CORE(BRE): Commit succeeded for: Create
2023-10-24 07:38:45:[TASK]:[Activity]: [23] CORE(BRE): Writer processes 115 Activity(s) completed
Var1NonLaborUnits,UnitsPercentComplete,AtCompletionExpenseCost,PlannedValueLaborUnits,PrimaryResourceName,Var1ExpenseCost,PlannedValueCost,Var1MaterialCost,DurationPercentOfPlanned,BL1LateStart,ActualExpenseCost,NonLaborUnitsCompletePercent,PlannedMaterialCost,VarCost,BL1LateFinish,BLPlannedNonLaborUnits,ScheduleVarianceLaborUnits,RemainingMaterialCost,BLPlannedMaterialCost,NonLaborCostPercentComplete,VarianceAtCompletionLaborUnits,RemainingUnits,ActualNonLaborCost,BLStartDate,ActivityId,VarLaborCost,ActualLaborCost,VarExpenseCost,VarNonLaborUnits,ScheduleVarIndexLaborUnits,OwnerId,EstimateToComplete,VarStartDate,RemainingLaborCost,WbsName,WbsShortName,EstimateAtCompletionLaborUnits,DurationPercentComplete,AtCompletionDuration,FinishDate,ActualCost,EarnedValueLaborUnits,PercentComplete,ActualMaterialCost,CostVariance,BLLateFinish,PlannedUnits,ScheduleVariance,VarianceAtCompletion,ActualThisPeriodNonLaborCost,ActualThisPeriodMaterialCost,ExpenseCostPercentComplete,BLPlannedLaborCost,LastUpdateDate,BLPlannedDuration,RemainingFloat,BLPlannedCost,AtCompletionLaborCost,Critical,PlannedLaborCost,EarnedValueCost,CreateDate,StartDate,Var1NonLaborCost,AtCompletionNonLaborUnits,ActualThisPeriodLaborCost,CostVarianceIndexLaborUnits,RemainingExpenseCost,PlannedCost,AccountingVarianceLaborUnits,PerformancePercentComplete,BLDuration,SchedulePercentComplete,ToCompletePerformanceIndex,CostPercentOfPlanned,PhysicalPercentComplete,ActualUnits,PlannedNonLaborCost,CostVarianceIndex,PrimaryResourceShortName,AtCompletionMaterialCost,AtCompletionUnits,AtCompletionLaborUnits,ActualDuration,RemainingNonLaborCost,EstimateToCompletionLaborUnits,SchedulePerfIndexLaborUnits,CostPercentComplete,ActualProgressDate,BLPlannedNonLaborCost,CostVarianceLaborUnits,OwnerName,RemainingCost,CostPerformanceIndex,CalendarName,Var1Cost,AtCompletionNonLaborCost,VarFinishDate,VarLaborUnits,BLFinishDate,SchedulePerformanceIndex,BudgetAtCompletion,Var1LaborCost,PlannedExpenseCost,MaterialCostPercentComplete,BLLateStart,BLPlannedLaborUnits,CostPerformanceIndexLaborUnits,DataDate,EstimateAtCompletionCost,VarNonLaborCost,AtCompletionCost,ScheduleVarianceIndex,AccountingVariance,VarMaterialCost,BLPlannedExpenseCost,VarDuration,Var1LaborUnits,Var1StartDate,Var1FinishDate,LaborUnitsCompletePercent,LaborCostPercentComplete,Var1Duration)
2023-10-24 08:02:44:[TASK]:[Activity]: [23] CORE(BRE): Object(s) loaded: 116; Load time: 00:23:59.405
2023-10-24 08:02:44:[TASK]:[Activity]: [23] CORE(BRE): Writer is processing 116 Activity(s)...

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.