ADF: Monitor performance of VO query using base-classes

Problem Description: In ADF we use VO at multiple places. For example we can use a VO as view-instance in AM or ViewAccessor in EO/VO. There are different events which can execute these VOs
For example if I drag and drop a VO-view-instance on a page, it will get executed automatically. Same thing about view accessor, they gets executed when needed by framework. Because framework is taking care of VO execution at many places, we need to double sure about followings
1. Which all VOs are getting executed when I do some activity (like load a page/click a button etc)
2. What is exact query that framework has formed?
3. What are bind parameters? All parameters are binded or some blank query is firing.

In this blog I am trying to implement a central approach, which will tell me about all that information.

Solution:
Our solution is quite simple
1. Create baseclasses for your model project
2. Use those baseclasses in your VOs/EOs
3. Override executeQuery method of baseclass and generate above required information

Let us implement it

1. Create baseclasses for your model project: It is always a good practice to create baseclasses for your model project. Base classes are nothing but few classes, which you create in your model project and then all EOs/VOs/AMs extend those classes. Your baseclasses extend framework provided classes for example EntityImpl, VOImpl, VORowImpl, AMImpl etc. If you don't have base classes, your EOs/VOs/AMs directly extend framework provided classes.

To create base classes you need do following steps
a. Create base classes: If we have only one model project, we can create base classes in that project itself. But if we want to reuse our base classes in multiple model project, we can create a new project for base classes and add it as a library in other model project. In this example I am using model project to create base classes.
To create base classes you just need to create normal java classes but you need to extend framework provided base classes. Although there are total 8 base classes you can create but we generally create 5 baseclasses. One for EOs, One for VOs, One for VORows, One for AMs. Let say I want to have following base classes

EOs: com.san.blog.model.baseclasses.MyEntityImpl  extends oracle.jbo.server.EntityImpl
VOs: com.san.blog.model.baseclasses.MyVOImpl      extends oracle.jbo.server.ViewObjectImpl
VORows: com.san.blog.model.baseclasses.MyVORowImpl  extends oracle.jbo.server.ViewRowImpl
AMs: com.san.blog.model.baseclasses.MyApplicationModuleImpl extends oracle.jbo.server.ApplicationModuleImpl

NOTE: To extend oracle.jbo.server classes you must have ADF Model Runtime library added in your model project.

After creating these classes your project will look something like

Code in these files will look something like

package com.san.blog.model.baseclasses;
import oracle.jbo.server.EntityImpl;
public class MyEntityImpl extends EntityImpl {
    public MyEntityImpl() {
        super();
    }
}

package com.san.blog.model.baseclasses;
import oracle.jbo.server.ViewDefImpl;
import oracle.jbo.server.ViewObjectImpl;
public class MyViewObjectImpl extends ViewObjectImpl {
    public MyViewObjectImpl(String string, ViewDefImpl viewDefImpl) {
        super(string, viewDefImpl);
    }
    public MyViewObjectImpl() {
        super();
    }
}

package com.san.blog.model.baseclasses;
import oracle.jbo.server.ViewRowImpl;
public class MyViewRowImpl extends ViewRowImpl {
    public MyViewRowImpl() {
        super();
    }
}

package com.san.blog.model.baseclasses;
import oracle.jbo.server.ApplicationModuleImpl;
public class MyApplicationModuleImpl extends ApplicationModuleImpl {
    public MyApplicationModuleImpl() {
        super();
    }
}

b. Change settings to recognize your custom classes as base classes: For this you need to navigate to Tools > Preferences > Business Components > Base Classes and change framework provided classes to your custom classes

Another place where you can change base classes is model project properties > Business Components > Base Classes. I think this approach is better as base class information resides in jpr file.

Now if you create any EO/VO/AM, they will be extending baseclasses you just created and your custom base-classes are extending framework provided base-classes so you will get all framework functionality. But you can change/add functionality in your base-classes and that will be applicable in all your ADF model objects.

NOTE: If you forget to mention base classes initially and want to implement it on already existing project you need to follow above steps and then make minor modification in each EOs/VOs/AMs so that system updates your EO/VO/AM files with correct base-classes. For example you can add transient attribute in EO/VO and then remove it.

2. Use Base-classes in EOs/VOs: Next thing we want to use these base classes. Let us create an employee form. In which we can have "update employee" functionality. We would like to create LOV for department, we would also like to have a validation for department in EmployeeEO. Let us have following objects:
EmployeeEO: Based on Employee table.
EmployeeVO: Updateable VO based on EmployeeEO.
DeptVVO: Validation VO to validate department
DeptLOVVO: VO to create department LOV
EmployeeAM: Application module

After creating these objects your project should look like

Add validation for department in DeptEO using DeptVVO. Also create an LOV for department in EmpVO using DeptLOVVO. Add EmpVO as a view instance in EmployeeAM. Once done your model is ready.

Now Create a page in ViewController project and drag and drop EmpVO from datacontrol. Select a form with Submit and Navigation button. Once done your flow is complete.

Our aim is when we navigate between pages, system should log each VO query that its firing and should report if any VO query is taking time. Here is the code that you can write in your base class MyViewObjectImpl.java to achieve this.

    public void executeQueryForCollection(Object rowset, Object[] params, int noUserParams) {   
            long startTime = 0L;
            long stopTime = 0L;
            long elapsedTime = 0L;
            if (_logger.isLoggable(Level.INFO)) {
                _logger.info("Executing VO: " + this.getFullName() + " Started.");
                startTime = System.currentTimeMillis();
            }
            
            super.executeQueryForCollection(rowset, params, noUserParams);             
            
            if (_logger.isLoggable(Level.INFO)) {
                stopTime = System.currentTimeMillis();
                elapsedTime = stopTime - startTime;
                if (elapsedTime > 100) {
                    _logger.info("********************SLOW QUERY HAS BEEN DETECTED ******************");
                    _logger.info("VO: " + this.getFullName());
                    _logger.info("Query: " + this.getQuery());
                    _logger.info("Total time taken: " + elapsedTime + "millisec");
    
                    if (params != null) {
                        _logger.info("Bind variables");
                        for (Object param : params) {
                            Object[] value = (Object[])param;
                            _logger.info("Name: " + value[0] + " Value: " +  value[1]);
                        }
                    }
    
    
                } 
                _logger.info("Executing VO: " + this.getFullName() + " Finished. Total time taken: " + elapsedTime);
            }
                   
        }

Now if I run my page and navigate between rows, change department and commit. I see various VOs are getting executed but all queries are getting logged continuously. 

On Page Load

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.EmpVO Started.

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.EmpVO Finished. Total time taken: 1

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM._LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO Started.

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM._LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO Finished. Total time taken: 1

On Next Click

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM._LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO Started.

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM._LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO Finished. Total time taken: 0

On changing department and commit

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.__LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO_findByVC_8fc_LOV_DepartmentId__lov__filterlist__vcr___ Started.

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.__LOCAL_VIEW_USAGE_com_san_blog_model_vo_EmpVO_DeptLOVVO_findByVC_8fc_LOV_DepartmentId__lov__filterlist__vcr___ Finished. Total time taken: 0

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.DeptVVO_66_findByKey_ Started.

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.DeptVVO_66_findByKey_ Finished. Total time taken: 1

If there is any slow query (more than 100 millisec), logger will write query with bind parameters as

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.EmpVO Started.

<MyViewObjectImpl> <executeQueryForCollection> ********************SLOW QUERY HAS BEEN DETECTED ******************

<MyViewObjectImpl> <executeQueryForCollection> VO: EmployeeAM.EmpVO

<MyViewObjectImpl> <executeQueryForCollection> Query: SELECT EmpEO.EMPLOYEE_ID,         EmpEO.FIRST_NAME,         EmpEO.LAST_NAME,         EmpEO.EMAIL,         EmpEO.PHONE_NUMBER,         EmpEO.HIRE_DATE,         EmpEO.JOB_ID,         EmpEO.SALARY,         EmpEO.COMMISSION_PCT,         EmpEO.MANAGER_ID,         EmpEO.DEPARTMENT_ID FROM EMP EmpEO

<MyViewObjectImpl> <executeQueryForCollection> Total time taken: 102millisec

<MyViewObjectImpl> <executeQueryForCollection> Executing VO: EmployeeAM.EmpVO Finished. Total time taken: 102

NOTE: Logger is enabled for info level only because we do not want logging everytime. It should only be enabled if some user reports slow performance and we want to check VO query performances. To see logs you need to enable INFO level of logging for MyViewObjectImpl file. To do that while running application in integrated weblogic, you can select 'Configure Oracle Diagnostic Logging' in jdev as shown below.

That's it: Now you have VO monitoring system, which keeps track of slow running queries.