How to read jdedebug.log

[WorldJDE]

Hello All,

We are having an issue in running an application that is taking 2-3 minutes to display 1000 records from F0411 table.
Checked from database end and there is no issue from backend side. No issue with the indexes even.
I am trying to analyse the logs and not sure of how to read the entries.
Seems to be related to Synchronous call to some Business Function.
I can see the time difference like for executing one Event it starts at 08:42:02 then the immediate next event is fired at 08:45:45. What has happened in the time between?

If I read the debuglog, I see enteries like:

Jun 06 08:42:14 ** 3732/3584 *** Start dumping data structure for business function FormatCompany
Jun 06 08:42:14 ** 3732/3584 **********************************************************************************
Jun 06 08:42:14 ** 3732/3584 OUT->[ 1] <Item>: idBhvrErrorId <type>: ID <Value>: [73121560]
Jun 06 08:42:14 ** 3732/3584 OUT->[ 2] <Item>: szBehaviorEditString <type>: STRING <Value>: []
Jun 06 08:42:14 ** 3732/3584 OUT->[ 3] <Item>: szDescription001 <type>: STRING <Value>: []
Jun 06 08:42:14 ** 3732/3584 OUT->[ 4] <Item>: szCompany <type>: STRING <Value>: [ ]
Jun 06 08:42:14 ** 3732/3584 **********************************************************************************
Jun 06 08:42:14 ** 3732/3584 *** End dumping data structure for business function FormatCompany
Jun 06 08:42:14 ** 3732/3584 **********************************************************************************
Jun 06 08:42:14 ** 3732/3584 Return value is 0 for FormatCompany. (BSFNLevel = 1)
Jun 06 08:42:14 ** 3732/3584 Entering JDB_AuditingOn
Jun 06 08:42:14 ** 3732/3584 Exiting JDB_AuditingOn with success
Jun 06 08:42:14 ** 3732/3584 Calling Business function FormatCompany for JDE. Application Name [P0413M], Version [ZJDE0001] (BSFNLevel = 1)
Jun 06 08:42:14 ** 3732/3584 **********************************************************************************

Jun 06 08:42:14 ** 3732/4004 *** Start dumping data structure for business function IsColumnInAddressBook
Jun 06 08:42:14 ** 3732/4004 **********************************************************************************
Jun 06 08:42:14 ** 3732/4004 OUT->[ 1] <Item>: idBhvrErrorId <type>: ID <Value>: [0]
Jun 06 08:42:14 ** 3732/4004 OUT->[ 2] <Item>: szBehaviorEditString <type>: STRING <Value>: [5058]
Jun 06 08:42:14 ** 3732/4004 OUT->[ 3] <Item>: szDescription001 <type>: STRING <Value>: [EMO AS ]
Jun 06 08:42:14 ** 3732/4004 OUT->[ 4] <Item>: mnAddressnumber <type>: MATH_NUMERIC <Value>: [5058]
Jun 06 08:42:14 ** 3732/4004 **********************************************************************************
Jun 06 08:42:14 ** 3732/4004 *** End dumping data structure for business function IsColumnInAddressBook
Jun 06 08:42:14 ** 3732/4004 **********************************************************************************
Jun 06 08:42:14 ** 3732/4004 Return value is 0 for IsColumnInAddressBook. (BSFNLevel = 1)
Jun 06 08:45:12 ** 3732/3584 CRTBusinessView::SelectKeyed Call to JDB_SelectKeyed failed[T:e00 F:C:\b7\system\JDEUSER\jdecgrt\RT_BVIEW.CPP Ln:184 Lv:LEVEL1]
Jun 06 08:45:12 ** 3732/3584 Entering JDB_SetRequestOptions (Option No = 7 , Setting = 22)
Jun 06 08:45:12 ** 3732/3584 RT: >>>Beginning ER: Last Grid Record Has Been Read App: Form: W0413ME [T:e00 F:C:\b7\system\JDEUSER\jdecgrt\RT_ER.cpp Ln:2977 Lv:LEVEL3]
Jun 06 08:45:12 ** 3732/3584 RT: <<<Finished ER: Last Grid Record Has Been Read App: Form: W0413ME [T:e00 F:C:\b7\system\JDEUSER\jdecgrt\RT_ER.cpp Ln:3001 Lv:LEVEL3]


I don't know what it means by BF: IsColumnInAddressBook and FormatCompany.
There are no such Busines Functions in the code.
If possible kindly put an insight into Levels as(BSFNLevel = 1)

I am very much confused.


Release: B7333, SP-23

Many Thanks in advance.
Regards
World JDE

 

[BBritain]

First of all, the BF: IsColumnInAddressBook and FormatCompany calls are legit. Either they are business functions called by other business functions or are called by the engine itself because you have a company (CO) or address book (AN8) data dictionary value in a grid (GC) or on the screen (FC). Neither of them are the problem, so don't worry about them.

The very next line - Jun 06 08:45:12 ** 3732/3584 CRTBusinessView::SelectKeyed Call to JDB_SelectKeyed failed[T:e00 F:C:\b7\system\JDEUSER\jdecgrt\RT_BVIEW.CPP Ln:184 Lv:LEVEL1] is your problem. The 'failed' should be a big clue. For some reason the database seems to be having a problem with the business view (or at least processing the SQL statement) from the business view. You might look in jde.log in the 08:42:14 time stamp and see if there is a message about fields no found in the table. Anyway, because the database server can't make headway from the business view, it is creating it's own SQL statement and processing it 'on the fly' and taking the 2-3 minutes to create this dynamically. I'm guessing that if you go back to the table and re-generate the indices (not the entire table) and then go in and look at the business view being used, you will find some field that it warns you about.

Hope this helps,
Ben again,

 

[JDE User11]

Oracle has a tool called performance workbench that you can use to help determine the problem from your logs. The tool parses your logs and reports on things like timing gaps.

Check out solution ID 201042952 on the support site.

Here is the download site they listed. http://www.peoplesoft.com/corp/en/iou/performance/perf_workbench.jsp

The help in the tool gives you pretty good understanding of what to do. Their support has helped us with the tool as well when we had questions.

Hope this can help resolve your issue.

Steven

 

[WorldJDE]

Hi Again,
Thanks alot for such a useful tool. I got this information from the log file:

** Total time in log file: 230 seconds
** Total time in level 1 BSFNs: 1 seconds (0.4 % of total)
** Total < 1 sec level 1 BSFNs: 126

It shows problem in fetching records from F0411 as per the logs as:

8. CRPDTA.F0411 O: 0 C: 0 S: 2 I: 0 D: 0 U: 0
** 2 Long Running SELECTs (>2 secs)
** 0 1sec SELECTs
** 145 Total SELECT secs (1sec+)

And also it shows that the table F0411 is making 2 selects and taking 145 seconds to do the select.

Attached above is the SQL query that is got through the SQLParser.
It is a simple query but why is it taking a lot of time?

This is the log section of jdedebug.log where the query is listed. See the time difference.

F:C:\b7\system\JDEUSER\jdecgrt\RT_ER.cpp Ln:3001 Lv:LEVEL3]
Jun 09 08:24:11 ** 10364/7840 Entering JDB_AuditingOn
Jun 09 08:24:11 ** 10364/7840 Exiting JDB_AuditingOn with success
Jun 09 08:24:11 ** 10364/7840 Calling Business function IsColumnInAddressBook for JDE. Application Name [P0413M], Version [ZJDE0001] (BSFNLevel = 1)
Jun 09 08:24:11 ** 10364/7840 Entering JDB_InitBhvr
Jun 09 08:24:11 ** 10364/7840 Entering JDB_OpenTable( Table = F0101)
Jun 09 08:24:11 ** 10364/7840 Entering JDB_FetchKeyed
Jun 09 08:24:11 ** 10364/7840 Entering JDB_CloseTable(Table = F0101)
Jun 09 08:24:11 ** 10364/7840 Entering JDB_ClearSequencing
Jun 09 08:24:11 ** 10364/7840 Entering JDB_ClearSelection
Jun 09 08:24:11 ** 10364/7840 Entering JDB_ClearBuffers
Jun 09 08:24:11 ** 10364/7840 Exiting JDB_ClearBuffers with success.
Jun 09 08:24:11 ** 10364/7840 Exiting JDB_CloseTable(Table = F0101) with Success
Jun 09 08:24:11 ** 10364/7840 Entering JDB_FreeBhvr
Jun 09 08:24:11 ** 10364/7840 Return value is 0 for IsColumnInAddressBook. (BSFNLevel = 1)
Jun 09 08:24:11 ** 10364/11676 Entering JDB_ClearSelection
Jun 09 08:24:11 ** 10364/11676 Entering JDB_ClearSequencing
Jun 09 08:24:11 ** 10364/11676 Entering JDB_SetSelection
Jun 09 08:24:11 ** 10364/11676 Exiting JDB_SetSelection With Success
Jun 09 08:24:11 ** 10364/11676 Entering JDB_SetSequencing
Jun 09 08:24:11 ** 10364/11676 Entering JDB_SelectKeyed
Jun 09 08:24:11 ** 10364/11676 ODBC:S DBInitRequest(new) conn=03382550 hd=03C9BEB0 dr=03C8D778 BKNJDETS01 A (JDE@Business Data - CRP)
Jun 09 08:24:11 ** 10364/11676 SELECT RPKCO, RPDOC, RPDCT, RPSFX, RPSFXE, RPAN8, RPPYE, RPDDJ, RPCO, RPPST, RPAG, RPAAP, RPADSC, RPADSA, RPCRRM, RPCRCD, RPCRR, RPACR, RPFAP, RPCDS, RPCDSA, RPGLC, RPGLBA, RPMCU, RPVINV, RPPO, RPRMK, RPRP1 FROM CRPDTA.F0411 WHERE ( RPPST = 'A' AND RPAN8 = 5058.000000 ) ORDER BY RPAN8 ASC,RPDDJ ASC,RPDOC ASC,RPDCT ASC,RPKCO ASC,RPSFX ASC
Jun 09 08:25:46 ** 10364/11676 Data selection processed with high concurrency option. Jun 09 08:25:46 ** 10364/11676 SELECT RPKCO, RPDOC, RPDCT, RPSFX, RPSFXE, RPAN8, RPPYE, RPDDJ, RPCO, RPPST, RPAG, RPAAP, RPADSC, RPADSA, RPCRRM, RPCRCD, RPCRR, RPACR, RPFAP, RPCDS, RPCDSA, RPGLC, RPGLBA, RPMCU, RPVINV, RPPO, RPRMK, RPRP1 FROM CRPDTA.F0411 (NOLOCK) WHERE ( RPPST = 'A' AND RPAN8 = 5058.000000 ) ORDER BY RPAN8 ASC,RPDDJ ASC,RPDOC ASC,RPDCT ASC,RPKCO ASC,RPSFX ASC
Jun 09 08:26:36 ** 10364/11676 Entering JDB_SetRequestOptions (Option No = 7 , Setting = 22)
Jun 09 08:26:36 ** 10364/11676 Entering JDB_Fetch
Jun 09 08:26:36 ** 10364/11676 Entering JDB_AuditingOn
Jun 09 08:26:36 ** 10364/11676 Exiting JDB_AuditingOn with success
Jun 09 08:26:36 ** 10364/11676 Calling Business function DecimalsTriggerGetbyCOCRCD for JDE. Application Name [], Version [] (BSFNLevel = 1)
Jun 09 08:26:36 ** 10364/11676 Entering JDB_InitBhvr
Jun 09 08:26:36 ** 10364/11676 Entering JDB_OpenTable( Table = F0010)
Jun 09 08:26:36 ** 10364/11676 Entering JDB_FetchKeyed
Jun 09 08:26:36 ** 10364/11676 Entering JDB_OpenTable( Table = F0013)
Jun 09 08:26:36 ** 10364/11676 Entering JDB_FetchKeyed
Jun 09 08:26:36 ** 10364/11676 ODBC:S DBInitRequest(new) conn=03382550 hd=03CD9E78 dr=03CDD570 BKNJDETS01 A (JDE@Business Data - CRP)
Jun 09 08:26:36 ** 10364/11676 SELECT * FROM CRPDTA.F0013 WHERE ( CVCRCD = 'NOK' )
Jun 09 08:26:36 ** 10364/11676 Entering JDB_FreeBhvr
Jun 09 08:26:36 ** 10364/11676 Return value is 0 for DecimalsTriggerGetbyCOCRCD. (BSFNLevel = 1)
Jun 09 08:26:36 ** 10364/11676 RT: >>>Beginning ER: Grid Record is Fetched App: Form: W0413ME [T:2d9c F:C:\b7\system\JDEUSER\jdecgrt\RT_ER.cpp Ln:2977 Lv:LEVEL3]
Jun 09 08:26:36 ** 10364/11676 RT: BSFN: Calling : RetrieveCompanyCurrencyCode App: P0413M Form: W0413ME [T:2d9c F:C:\b7\system\JDEUSER\JDECGRT\RT_BSFN.cpp Ln:1519 Lv:BUSINESS FUNC]
Jun 09 08:26:36 ** 10364/11676 Entering JDB_AuditingOn
Jun 09 08:26:36 ** 10364/11676 Exiting JDB_AuditingOn with success
Jun 09 08:26:36 ** 10364/11676 Calling Business function RetrieveCompanyCurrencyCode for JDE. Application Name [P0413M], Version [ZJDE0001] (BSFNLevel = 1)
What does it mean by: Data selection processed with high concurrency option.

It seems out of 230 seconds, 145 seconds it spends in searching records in F0411. Any idea, why this is happening.
If I run the same query as provided by logs in backend(SQL Server), it takes 8 seconds.?

 

[mco]

We are in the process of migrating from iSeries to Wintel and are currently experiencing a similar problem with F4211. I was wondering if you found a resolution to this one?