Gary P
Active Member
Hello,
I've built a program that simplifies the supply and demand rules to summarize quantity available buckets for a given date range--each one calendar month but the first bucket going back a few years to gather anything past-due. To do this, I perform a series of select/fetch commands on business views that consist of order tables joined to a custom table that only consists of an order type column (for desired order types).
When we run this to get a forecast of parts, it will sometimes run very slowly, with a 5-15 second pause. Other times it will be almost instant. The main slowdown is almost always on the first bucket (a few years back through the end of this calendar month) selecting from the above-mentioned table joined to the F4211, though other slowdowns rarely come from a F4311 fetch. The rest of the buckets (subsequent calendar months) run very quickly. Running the same query directly through our database software does not produce this slowdown. The delay only appears to happen when running from JDE.
Below is a snippet of a log we captured, with broken lines to prevent epic scrolling:
<font class="small">Code:</font><hr /><pre>
Oct 20 15:23:55.889536 jdb_rqst.c678 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SetSelection With Success
Oct 20 15:23:55.889560 jdb_rqst.c957 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering JDB_SetSequencing
Oct 20 15:23:55.889584 jdb_rqst.c1076 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SetSequencing with Success
Oct 20 15:23:55.889600 jdb_exef.c2506 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering JDB_SelectKeyed
Oct 20 15:23:55.889768 dbdrv.c569 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DBInitRequest
Oct 20 15:23:55.889984 dbdrv.c2045 - 1512/6 WRK:GREGD_80000000_P5688SAD DB2/400 DBInitReq Connhdl = 'SPP:0000 :0000 :0:3:13'
A DBReqHand = 'SPP:0000 :0000 :0:13:13' REUSE C3PO(Business Data - CRP)
Oct 20 15:23:55.890064 dbsql_s.c1821 - 1512/6 WRK:GREGD_80000000_P5688SAD
SELECT T0.SDKCOO, T0.SDDOCO, T0.SDDCTO, T0.SDLNID, T0.SDMCU, T0.SDCO,
T0.SDPPDJ, T0.SDITM, T0.SDLNTY, T0.SDNXTR, T0.SDLTTR, T0.SDEMCU, T0.SDUOM, T0.SDUORG, T0.SDCRCD, T0.SDBCRC, T1.SSDCTO
FROM CRPDTA/F4211 T0,CRPDTA/F5688SDD T1
WHERE ( T0.SDITM = 86754.000000 AND T0.SDMCU = ' 3010' AND T0.SDNXTR < '620' AND T0.SDPPDJ >= 105001 AND T0.SDPPDJ <= 110304 )
AND ( T0.SDDCTO=T1.SSDCTO )
ORDER BY T0.SDUOM ASC
Oct 20 15:23:55.890120 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.890136 dbdrvsql.c746 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PrepareSQLRequest
Oct 20 15:23:55.890192 dbdrvsql.c1575 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - GetSQLStmtNameFromSQLPkg QxdaProcessExtDynEDRS
Oct 20 15:23:55.890256 dbdrvsql.c1586 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>End - GetSQLStmtNameFromSQLPkg QxdaProcessExtDynEDRS
Oct 20 15:23:55.890280 dbdrvsql.c1024 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, done with first for loop, 17 iters
Oct 20 15:23:55.890304 dbdrvsql.c1028 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, before first jdeAlloc, 1421 len
Oct 20 15:23:55.890328 dbdrvsql.c1030 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, after first jdeAlloc, 1421 len
Oct 20 15:23:55.890352 dbdrvsql.c1045 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, after second jdeAlloc, 340 len
Oct 20 15:23:55.890368 dbdrvsql.c1066 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, done with second for loop, 17 iters
Oct 20 15:23:55.890392 dbdrvsql.c1076 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PrepareSQLRequest, req=80000000000000000000800003102D10
Oct 20 15:23:55.890416 dbdrvag.c1199 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PerformRequest, result=1
Oct 20 15:23:55.890432 dbdrv_dt.c739 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering BuildInputDataMap
Oct 20 15:23:55.890456 dbdrv_dt.c1371 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting BuildInputDataMap, result=1
Oct 20 15:23:55.890480 dbdrv_dt.c307 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering BuildOutputDataMap
Oct 20 15:23:55.890560 dbdrv_dt.c699 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting BuildOutputDataMap, result=1
Oct 20 15:23:55.890584 dbdrv.c847 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting DBInitRequest, result=1
Oct 20 15:23:55.890608 dbdrv.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DBPerformRequest
Oct 20 15:23:55.890624 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.890648 dbdrvag.c823 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DoOpenCursor
Oct 20 15:23:55.890680 dbdrvsql.c1244 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering OpenSQLCursor
Oct 20 15:23:55.890704 dbdrvsql.c1272 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - OpenSQLCursor QxdaProcessExtDynEDRS
Oct 20 15:23:55.890904 dbdrvsql.c1283 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>End - OpenSQLCursor QxdaProcessExtDynEDRS
Oct 20 15:23:55.890928 dbdrv_log.c220 - 1512/6 WRK:GREGD_80000000_P5688SAD OpenSQLCursor:Open SQL cursor: Crsr23.
Oct 20 15:23:55.890952 dbdrvsql.c1304 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting OpenSQLCursor, result=1
Oct 20 15:23:55.890968 dbdrvag.c1199 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PerformRequest, result=1
Oct 20 15:23:55.890992 dbdrv.c1048 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting DBPerformRequest, result=1
Oct 20 15:23:55.891008 jdb_exef.c2514 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SelectKeyed with Success
Oct 20 15:23:55.891032 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.891064 dbdrvsql.c1362 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - FetchSQLRow QxdaProcessExtDynEDRS
Oct 20 15:24:00.738728 jdekdisp.c2537 - 1512/2 SYSispatch ADD TO POOL type: 10, 0.0.0.0_0_m0
Oct 20 15:24:00.739104 jdekdisp.c1594 - 1512/4 WRK:Active Worker START SYSTEM JOB type 10, 0.0.0.0_0_m0
Oct 20 15:24:00.739176 jdekdisp.c1833 - 1512/4 WRK:eNetKernelIdle END SYSTEM JOB type 10, 0.0.0.0_0_m0
Oct 20 15:24:01.007848 jde400u.c2754 - 1512/2 SYSispatch _C_TS_malloc_info returned 97
Oct 20 15:24:01.008056 netflow.c1230 - 1512/2 SYSispatch About to call dispatch function, flags=0x0, Type=916
Oct 20 15:24:01.008096 jdekdisp.c2537 - 1512/2 SYSispatch ADD TO POOL type: 916, 192.168.51.26_1441_m60787
Oct 20 15:24:01.008216 jdekdisp.c1594 - 1512/7 WRK:Active Worker START SYSTEM JOB type 916, 192.168.51.26_1441_m60787
Oct 20 15:24:01.008400 jdekdisp.c1833 - 1512/7 WRK:Get User List END SYSTEM JOB type 916, 192.168.51.26_1441_m60787
</pre><hr />
I've gone through google, talked to a couple of our consultants, and looked through here and Oracle's support site, but I've been unable to find out why the slowdown happens from JDE but not directly on the database. If anyone can offer suggestions on finding the problem or fixing it, I would greatly appreciate it.
We are using EnterpriseOne 9.0 with tools 8.98, with AS400 database server. This code is called from a C business function that runs on the AS400 server. The same delay happens when running the business function on a Windows server. Our direct testing (which did not produce the slowdown) was done with iSeries Navigator.
I've built a program that simplifies the supply and demand rules to summarize quantity available buckets for a given date range--each one calendar month but the first bucket going back a few years to gather anything past-due. To do this, I perform a series of select/fetch commands on business views that consist of order tables joined to a custom table that only consists of an order type column (for desired order types).
When we run this to get a forecast of parts, it will sometimes run very slowly, with a 5-15 second pause. Other times it will be almost instant. The main slowdown is almost always on the first bucket (a few years back through the end of this calendar month) selecting from the above-mentioned table joined to the F4211, though other slowdowns rarely come from a F4311 fetch. The rest of the buckets (subsequent calendar months) run very quickly. Running the same query directly through our database software does not produce this slowdown. The delay only appears to happen when running from JDE.
Below is a snippet of a log we captured, with broken lines to prevent epic scrolling:
<font class="small">Code:</font><hr /><pre>
Oct 20 15:23:55.889536 jdb_rqst.c678 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SetSelection With Success
Oct 20 15:23:55.889560 jdb_rqst.c957 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering JDB_SetSequencing
Oct 20 15:23:55.889584 jdb_rqst.c1076 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SetSequencing with Success
Oct 20 15:23:55.889600 jdb_exef.c2506 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering JDB_SelectKeyed
Oct 20 15:23:55.889768 dbdrv.c569 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DBInitRequest
Oct 20 15:23:55.889984 dbdrv.c2045 - 1512/6 WRK:GREGD_80000000_P5688SAD DB2/400 DBInitReq Connhdl = 'SPP:0000 :0000 :0:3:13'
A DBReqHand = 'SPP:0000 :0000 :0:13:13' REUSE C3PO(Business Data - CRP)
Oct 20 15:23:55.890064 dbsql_s.c1821 - 1512/6 WRK:GREGD_80000000_P5688SAD
SELECT T0.SDKCOO, T0.SDDOCO, T0.SDDCTO, T0.SDLNID, T0.SDMCU, T0.SDCO,
T0.SDPPDJ, T0.SDITM, T0.SDLNTY, T0.SDNXTR, T0.SDLTTR, T0.SDEMCU, T0.SDUOM, T0.SDUORG, T0.SDCRCD, T0.SDBCRC, T1.SSDCTO
FROM CRPDTA/F4211 T0,CRPDTA/F5688SDD T1
WHERE ( T0.SDITM = 86754.000000 AND T0.SDMCU = ' 3010' AND T0.SDNXTR < '620' AND T0.SDPPDJ >= 105001 AND T0.SDPPDJ <= 110304 )
AND ( T0.SDDCTO=T1.SSDCTO )
ORDER BY T0.SDUOM ASC
Oct 20 15:23:55.890120 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.890136 dbdrvsql.c746 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PrepareSQLRequest
Oct 20 15:23:55.890192 dbdrvsql.c1575 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - GetSQLStmtNameFromSQLPkg QxdaProcessExtDynEDRS
Oct 20 15:23:55.890256 dbdrvsql.c1586 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>End - GetSQLStmtNameFromSQLPkg QxdaProcessExtDynEDRS
Oct 20 15:23:55.890280 dbdrvsql.c1024 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, done with first for loop, 17 iters
Oct 20 15:23:55.890304 dbdrvsql.c1028 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, before first jdeAlloc, 1421 len
Oct 20 15:23:55.890328 dbdrvsql.c1030 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, after first jdeAlloc, 1421 len
Oct 20 15:23:55.890352 dbdrvsql.c1045 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, after second jdeAlloc, 340 len
Oct 20 15:23:55.890368 dbdrvsql.c1066 - 1512/6 WRK:GREGD_80000000_P5688SAD In PrepareSQLRequest, done with second for loop, 17 iters
Oct 20 15:23:55.890392 dbdrvsql.c1076 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PrepareSQLRequest, req=80000000000000000000800003102D10
Oct 20 15:23:55.890416 dbdrvag.c1199 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PerformRequest, result=1
Oct 20 15:23:55.890432 dbdrv_dt.c739 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering BuildInputDataMap
Oct 20 15:23:55.890456 dbdrv_dt.c1371 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting BuildInputDataMap, result=1
Oct 20 15:23:55.890480 dbdrv_dt.c307 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering BuildOutputDataMap
Oct 20 15:23:55.890560 dbdrv_dt.c699 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting BuildOutputDataMap, result=1
Oct 20 15:23:55.890584 dbdrv.c847 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting DBInitRequest, result=1
Oct 20 15:23:55.890608 dbdrv.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DBPerformRequest
Oct 20 15:23:55.890624 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.890648 dbdrvag.c823 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering DoOpenCursor
Oct 20 15:23:55.890680 dbdrvsql.c1244 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering OpenSQLCursor
Oct 20 15:23:55.890704 dbdrvsql.c1272 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - OpenSQLCursor QxdaProcessExtDynEDRS
Oct 20 15:23:55.890904 dbdrvsql.c1283 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>End - OpenSQLCursor QxdaProcessExtDynEDRS
Oct 20 15:23:55.890928 dbdrv_log.c220 - 1512/6 WRK:GREGD_80000000_P5688SAD OpenSQLCursor:Open SQL cursor: Crsr23.
Oct 20 15:23:55.890952 dbdrvsql.c1304 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting OpenSQLCursor, result=1
Oct 20 15:23:55.890968 dbdrvag.c1199 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting PerformRequest, result=1
Oct 20 15:23:55.890992 dbdrv.c1048 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting DBPerformRequest, result=1
Oct 20 15:23:55.891008 jdb_exef.c2514 - 1512/6 WRK:GREGD_80000000_P5688SAD Exiting JDB_SelectKeyed with Success
Oct 20 15:23:55.891032 dbdrvag.c963 - 1512/6 WRK:GREGD_80000000_P5688SAD Entering PerformRequest
Oct 20 15:23:55.891064 dbdrvsql.c1362 - 1512/6 WRK:GREGD_80000000_P5688SAD >>>Start - FetchSQLRow QxdaProcessExtDynEDRS
Oct 20 15:24:00.738728 jdekdisp.c2537 - 1512/2 SYSispatch ADD TO POOL type: 10, 0.0.0.0_0_m0
Oct 20 15:24:00.739104 jdekdisp.c1594 - 1512/4 WRK:Active Worker START SYSTEM JOB type 10, 0.0.0.0_0_m0
Oct 20 15:24:00.739176 jdekdisp.c1833 - 1512/4 WRK:eNetKernelIdle END SYSTEM JOB type 10, 0.0.0.0_0_m0
Oct 20 15:24:01.007848 jde400u.c2754 - 1512/2 SYSispatch _C_TS_malloc_info returned 97
Oct 20 15:24:01.008056 netflow.c1230 - 1512/2 SYSispatch About to call dispatch function, flags=0x0, Type=916
Oct 20 15:24:01.008096 jdekdisp.c2537 - 1512/2 SYSispatch ADD TO POOL type: 916, 192.168.51.26_1441_m60787
Oct 20 15:24:01.008216 jdekdisp.c1594 - 1512/7 WRK:Active Worker START SYSTEM JOB type 916, 192.168.51.26_1441_m60787
Oct 20 15:24:01.008400 jdekdisp.c1833 - 1512/7 WRK:Get User List END SYSTEM JOB type 916, 192.168.51.26_1441_m60787
</pre><hr />
I've gone through google, talked to a couple of our consultants, and looked through here and Oracle's support site, but I've been unable to find out why the slowdown happens from JDE but not directly on the database. If anyone can offer suggestions on finding the problem or fixing it, I would greatly appreciate it.
We are using EnterpriseOne 9.0 with tools 8.98, with AS400 database server. This code is called from a C business function that runs on the AS400 server. The same delay happens when running the business function on a Windows server. Our direct testing (which did not produce the slowdown) was done with iSeries Navigator.