• JDELIST is celebrating its 20 year anniversary today!
  • Introducing Dark Mode! Switch by clicking on the lightbulb icon next to Search or by clicking on Default style at the bottom left of the page!

UBE pauses every 50 records

TimPierce

Reputable Poster
Any have any ideas on this one?!

We have a UBE with a Group Section joining the F0911, F0618, F0101 and F0006 all with Simple Joins. This is taking much longer to run since we upgraded to 9.2

After debugging we realised that this section is pausing for 2 or 3 minutes every 50 records, almost like it has to refresh the cache before continuing to read records.

Is there a setting somewhere we can check?

Thanks!
 

TimPierce

Reputable Poster
Update - there is an insert statement to a custom table in the section. When I comment it out there is no pause. Is it a commit problem?
 

TimPierce

Reputable Poster
Thanks for the replies guys, I'll try both suggestions.

Ran it in debug this morning and it paused for 30 minutes trying to run a SQL Statement (see log extract below). I think the WITH (NOLOCK) on each table and "Data selection processed with high concurrency option." message have something to do with it.

If I run the same statement in SQL it finishes in 3 minutes.




n 30 10:13:43.067001 - 1816/3156 UNKNOWN ODBC[JDBODBC.C,7856] STMT:00 [HYT00][0] [Microsoft][SQL Server Native Client 11.0]Query timeout expired
Jan 30 10:13:43.067002 - 1816/3156 UNKNOWN ODBC[JDBODBC.C,7893] wSQLCloseCursor - warning: invalid cursor state failure. rc = -1
Jan 30 10:13:43.067003 - 1816/3156 UNKNOWN ODBC[JDBODBC.C,7893] STMT:00 [24000][0] [Microsoft][SQL Server Native Client 11.0]Invalid cursor state
Jan 30 10:13:43.176000 - 1816/3156 UNKNOWN Data selection processed with high concurrency option.
Jan 30 10:13:43.176003 - 1816/3156 UNKNOWN SELECT DISTINCT T0.YTAN8, T0.YTPRTR, T0.YTCO, T0.YTHMCU, T0.YTMCU, T0.YTGMCU, T0.YTGOBJ, T0.YTGSUB, T0.YTPHRW, T0.YTPDBA, T0.YTDGL, T0.YTDWK, T0.YTEXR, T0.YTGICU, T0.YTAID, T0.YTALT0, T0.YTCRCD, T0.YTCRDC, T1.MCMCU, T1.MCAN8O, T1.MCDL01, T1.MCRP25, T1.MCANPA, T1.MCMCUS, T2.GLKCO, T2.GLDCT, T2.GLDOC, T2.GLDGJ, T2.GLJELN, T2.GLEXTL, T2.GLPOST, T2.GLICU, T2.GLCO, T2.GLAID, T2.GLMCU, T2.GLOBJ, T2.GLSUB, T2.GLLT, T2.GLCRCD, T2.GLAA, T2.GLU, T2.GLODOC, T2.GLALT1, T2.GLBC, T2.GLBCRC, T2.GLCRRM, T3.ABAN8, T3.ABALPH FROM JDE_QUALITYASSURANCE.QADTA.F0618 T0 WITH (NOLOCK) ,JDE_QUALITYASSURANCE.QADTA.F0006 T1 WITH (NOLOCK) ,JDE_QUALITYASSURANCE.QADTA.F0911 T2 WITH (NOLOCK) ,JDE_QUALITYASSURANCE.QADTA.F0101 T3 WITH (NOLOCK) WHERE ( ( T0.YTGOBJ = '501010' AND T2.GLPOST = 'P' ) AND ( T0.YTDWK >= 116340 AND T1.MCRP25 = '1405' AND T0.YTDWK <= 116340 AND T1.MCRP25 = '1405' ) ) AND ( T0.YTUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T1.MCUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T2.GLUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T3.ABUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T0.YTGMCU = T1.MCMCU AND T0.YTGMCU = T2.GLMCU AND T0.YTGOBJ = T2.GLOBJ AND T0.YTGSUB = T2.GLSUB AND T0.YTGICU = T2.GLICU AND T0.YTAN8 = T3.ABAN8 ) ORDER BY T0.YTAN8 ASC,T0.YTDWK ASC,T0.YTPRTR ASC
Jan 30 10:44:39.500000 - 1816/3156 UNKNOWN Exiting DBPerformRequest
Jan 30 10:44:39.500001 - 1816/3156 UNKNOWN Exiting JDB_SelectKeyed with Success
Jan 30 10:44:39.500002 - 1816/3156 UNKNOWN Entering JDB_StartRetainPrevious (hRequest 39175818)
 

TimPierce

Reputable Poster
I would also look at the tables indexes.

Chan
Yes, the fragmentation was >95% in our QA environment so we regenerated the indexes and the job ran in 45 minutes on exactly the same data (versus 51 hours in Production!).

We're going to re-gen the PD indexes tonight, but the fragmentation is low (<3%) so I can't imagine what effect it might have ....but it's worth a try.
 

brandonkirsch

Active Member
You could have a table locking issue as well, where the INSERT is being held up by some other transaction that's concurrently running against the target table.
 

johndanter

Legendary Poster
Is this a cloned UBE?

If so did you make sure the allow Table I/O tickbox was ticked? Not sure what difference it makes but it's there for a reason I'd imagine
 

TimPierce

Reputable Poster
Is this a cloned UBE?

If so did you make sure the allow Table I/O tickbox was ticked? Not sure what difference it makes but it's there for a reason I'd imagine
I'll check that, thanks.

But we recently copied the PD data back to PY and it ran in under an hour. So it seems to be related to Infrastructure and/or Configuration.

Still looking for the reason!
 

TimPierce

Reputable Poster
Update - debugging it again and it appears to be hanging on a SELECT statement. It tries once, times out 17 times as per the jde.ini setting then hangs.

It's been doing nothing for 90 minutes so far. I <think> when this happens it adds WITH (NOLOCK) to the joins in the Select and retries, I suspect that's what it's hanging on.

Last entries in the jdedebug.log as follows, it's currently 1:59pm:-


Feb 08 12:11:56.239020 - 4124/5056 UNKNOWN SELECT DISTINCT T0.YTAN8, T0.YTPRTR, T0.YTCO, T0.YTHMCU, T0.YTMCU, T0.YTGMCU, T0.YTGOBJ, T0.YTGSUB, T0.YTPHRW, T0.YTPDBA, T0.YTDGL, T0.YTDWK, T0.YTEXR, T0.YTGICU, T0.YTAID, T0.YTALT0, T0.YTCRCD, T0.YTCRDC, T1.MCMCU, T1.MCAN8O, T1.MCDL01, T1.MCRP25, T1.MCANPA, T1.MCMCUS, T2.GLKCO, T2.GLDCT, T2.GLDOC, T2.GLDGJ, T2.GLJELN, T2.GLEXTL, T2.GLPOST, T2.GLICU, T2.GLCO, T2.GLAID, T2.GLMCU, T2.GLOBJ, T2.GLSUB, T2.GLLT, T2.GLCRCD, T2.GLAA, T2.GLU, T2.GLODOC, T2.GLALT1, T2.GLBC, T2.GLBCRC, T2.GLCRRM, T3.ABAN8, T3.ABALPH FROM JDE_PRODUCTION.PRODDTA.F0618 T0,JDE_PRODUCTION.PRODDTA.F0006 T1,JDE_PRODUCTION.PRODDTA.F0911 T2,JDE_PRODUCTION.PRODDTA.F0101 T3 WHERE ( ( T0.YTGOBJ = '501010' AND T2.GLPOST = 'P' ) AND ( T0.YTDWK >= 116336 AND T1.MCRP25 = '1400' AND T0.YTDWK <= 116366 AND T1.MCRP25 = '1400' ) ) AND ( T0.YTUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T1.MCUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T2.GLUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T3.ABUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T0.YTGMCU = T1.MCMCU AND T0.YTGMCU = T2.GLMCU AND T0.YTGOBJ = T2.GLOBJ AND T0.YTGSUB = T2.GLSUB AND T0.YTGICU = T2.GLICU AND T0.YTAN8 = T3.ABAN8 ) ORDER BY T0.YTAN8 ASC,T0.YTDWK ASC,T0.YTPRTR ASC
Feb 08 12:11:56.239021 - 4124/5056 UNKNOWN Entering DBPerformRequest
Feb 08 12:11:56.239022 - 4124/5056 UNKNOWN ODBC:S DBPerformRequest req=27722890 con=0B545838 env=00EAAEA8 dbc=00EAAF20 spid=94 TOCPDBERP A (MSIUSER@TOCPDBERP)
Feb 08 12:11:57.241000 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7856] wSQLExecute failure. rc = -1
Feb 08 12:11:57.241001 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7856] STMT:00 [HYT00][0] [Microsoft][SQL Server Native Client 11.0]Query timeout expired
Feb 08 12:11:57.241002 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7893] wSQLCloseCursor - warning: invalid cursor state failure. rc = -1
Feb 08 12:11:57.241003 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7893] STMT:00 [24000][0] [Microsoft][SQL Server Native Client 11.0]Invalid cursor state
<repeated 17 times>
Feb 08 12:12:12.681002 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7893] wSQLCloseCursor - warning: invalid cursor state failure. rc = -1
Feb 08 12:12:12.681003 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7893] STMT:00 [24000][0] [Microsoft][SQL Server Native Client 11.0]Invalid cursor state
Feb 08 12:12:13.786000 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7856] wSQLExecute failure. rc = -1
 

TimPierce

Reputable Poster
Yes, as suspected (log below). If I run the SQL Select in isolation in query analyzer it finishes in 3 minutes.

Feb 08 12:12:13.786003 - 4124/5056 UNKNOWN ODBC[JDBODBC.C,7893] STMT:00 [24000][0] [Microsoft][SQL Server Native Client 11.0]Invalid cursor state
Feb 08 12:12:13.886000 - 4124/5056 UNKNOWN Data selection processed with high concurrency option.
Feb 08 12:12:13.886001 - 4124/5056 UNKNOWN SELECT DISTINCT T0.YTAN8, T0.YTPRTR, T0.YTCO, T0.YTHMCU, T0.YTMCU, T0.YTGMCU, T0.YTGOBJ, T0.YTGSUB, T0.YTPHRW, T0.YTPDBA, T0.YTDGL, T0.YTDWK, T0.YTEXR, T0.YTGICU, T0.YTAID, T0.YTALT0, T0.YTCRCD, T0.YTCRDC, T1.MCMCU, T1.MCAN8O, T1.MCDL01, T1.MCRP25, T1.MCANPA, T1.MCMCUS, T2.GLKCO, T2.GLDCT, T2.GLDOC, T2.GLDGJ, T2.GLJELN, T2.GLEXTL, T2.GLPOST, T2.GLICU, T2.GLCO, T2.GLAID, T2.GLMCU, T2.GLOBJ, T2.GLSUB, T2.GLLT, T2.GLCRCD, T2.GLAA, T2.GLU, T2.GLODOC, T2.GLALT1, T2.GLBC, T2.GLBCRC, T2.GLCRRM, T3.ABAN8, T3.ABALPH FROM JDE_PRODUCTION.PRODDTA.F0618 T0 WITH (NOLOCK) ,JDE_PRODUCTION.PRODDTA.F0006 T1 WITH (NOLOCK) ,JDE_PRODUCTION.PRODDTA.F0911 T2 WITH (NOLOCK) ,JDE_PRODUCTION.PRODDTA.F0101 T3 WITH (NOLOCK) WHERE ( ( T0.YTGOBJ = '501010' AND T2.GLPOST = 'P' ) AND ( T0.YTDWK >= 116336 AND T1.MCRP25 = '1400' AND T0.YTDWK <= 116366 AND T1.MCRP25 = '1400' ) ) AND ( T0.YTUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T1.MCUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T2.GLUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T3.ABUSER NOT BETWEEN 'JOBHR ' AND 'JOBJR ' ) AND ( T0.YTGMCU = T1.MCMCU AND T0.YTGMCU = T2.GLMCU AND T0.YTGOBJ = T2.GLOBJ AND T0.YTGSUB = T2.GLSUB AND T0.YTGICU = T2.GLICU AND T0.YTAN8 = T3.ABAN8 ) ORDER BY T0.YTAN8 ASC,T0.YTDWK ASC,T0.YTPRTR ASC
Feb 08 14:05:23.091000 - 4124/5056 UNKNOWN Exiting DBPerformRequest
Feb 08 14:05:23.091002 - 4124/5056 UNKNOWN Exiting JDB_SelectKeyed with Success
Feb 08 14:05:23.091001 - 4124/2816 UNKNOWN ODBC[JDBODBC.C,4664] wSQLCloseCursor - warning: invalid cursor state failure. rc = -1
Feb 08 14:05:23.091003 - 4124/2816 UNKNOWN ODBC[JDBODBC.C,4664] STMT:00 [24000][0] [Microsoft][SQL Server Native Client 11.0]Invalid cursor state
 

Larry_Jones

Legendary Poster
Looks like blocking / concurrency issue to me.
You can either:
a) Fix the offending code/design (I assume its a custom UBE)
-or-
b) Implement Row Level Versioning on your SQL Server Database. Here's 2012 post from Justin Miller (smart guy) on this subject
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
A key point with SQL Server is that without "Row Level Versioning" turned on you get blocking SELECTS. SELECT statements can block other SELECT statements. So this NOLOCK fallback that E1 uses comes into play regardless of whether the blocking condition is the result of an update.

With NOLOCK giving no guarantee of integrity I have decided at all my SQL Server sites to do my best to eliminate the possibility that E1 will revert to NOLOCK after 3 tries. Dirty reads are not "don't give me pending updates that have not been committed" but can be "give me whatever happens to have been written out to the data files at this particular moment". Unless you are running a non-update UBE with values that will never need to be audited (no financial balances other than indicative amounts) then I submit that you would never want what NOLOCK gives you.

To solve the SQL blocking issue you can either look at Row Level Versioning or optimising you DB I/O including TEMPDB to get the best possible query execution times. I came from Oracle first and was floored when I discovered that SQL Server did blocking reads. This I hear has explained in the past why SQL Server could beat Oracle performance benchmarks. If you aren't spending time with concurrency management by simply blocking other processes then you can run things faster. In SQL 2005 they finally introduced RLV which allows SQL Server to behave like Oracle and not block selects. You get a clean and consistent SELECT with no blocking. Blocking then only comes into play with writes. RLV has a number of considerations including increased TEMPDB usage. You shouldn't just turn it on. That being said I have had great results at all my SQL sites.

If you can't turn on RLV then you can only look at optimising your I/O. Since long running SELECTS with ORDER BY are natural for E1 you want to get your longest running queries to execute within a time where other processes that would be blocked by selecting on the same data don't wait long enough for the timeout. Optimising TEMPDB I/O is a key way to do this.

As to the difference between 8.10/older tools and 8.98.4.2 I think that they introduced this parameter to try and get around queries simply hanging until they got their turn. I think it was a bad approach. Reissuing a query multiple times with the final try being a dirty read is a silly approach. It introduces more system activity/churning and give you the possiblity for dirty data to be used as input to update transactions. If the setting was going to be introduced at all they should have a provided a system API to configure it at runtime in NER and C code and had some sort of OCM mapping that would control against which programs, UBEs and perhaps tables the setting could be applied.

In short - my advice is to implement row-level versioning.
 

craig_welton

Legendary Poster
Agreed. We saw RCSI have a very positive impact at SQL server clients. It's not going to fix an overly complex query, but it helps with the blocking. It's also recommended in Oracle's tuning manual - Advanced Tuning for JD Edwards EnterpriseOne Implementations

Craig
 

TimPierce

Reputable Poster
Thanks all.

I'm pretty sure we already have RSCI up and running, I'll check with our DBA to see if the setup is correct.
 

TimPierce

Reputable Poster
Yes, it is already set up.

I ran some analytics this morning and I saw the SQL Select got up to 3 billion logical reads before moving on. It's almost as though it's completely ignoring the indexes.
 
Top