SQL Fetch Row Slowdown

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.

Have you checked if you are up to date with PTFs on your iSeries?

Following are Informational APARs for E1 on iSeries.
V5R4M0 - II14151
V6R1M0 - II14331
V7R1M0 - II14493

Also, if you are using the Web client, did you try deleting the JAVAMIGBAA SQL package from the iSeries?

Gary,

My initial guess is that the 400 is paging in things you need (mostly access paths, and possibly some data) the first time.

AFter that, things go much quicker. I'd also check your index advisor and see if there are any suggestions involving order type for the files involved.

Tom

Gary,

this is a stab in the dark, but what happens if you remove the Order By clause?

Thanks for all your help. Index advisor didn't give us anything new, and I'm checking right now on the packages.

I'm going to edit the C function to remove the sorting and see if that changes anything, but I'm hoping it won't. Because I need to account for different UoMs, sorting by UoM means I can store a conversion rate rather than call a conversion function for each order pulled. Incidentally, many of the queries that take a long time only pull a handful of records, some only pulling one.

I'll get back to you with any new information.

You may want to check the last statistics collected date or analyzed date of key tables involved.

Gary,

Remember it isn't the number of records it PULLS, its the number of records it PROCESSES

Tom

Gary,

JDE uses server side cursors to access data, these are standard APIs which run on all database platforms and also manages the paging of data. When you run the SQL natively in DB2 it will execute differently than if the very same query is executed by a server side cursor. That explains the difference in execution times that you see between JDE and running it natively. Even though the SQL is being executed from a compiled C BSFN it still goes through the JDE database middleware where the call gets executed as a cursor.

Unfortuantely that doesn't help you much as there is nothing you can do about changing how JDE executes the queries. Best suggestion I can come up with is look at adding covering indexes or changing the query slightly to try and improve how it gets executed as a server side cursor.

Hope that helps.

Jack.

Taking advice from users and probing more, I went back to looking at indexes. Like I said before, Index advisor wasn't recommending anything, but when I examined the index the iSeries was using on the query (through query analyzer), I noticed that the column lineup and sorting order weren't intuitive. UoM was sorting descending instead of ascending, and only a partial key was used (PPDJ and NXTR weren't being utilized). I custom assembled an index with the following fields:

<font class="small">Code:</font><hr /><pre>
CREATE INDEX CRPDTA.F4211_GP3B ON CRPDTA.F4211 ( SDMCU ASC , SDITM ASC, SDNXTR ASC , SDPPDJ ASC, SDUOM ASC, SDDCTO ASC ) ;
</pre><hr />
...and found that now the query analyzer was using this index instead, though there wasn't really a change in the time taken to execute. However, going back to JDE did show a major improvement; the application logs no longer showed a long delay between executing the select and fetch next, and the overall process went from taking around 20 seconds to almost 3 seconds--which is reasonable considering the task.

All-in-all, it really was an indexing problem all along, but apprently iSeries index advisor doesn't always recommend the absolute best index to use if an existing index will suffice on its end.

Thanks for your assistance