Slow SQL Statement

ganlida

Member
Currently I am facing performance slowness issue when querying F4072 which has million of records.

I created a business view of F4072 with limited columns and used FetchSingle to fetch single record and it worked fine for the last 2 weeks. But now I am encountering the slowness issue when carrying out the query since 2 days ago.

Tested in Web and Fat and the problem was only with the Web. Checked JAS Debug Log and found before the resultset was returned, the following activity: "[Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis" had taken 1 minute to process. May I know what was JAS doing and whether it is related to the sql statement or the system needs some fine tuning?

I need some advice. Thanks!

The following is the part of debug log related to the SQL statement:

Highlighted in blue: SQL Statement querying F4072 via BSVW V554072D
Highlighted in red: Where the delay happens

[ Worker Thread - OWVirtual_Thread_Group9 Assigned To com.jdedwards.runtime.virtual.[email protected]] NONE : Reused BVTemplate for V554072D
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table Template for F4072
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused BVTemplate for V554072D
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table Template for F4072
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table Template for F4072
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : DEBUG (Level 3) > [E5110527 - JPD7334] > Select :: DSN is [Business Data - PROD], DB User is [rsmis]
<font color="blue"> [1] SQL Statement :
SELECT F4072.ADAST, F4072.ADITM, F4072.ADAN8, F4072.ADICID, F4072.ADSDGR, F4072.ADSDV1, F4072.ADSDV2, F4072.ADSDV3, F4072.ADCRCD, F4072.ADUOM, F4072.ADMNQ, F4072.ADEXDJ FROM PRODDTA.F4072 F4072 WHERE (F4072.ADCRCD = 'SGD') AND (F4072.ADAST = 'XXF233') AND (F4072.ADEXDJ >= 110112) AND (F4072.ADAN8 = 0) </font>
[2] Where Columns' messages are :
[1] [F4072.ADCRCD] , [CurrencyCodeFrom] , [EVDT_STRING]
[2] [F4072.ADAST] , [PriceAdjustmentType] , [EVDT_STRING]
[3] [F4072.ADEXDJ] , [DateExpiredJulian1] , [EVDT_JDEDATE]
[4] [F4072.ADAN8] , [AddressNumber] , [EVDT_MATH_NUMERIC]
[3] Select Columns' messages are :
[1] [F4072.ADMNQ] , [QuantityMinimum] , [EVDT_MATH_NUMERIC]
[2] [F4072.ADEXDJ] , [DateExpiredJulian1] , [EVDT_JDEDATE]
[3] [F4072.ADAN8] , [AddressNumber] , [EVDT_MATH_NUMERIC]
[4] [F4072.ADUOM] , [UnitOfMeasureAsInput] , [EVDT_STRING]
[5] [F4072.ADCRCD] , [CurrencyCodeFrom] , [EVDT_STRING]
[6] [F4072.ADITM] , [IdentifierShortItem] , [EVDT_MATH_NUMERIC]
[7] [F4072.ADSDV3] , [SalesDetailValue03] , [EVDT_STRING]
[8] [F4072.ADSDV2] , [SalesDetailValue02] , [EVDT_STRING]
[9] [F4072.ADSDV1] , [SalesDetailValue01] , [EVDT_STRING]
[10] [F4072.ADICID] , [ItemCustomerKeyID] , [EVDT_MATH_NUMERIC]
[11] [F4072.ADSDGR] , [SalesDetailGroup] , [EVDT_STRING]
[12] [F4072.ADAST] , [PriceAdjustmentType] , [EVDT_STRING]
[4] Data Source Information is :
[1] DataSource Server : [SGSINJDE04]
[2] DataBase Name : [JDEPROD]
[3] Owner : [PRODDTA]
[4] LibraryList Name : []
[5] Library Name : []
[6] DataSource Type : [O]
[7] Julian Date : [true]
[8] Decimal shifting : [true]

2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To com[email protected]] JDBC : Obtaining single use connection
2010-04-22 11:29:28.461 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Prepared Statement added to pool : SELECT F4072.ADAST, F4072.ADITM, F4072.ADAN8, F4072.ADICID, F4072.ADSDGR, F4072.ADSDV1, F4072.ADSDV2, F4072.ADSDV3, F4072.ADCRCD, F4072.ADUOM, F4072.ADMNQ, F4072.ADEXDJ FROM PRODDTA.F4072 F4072 WHERE (F4072.ADCRCD = ?) AND (F4072.ADAST = ?) AND (F4072.ADEXDJ >= ?) AND (F4072.ADAN8 = ?) - Current Pool Size :13
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : clean cache group -> JDEPROD_rsmis
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : ENTER: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove() before calling dispose(), CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1325534594
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove(), before fireCacheCleaned, CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1325534594
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : ENTER: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove() before calling dispose(), CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 2081787266
2010-04-22 11:29:37.227 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove(), before fireCacheCleaned, CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 2081787266
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : ENTER: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove() before calling dispose(), CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 737709442
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove(), before fireCacheCleaned, CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 737709442
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : ENTER: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove() before calling dispose(), CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1988791682
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove(), before fireCacheCleaned, CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1988791682
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : ENTER: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove() before calling dispose(), CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1120308345
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] JAS : In CacheGroup.remove(), before fireCacheCleaned, CacheGroup JDEPROD_rsmis class com.jdedwards.system.lib.pool.OWConnection Object ID 1120308345
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
2010-04-22 11:29:37.242 [Thread-11-CacheMonitor-Daemon] NONE : Closing Prepared Statement
<font color="red">
2010-04-22 11:29:37.258 [Thread-11-CacheMonitor-Daemon] JAS : RETURN: remove() CacheGroup JDEPROD_rsmis
2010-04-22 11:30:37.258 [Thread-11-CacheMonitor-Daemon] JAS : clean cache group -> JDBCProxy
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : dbRequest: DBRequest: NextPageID=-1 Operation = Fetch Single Type: View Table: V554072D PageSize: 1 ResultSet: JASResultSet is returning 1 rows </font>
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : class [email protected] >*trace*> close result set cache
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : class [email protected] >*trace*> JDBCProxy/jdbcProxy()>>>response is good(execute()) -> , status = 2, nextpageid = -1, data = JASResultSet is returning 1 rows
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table Template for F4073
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table Template for F4073
2010-04-22 11:31:05.555 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : DEBUG (Level 3) > [E5110527 - JPD7334] > Select :: DSN is [Business Data - PROD], DB User is [rsmis]

Thanks in advance for the advice and help!
 

Alex_Pastuhov

Legendary Poster
I think it's a bug in JAS - it does some waiting for no apparent reason in the CacheGroup class / ready method, called from the CacheMonitor class / run method (of course, this is really of no use to you, but if any JDE JAS developers are watching, perhaps they can have a look at the code).

I think this time interval is controlled by the following setting JAS.INI:

[CACHE]
CacheCheck=60000 # Exactly 1 minute you are observing ;-)

So, perhaps if you set it to 0 and bounce the server, it may fix this issue.

Please, keep us posted on your results...
 

ganlida

Member
Alex, thanks for the reply! I sure will keep your guy informed of the result!

I am not familiar with CNC. So do you mind explain a bit the purpose of CacheCheck?
 

ganlida

Member
The following is the result when I reduced CacheChecking to 30 seconds:

Reused BVTemplate for V554072D
2010-04-23 16:02:44.758 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table

Template for F4072
2010-04-23 16:02:44.758 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Reused Table

Template for F4072
2010-04-23 16:02:44.758 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : DEBUG (Level 3) >

[E5110527 - JPD7334] > Select :: DSN is [Business Data - PROD], DB User is [rsmis]
[1] SQL Statement :
SELECT F4072.ADAST, F4072.ADITM, F4072.ADAN8, F4072.ADICID, F4072.ADSDGR, F4072.ADSDV1, F4072.ADSDV2, F4072.ADSDV3, F4072.ADCRCD, F4072.ADUOM,

F4072.ADMNQ, F4072.ADEXDJ FROM PRODDTA.F4072 F4072 WHERE (F4072.ADCRCD = 'SGD') AND (F4072.ADAST = 'XXF233') AND (F4072.ADEXDJ >= 110113) AND (F4072.ADAN8

= 0)
[2] Where Columns' messages are :
[1] [F4072.ADCRCD] , [CurrencyCodeFrom] , [EVDT_STRING]
[2] [F4072.ADAST] , [PriceAdjustmentType] , [EVDT_STRING]
[3] [F4072.ADEXDJ] , [DateExpiredJulian1] , [EVDT_JDEDATE]
[4] [F4072.ADAN8] , [AddressNumber] , [EVDT_MATH_NUMERIC]
[3] Select Columns' messages are :
[1] [F4072.ADMNQ] , [QuantityMinimum] , [EVDT_MATH_NUMERIC]
[2] [F4072.ADEXDJ] , [DateExpiredJulian1] , [EVDT_JDEDATE]
[3] [F4072.ADAN8] , [AddressNumber] , [EVDT_MATH_NUMERIC]
[4] [F4072.ADUOM] , [UnitOfMeasureAsInput] , [EVDT_STRING]
[5] [F4072.ADCRCD] , [CurrencyCodeFrom] , [EVDT_STRING]
[6] [F4072.ADITM] , [IdentifierShortItem] , [EVDT_MATH_NUMERIC]
[7] [F4072.ADSDV3] , [SalesDetailValue03] , [EVDT_STRING]
[8] [F4072.ADSDV2] , [SalesDetailValue02] , [EVDT_STRING]
[9] [F4072.ADSDV1] , [SalesDetailValue01] , [EVDT_STRING]
[10] [F4072.ADICID] , [ItemCustomerKeyID] , [EVDT_MATH_NUMERIC]
[11] [F4072.ADSDGR] , [SalesDetailGroup] , [EVDT_STRING]
[12] [F4072.ADAST] , [PriceAdjustmentType] , [EVDT_STRING]
[4] Data Source Information is :
[1] DataSource Server : [SGSINJDE04]
[2] DataBase Name : [JDEPROD]
[3] Owner : [PRODDTA]
[4] LibraryList Name : []
[5] Library Name : []
[6] DataSource Type : [O]
[7] Julian Date : [true]
[8] Decimal shifting : [true]

<font color="red">2010-04-23 16:02:44.758 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : Obtaining single

use connection
2010-04-23 16:02:44.758 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] NONE : Prepared Statement

added to pool : SELECT F4072.ADAST, F4072.ADITM, F4072.ADAN8, F4072.ADICID, F4072.ADSDGR, F4072.ADSDV1, F4072.ADSDV2, F4072.ADSDV3, F4072.ADCRCD,

F4072.ADUOM, F4072.ADMNQ, F4072.ADEXDJ FROM PRODDTA.F4072 F4072 WHERE (F4072.ADCRCD = ?) AND (F4072.ADAST = ?) AND (F4072.ADEXDJ >= ?) AND (F4072.ADAN8 =

?) - Current Pool Size :1
2010-04-23 16:03:43.804 [ Worker Thread - OWVirtual_Thread_Group9 Assigned To [email protected]] JDBC : dbRequest:

DBRequest: NextPageID=-1 Operation = Fetch Single Type: View Table: V554072D PageSize: 1 ResultSet: JASResultSet is returning 1 rows</font>

From the log above, we can see the "remove() CacheGroup JDEPROD_rsmis" disappeared and the respond time did improve from 1 and half minutes to 58~59 seconds. However, it didn't further improve when tried to reduce CacheChecking interval some more.

But from the logfile, now we can see the "Prepared Statement added to pool" has taken 1 minute to process. It seemed taking too much time to cache JDBC prepared statements.

Any advice to improve this prepared statement cache performance? or my statement is not efficient enough?
 

ganlida

Member
Hi Alex,

No chance to test the 0 value. However, by following the advice you given, we have found the information below:


<font color="blue"> Keep ResultSet to 60000 and tune CacheCheck setting from 60000 to 300000.

Example JAS.INI
[CACHE]
# These intervals are in milliseconds. For example, 60000ms = 1 minute
ResultSet=60000
CacheCheck=300000

Details:
It is not just the ResultSet setting in jas.ini, a corresponding setting CacheCheck also needs to be in tune with ResultSet setting. CacheCheck setting is the time interval for a background thread to check the result set cache to see if the result set is timed out or not.

For example, if CacheCheck is set to 60000, that means every one minute the background thread will check the result set cache. If this background check fails in one minute then ResultSet would timeout based on the ResultSet setting causing the fetch (get next page) timing out.

However, setting CacheCheck to 60000(one minute) does not really run background thread exactly every one minute. It could take more than one minute for the background to start running since this is controlled by JVM and there is no guarantee that the background thread will be kicked off exactly every one minute.

Note: Changes to INI file requires bounce of web services to get the changes in effect. </font>

After changing both CacheCheck and ResultSet as what recommended the issue is resolved.

Thanks so much for your advice!
 
Top