ADF BC: Find out what is really happening in the database

Problem

While there are multiple ways (see previous blog) within ADF BC to see what is being generated and executed in the database, perhaps you are not satisfied with the information provided nor the overhead of the other loggings which are blocking your clear view on the matter.

Or perhaps you are missing information like how many times a query is executed, how long it took, how many fetches were used, ... 

Solution

Use the logging of the database to find the required information.  You can enable your sessions or even the entire database to activate logging that can be used to give you a clear overview on what is being asked from the database.

To activate this logging you need to perform the following actions:

1. Activate the logging in your session
   Execute the following statement : alter session set sql_trace=true
   You can execute this command in your application module impl class by overriding the afterConnect() method.  I'm also using this method to set some optimizer hints for my queries, like optimizer_index_cost_adj and optimizer_index_caching.
   Example:
• @Override
  protected void afterConnect() {
     super.afterConnect();
     executeCommand("alter session set sql_trace=true");
  }
2. Perform the necessary actions in your application for which you want to have the trace.
3. You can now stop the trace by executing the following statement: alter session set sql_trace=false
   or just perform action 4.
4. At this point the database will have generated a very detailed, not easy to read and understand trace file.  This file can be found under the user dump directory, which is defined by the database parameter user_dump_dest (show parameter user). 
5. Now we need to parse this file to a more readable file by executing the following statement:
   tkprof <sid>_ora_<pidid>.trc <result_file> sort=fchela
   Since it is very hard to know what process id you need, I just always took the last one :-)
   I added the sorting criteria to see the statements first with the biggest elapsed time.  Information on all parameters for tkprof can be found here.
   Example : tkprof orcl_ora_2463.trc test.txt sort=fchela 
6. Now you have a file that is readable, namely test.txt.  This file will give an overview of all statements being executed by your sessions and at the end an overview.  Let's have a look at output for 1 statement.
7. Only take the statements into account where the parsing user is not SYS.  The latter is used for database internal queries and do not adhere to the same tuning rules as your custom queries.

Here is an example output for a very simple query:

Let's have a look at the important bits of information:

• As 3th part of information you see the query like it has been asked at the db.  Here you see whether correct bind variables are used.  The only drawback of this technique is that this query is not linked directly to a certain view object.  It is up to you to determine which view object has generated this query.
• The count column of the Parse row, should be 1 or as low as possible.  This indicates how many times the db needed to parse this particular statement.  If you are not using bind variables, you will see that for each value a new statement overview is given and that the parse count will still be 1.
• The count column of the Execute row, should represent the number of times this query should be executed.  If you would have expected a lower number then the one appearing here, then BC has executed this query more often.  To solve this problem, you will need to look at the page definition files to determine when and how often the query is executed or even in your custom code when you asked to execute query on an iterator.
• Normally the cpu time of the execute row, should be very low.  If this is not the case, then it indicates that the query itself is very complex and has a lot of hierarchies of tables.  Or it could be because it is a DML-statement.
• Now comes the most important row, the Fetch-row.  The fetch count number indicates how many times the application has fetched rows for this query.  If the execute count is 1 and the fetch count is 10, this means that ADF BC has executed the query once, but needed to go 10 times to the db to get all data.  To resolve this problem, just change the 'in Batches of'-tuning parameter of your view object.  Look at the following blog for some tuning guides.

These were for me the most important pieces of information to be able to tune my ADF application.

Have Fun.

F