Case Study - Slow Performance in P4116

Case study for performance issue from Inventory Transaction. This document may cover multiple products and components in EnterpriseOne.

Questions to address when encountering slow performance with inventory transactions in JD Edwards EnterpriseOne.

Is the database optimized?

The causes of slow performance can vary. This document presumes that your DBA (Database Administrator) optimizes the database on a regular basis. This document does not cover how to optimize the database.

What is the business requirement?

In this example, we will review a manufacturing company manufacturing consumer goods which have to be controlled by Lot Number.
1. Manufacturing B/P produces and assigns a single lot.
2. The sales department dispatchs a single lot into multiple lots (for this example, 400 Lots) through P4116 (Item Reclassification)

>How do you determine if you have slow performance? How slow is slow?

In multiplying a single lot to many lots, users face 'Web Client Exception', 'Asynchronous Business Function Error' or 'Transaction Failure' when enterpriseServerTimeout = 90000 (milisecond) and JDENETTimeout = 60 second.

In reviewing data from F4111, it took a second in writing each row
Excel output example:
sql> select ILUKID,ILDCT,ILDOC, TO_CHAR(TO_DATE(SUBSTR(ILCRDJ,2,5),'YYDDD'),'YYYY/MM/DD') as "date",
ILTDAY as "time",ILFRTO,ILLITM,ILTRQT/100 as "quantity",ILTRUM,ILLOCN,ILLOTN
from proddta.f4111
where ILITM=187 AND ILLOTN like 'A%'
ORDER BY 2,1

ILUKID	ILDCT	ILDOC	date	time	ILFRTO	ILLITM	quantity	ILTRUM	ILLOCN	ILLOTN
357265	IB	61831	2013/01/16	171804		TESTITEM	0		FG20	30116-88
357266	IC	61831	2013/01/16	171804		TESTITEM	88	BC	FG20	30116-88
357267	IR	13000003	2013/01/16	173938	F	TESTITEM	-22620	KG	FG20	30116-88
357268	IB	13000003	2013/01/16	173940	T	TESTITEM	0		FG20	30116-01
357269	IR	13000003	2013/01/16	173940	T	TESTITEM	260	KG	FG20	30116-01
357270	IB	13000003	2013/01/16	173941	T	TESTITEM	0		FG20	30116-02
357271	IR	13000003	2013/01/16	173942	T	TESTITEM	260	KG	FG20	30116-02
				...
357440	IB	13000003	2013/01/16	174153	T	TESTITEM	0		FG20	30116-87
357441	IR	13000003	2013/01/16	174153	T	TESTITEM	260	KG	FG20	30116-87

When is audit information determined?

What sub-transactions are performed during F4111EndDoc?

How can performance issue be analyzed?

Example of log:
P4116 - Item Reclassifications
|--- (EVENT: Row Exit & Changed - Asynch) XT4116Z1 - F4116FSEditLine (F4116 FS Edit Line) which validates detail data and create cache for inventory and general ledger
: This functions gets called 400 times and more however this routine does not impact COMMIT FAILE
|--- (EVENT: Button Clicked (OK Button)) XT4116Z1 - F4116FSEndDoc (F4116 FS End Doc)
|--- XT4111Z1 - F4111EndDocument
: This function reads row by row based on inventory cache created through Edit Line routine. So below routines calls 400 times for this example.
|--- GetAuditInfo: So each rows from F4111 can have different time flag
|--- Other routine as question 5 reads
|--- X4181 - AverageCostUpdate (F4105UpdateAverageCost
|--- XF4105 - GetItemCost (F4105 Get Item Cost Row) to read before cost is computed.
|--- XF4105 - UpdateItemCost (F4105 UPdte Item Cost): main business function to edit F4105.
|--- XF4105 - EditF4105 (Edit F4105): validation before update
|--- JDB_UpdateTable (F4105)

11:06:09.230119 Calling Business function AverageCostUpdate from F4111EndDocument for USERID. Application Name [P4116], Version [ZJDE0001] (BSFNLevel = 3)
11:06:09.230123 IN->[ 1] mnShortItemNumber [9999]
11:06:09.230124 IN->[ 2] szSecondItemNumber [2NDITEM ]
11:06:09.230125 IN->[ 3] szThirdItemNumber [3RDITEM ]
11:06:09.230126 IN->[ 4] szBranchPlant [ M30]
11:06:09.230127 IN->[ 5] szLocation [LOCN ]
11:06:09.230128 IN->[ 6] szLotNumber [30124-50]
11:06:09.230129 IN->[ 7] mnTransactionQuantity [260]
11:06:09.230130 IN->[ 8] mnExtendedCost [7705]
11:06:09.230131 IN->[ 9] cCostingLevel [2] *** Since costing level is 2 it has to read all data from F41021 which meets MCU and ITM ***
11:06:09.230132 IN->[ 10] cUpdateAverageCost [Y] *** UpdateAverageCost is Y so it has to update Average Cost ***
11:06:09.230133 IN->[ 11] mnMarginMaintenance [.000]
11:06:09.230134 IN->[ 12] cMarginMaintenanceFlag [N]
11:06:09.230135 IN->[ 13] cSalesBasePriceLevel [3]
11:06:09.230136 IN->[ 14] szPrimaryUOM [KG]
11:06:09.230137 IN->[ 15] szProgramID [EP4116]
11:06:09.230138 IN->[ 16] szCurrencyCode []
11:06:09.230139 IN->[ 17] mnUnitCostInPrimary [29.6329]
11:06:09.230140 IN->[ 18] cUseUnitCost [1]
11:06:09.230148 Entering JDB_OpenTable(Table = F41021)
11:06:09.230153 Entering JDB_FetchKeyed (hRequest 06D96B58) *** This returns all the row which meets below WHERE condition ***
11:06:09.230155 SELECT LIITM, LIMCU, LILOCN, LILOTN, LIPQOH FROM CRPDTA.F41021 WHERE ( LIITM = 9999.000000 AND LIMCU = ' M30' ) *** No Order By statement because JDB_FetchKeyed() ***
11:06:09.230156 ORACLE DBFetch conn=09F9AA08 requ=09E4BAB8 maxrows=100 *** every 100 records to have better performance from DB. For this example, the record count 40,000 rows ***
11:06:09.230157 Fetched the record *** Indicate the 1st row was returned based on above SELECT statement ***
11:06:09.230158 Entering JDB_FetchMatchingKey (hRequest 06D96B58)
11:06:09.230159 Fetched the record
...
11:06:09.246210 Entering JDB_FetchMatchingKey (hRequest 06D96B58)
11:06:09.246211 ORACLE DBFetch conn=09F9AA08 requ=09E4BAB8 maxrows=100
11:06:09.246212 Fetched the record
11:06:09.246213 Entering JDB_FetchMatchingKey (hRequest 06D96B58)
11:06:09.246214 Fetched the record
...
11:06:10.575264 Entering JDB_FetchMatchingKey (hRequest 06D96B58)
11:06:10.575265 Fetched the record
11:06:10.575266 Entering JDB_FetchMatchingKey (hRequest 06D96B58)
11:06:10.575267 No More Data found *** Indicate that the last row was read from F4105 ***
11:06:10.575269 Entering JDB_CloseTable(Table = F41021)
11:06:10.590353 OUT->[ 1] mnShortItemNumber [9999]
11:06:10.590354 OUT->[ 2] szSecondItemNumber [2NDITEM ]
11:06:10.590355 OUT->[ 3] szThirdItemNumber [3RDITEM ]
11:06:10.590356 OUT->[ 4] szBranchPlant [ M30]
11:06:10.590357 OUT->[ 5] szLocation [LOCN ]
11:06:10.590358 OUT->[ 6] szLotNumber [30124-50]
11:06:10.590359 OUT->[ 7] mnTransactionQuantity [260]
11:06:10.590360 OUT->[ 8] mnExtendedCost [7705]
11:06:10.590361 OUT->[ 9] cCostingLevel [2]
11:06:10.590362 OUT->[ 10] cUpdateAverageCost [Y]
11:06:10.590363 OUT->[ 11] mnMarginMaintenance [.000]
11:06:10.590364 OUT->[ 12] cMarginMaintenanceFlag [N]
11:06:10.590365 OUT->[ 13] cSalesBasePriceLevel [3]
11:06:10.590366 OUT->[ 14] szPrimaryUOM [KG]
11:06:10.590367 OUT->[ 15] szProgramID [EP4116]
11:06:10.590368 OUT->[ 16] szCurrencyCode []
11:06:10.590369 OUT->[ 17] mnUnitCostInPrimary [29.6329]
11:06:10.590370 OUT->[ 18] cUseUnitCost [1]
11:06:10.590376 Return value is 0 for AverageCostUpdate. (BSFNLevel = 3)

JDEDBReturn = JDB_FetchKeyed( hRequest, IndexID, (void *)(&dsF41021Key1),
(short)(uNumOfKeys), (void *)(&dsF41021),
(int) FALSE ) ;
while ( JDEDBReturn == JDEDB_PASSED ) /* If costing level is 2 it will look for all location and lot which meets ITM and MCU */
{
MathAdd ( lpmnPQOH, lpmnPQOH, &dsF41021.lipqoh ) ; /* lpmnPQOH = lpmnPQOH + &dsF41021.lipqoh which sum up pqoh */
JDEDBReturn = JDB_FetchMatchingKey( hRequest, (void *)(&dsF41021Key1),
(short)(uNumOfKeys),
(void *)(&dsF41021), (int) FALSE ) ;
}
*** Break In Code ***

Possible workarounds

Maintaining otimal performance as data tables increase in size

Most of the performance is related with data and/or database (RDBMS) so it is important to have compact data set by purging it regularly.

Other considerations

Performance is very subjective. It is important to indicate expectations or objectives for the issue. The cause of slow performance is variable. Try to narrow down the issue from top to bottom. The information written here is most bottom level debugging.

Case study - Slow Performance in P4116 (Inventory Reclassification)

Purpose of Document

Table of Contents