A Note on Dependencies and Database Unit Testing

Ideas on unit testing for the database are often heavily influenced by the world of object oriented programming (OOP), usually Java in practice. This is no doubt because much of modern thinking on development methodologies, including test driven development (TDD), originated in this world. Some of these ideas appear to translate very well into the database world, including that of TDD itself, with automated unit tests. However, some ideas may not translate so well, or even make sense, in database unit testing. For example, Roy Osherove (2011), Unit Test - Definition says:

A good unit test ... runs in memory (no DB or File access, for example)

One concept that appears very important in the OOP world is that of dependencies, and of isolation of the code under test from its dependencies. This gives rise to complex mechanisms of 'mocking' and 'dependency injection' to bring about said isolation. Osherove mentions isolation in the same article as a requirement of good unit testing, and his view appears to be widespread. It's worth mentioning though that not everyone in the OOP world shares his insistence. The influential Martin Fowler (2014) uses a nice terminology of 'sociable' tests (as opposed to 'isolated' tests) for tests that rely on other units to fulfill the behaviour under test, and he uses this approach himself when practicable, UnitTest.

In the case of database unit testing, it seems to me to make very little sense to think in terms of isolating code under test from its dependencies. The following two diagrams represent how I see the relationships between base code, dependencies and unit test code across two distinct phases.

Development Phase
UT Phases-dev

Regression Phase
UT Phases-reg

I would welcome any comments or opinions.






 

A Template Script for JDBC Calling of Oracle Procedures with Object Array Parameters

Some time ago I wrote an Oracle database package for a web service. The Java developer for the service told me that it was throwing an error when called from Java, although I had unit tested it from PL/SQL. He gave me a small Java driver script to demonstrate the issue, and this allowed the issue to be quickly identified: As both Java and PL/SQL have boolean data types I had considered that a boolean parameter would make sense to pass a boolean value. However, it turns out that this does not work in JDBC, and so I replaced it with an integer parameter.

It occurred to me then that it would be nice if the database developer was able in general to test JDBC compatibility of his or her procedure as a final step after unit testing. To this end I created a more generic example script based on a simple procedure that I wrote against Oracle's HR demo schema, the same procedure that I used as an example of a unit testing design pattern Design Patterns for Database Unit Testing 2: Web Service Saving - Code

Update, 4 November 2017: I have made a self-contained project on GitHub with both Java and Oracle code, avoiding dependency on my testing project. JDBC Calling of Oracle Procedures with Object Array Parameters on GitHub. I have also added the Oracle code below.

The code below runs against any Oracle instance in which the standard Oracle HR demo schema has been installed. There is a video demonstration of how to install and run it at the end of this article. The procedure has one input and one output object array parameter, and can easily be extended as desired. It requires one jar file in the classpath, ojdbc6.jar, which is available in Oracle client or database installations, and can be run from an IDE such as Eclipse.

Java Code

package jdbcdemo;
/***************************************************************************************************
Name:        Driver.java
Description: This is a Java driver script for Brendan's HR demo web service procedure. It is
             designed to serve as a template for other web service procedures to allow a database
             developer to do a JDBC integration test easily, and can also be used as a starting point
             for Java development.

             The template procedure takes an input array of objects and has an output array of 
             objects. It is easy to update for any named object and array types, procedure and
             Oracle connection. Any other signature types would need additional changes.

	     See 'A Template Script for JDBC Calling of Oracle Procedures with Object Array Parameters'
             
A Template Script for JDBC Calling of Oracle Procedures with Object Array Parameters
Modification History Who When Which What -------------------- ----------- ----- ------------------------------------------------------------- Brendan Furey 14-May-2016 1.0 Created Brendan Furey 04-Nov-2017 1.1 Put into new GitHub project along with Oracle code ***************************************************************************************************/ import java.sql.DriverManager; import java.sql.SQLException; import java.sql.Array; import java.sql.Struct; import oracle.jdbc.OracleTypes; import oracle.jdbc.OracleCallableStatement; import oracle.jdbc.OracleConnection; public class Driver { // Change section 1/2: Replace these constants with your own values private static final String DB_CONNECTION = "jdbc:oracle:thin:hr/hr@localhost:1521/orclpdb"; private static final String TY_IN_OBJ = "TY_EMP_IN_OBJ"; private static final String TY_IN_ARR = "TY_EMP_IN_ARR"; private static final String TY_OUT_ARR = "TY_EMP_OUT_ARR"; private static final String PROC_NAME = "Emp_WS.AIP_Save_Emps"; private static OracleConnection conn; public static void main(String[] argv) { try { getDBConnection (); prOutArray (callProc (inArray ())); } catch (SQLException e) { System.out.println(e.getMessage()); } } private static Array inArray () throws SQLException { // Change section 2/2: Replace [2] with number of test records, and the arrays with their values Struct[] struct = new Struct[2]; struct[0] = conn.createStruct (TY_IN_OBJ, new Object[] {"LN 1", "EM 1", "IT_PROG", 1000}); struct[1] = conn.createStruct (TY_IN_OBJ, new Object[] {"LN 2", "EM 2", "IT_PROG", 2000}); return conn.createARRAY (TY_IN_ARR, struct); } private static Array callProc (Array objArray) throws SQLException { OracleCallableStatement ocs = (OracleCallableStatement) conn.prepareCall ("BEGIN "+PROC_NAME+"(:1, :2); END;"); ocs.setArray (1, objArray); ocs.registerOutParameter (2, OracleTypes.ARRAY, TY_OUT_ARR); ocs.execute (); return ocs.getARRAY (2); } private static void prOutArray (Array arr) throws SQLException { Object[] objArr = (Object[]) arr.getArray(); int j = 0; for (Object rec : objArr) { Object[] objLis = ((Struct)rec).getAttributes (); int i = 0; String recStr = ""; for (Object fld : objLis) { if (i++ > 0) recStr = recStr + '/'; recStr = recStr + fld.toString(); } System.out.println ("Record "+(++j)+": "+recStr); } } private static void getDBConnection () throws SQLException { conn = (OracleConnection) DriverManager.getConnection (DB_CONNECTION); conn.setAutoCommit (false); System.out.println ("Connected..."); } }

Example output

Connected...
Record 1: 239/TWO HUNDRED THIRTY-NINE
Record 2: 240/TWO HUNDRED FORTY

Google Java Style

Oracle Code

/***************************************************************************************************

Author:      Brendan Furey
Description: Script to create objects to demo JDBC procedure calls with object array parameters

         See 'A Template Script for JDBC Calling of Oracle Procedures with Object Array Parameters'
             
A Template Script for JDBC Calling of Oracle Procedures with Object Array Parameters
Modification History Who When Which What -------------------- ----------- ----- ------------------------------------------------------------- Brendan Furey 04-May-2016 1.0 Created Brendan Furey 04-Nov-2017 1.1 Extracted the JDBC demo code from the unit testing project, and put into new GitHub project along with Java code ***************************************************************************************************/ REM Run this script from Oracle's standard HR schema to create objects to demo JDBC procedure calls COLUMN "Database" FORMAT A20 COLUMN "Time" FORMAT A20 COLUMN "Version" FORMAT A30 COLUMN "Session" FORMAT 9999990 COLUMN "OS User" FORMAT A10 COLUMN "Machine" FORMAT A20 SELECT 'Start: ' || dbs.name "Database", To_Char (SYSDATE,'DD-MON-YYYY HH24:MI:SS') "Time", Replace (Substr(ver.banner, 1, Instr(ver.banner, '64')-4), 'Enterprise Edition Release ', '') "Version" FROM v$database dbs, v$version ver WHERE ver.banner LIKE 'Oracle%'; PROMPT Input types creation DROP TYPE ty_emp_in_arr / CREATE OR REPLACE TYPE ty_emp_in_obj AS OBJECT ( last_name VARCHAR2(25), email VARCHAR2(25), job_id VARCHAR2(10), salary NUMBER ) / CREATE TYPE ty_emp_in_arr AS TABLE OF ty_emp_in_obj / PROMPT Output types creation DROP TYPE ty_emp_out_arr / CREATE OR REPLACE TYPE ty_emp_out_obj AS OBJECT ( employee_id NUMBER, description VARCHAR2(500) ) / CREATE TYPE ty_emp_out_arr AS TABLE OF ty_emp_out_obj / CREATE OR REPLACE PACKAGE Emp_WS AS /*************************************************************************************************** Description: HR demo web service code. Procedure saves new employees list and returns primary key plus same in words, or zero plus error message in output list ***************************************************************************************************/ PROCEDURE AIP_Save_Emps (p_ty_emp_in_lis ty_emp_in_arr, x_ty_emp_out_lis OUT ty_emp_out_arr); END Emp_WS; / CREATE OR REPLACE PACKAGE BODY Emp_WS AS PROCEDURE AIP_Save_Emps (p_ty_emp_in_lis ty_emp_in_arr, -- list of employees to insert x_ty_emp_out_lis OUT ty_emp_out_arr) IS -- list of employee results l_ty_emp_out_lis ty_emp_out_arr; bulk_errors EXCEPTION; PRAGMA EXCEPTION_INIT (bulk_errors, -24381); n_err PLS_INTEGER := 0; BEGIN FORALL i IN 1..p_ty_emp_in_lis.COUNT SAVE EXCEPTIONS INSERT INTO employees ( employee_id, last_name, email, hire_date, job_id, salary ) VALUES ( employees_seq.NEXTVAL, p_ty_emp_in_lis(i).last_name, p_ty_emp_in_lis(i).email, SYSDATE, p_ty_emp_in_lis(i).job_id, p_ty_emp_in_lis(i).salary ) RETURNING ty_emp_out_obj (employee_id, To_Char(To_Date(employee_id,'J'),'JSP')) BULK COLLECT INTO x_ty_emp_out_lis; EXCEPTION WHEN bulk_errors THEN l_ty_emp_out_lis := x_ty_emp_out_lis; FOR i IN 1 .. sql%BULK_EXCEPTIONS.COUNT LOOP IF i > x_ty_emp_out_lis.COUNT THEN x_ty_emp_out_lis.Extend; END IF; x_ty_emp_out_lis (SQL%Bulk_Exceptions (i).Error_Index) := ty_emp_out_obj (0, SQLERRM (- (SQL%Bulk_Exceptions (i).Error_Code))); END LOOP; FOR i IN 1..p_ty_emp_in_lis.COUNT LOOP IF i > x_ty_emp_out_lis.COUNT THEN x_ty_emp_out_lis.Extend; END IF; IF x_ty_emp_out_lis(i).employee_id = 0 THEN n_err := n_err + 1; ELSE x_ty_emp_out_lis(i) := l_ty_emp_out_lis(i - n_err); END IF; END LOOP; END AIP_Save_Emps; END Emp_WS; /

Here is a demo of installing and running the code, Oracle and Java:






 

Code Timing and Object Orientation and Zombies

This is a Word document that I wrote initially in November 2010 and uploaded to Scribd, Code Timing and Object Orientation and Zombies, with a big update in September 2012, about code timing in several languages.

I am going to upload a number of articles to this blog shortly that make use of an updated version of the Oracle code-timing package, and I am aware that many work networks disallow Scribd access, so I thought I would put it here first, Code Timing and Object Orientation and Zombies. It's also embedded below (if that is accessible).

Here is the introduction:

This article proposes an object-oriented design for simple CPU and elapsed timing of computer programs by individual code section or subroutine. The object data structure is first described using a diagram/tabulation approach first used in A Perl Object for Flattened Master-Detail Data in Excel, followed by a section describing method usage, and including a diagram showing a typical call structure.

The object class is then translated from the Ur-language of design into the programming languages of Oracle, Perl and Java (one might say that our class of class is instantiated into specific object classes for each language). In each case the code is listed, an example driving program is briefly described, the run results are listed, and any interesting features are highlighted.

Oracle's implementation of object-orientation is rather different from other languages, and a section of the article discusses how one can best obtain the advantages of object orientation in Oracle, suggesting that it's often better to bypass the 'official' object structures. Both approaches have been implemented here to help readers judge for themselves.

Finally, some notes are collated on differences between the languages.






 

SQL and Modularity: Patterns, Anti-Patterns and the Kitchen Sink

There's a lot of importance placed on code re-use in the database development world. In traditional procedural programming languages, such as C or Fortran, the value of modular programming and its application to promoting code re-use is well known and understood. When SQL enters the picture, however, the situation becomes less clear, and there is less consensus on how best to apply the traditional concept of modularity.

This article will consider the concept of modularity, and how it may best be applied to SQL, from the perspective of 'patterns' and 'anti-patterns'. Here is a definition of these terms from Wikipedia, Anti-pattern:

An anti-pattern (or antipattern) is a pattern used in social or business operations or software engineering that may be commonly used but is ineffective and/or counterproductive in practice.[1][2]

The term was coined in 1995 by Andrew Koenig,[3] inspired by Gang of Four's book Design Patterns, which developed the concept of design patterns in the software field. The term was widely popularized three years later by the book AntiPatterns, which extended the use of the term beyond the field of software design and into general social interaction. According to the authors of the latter, there must be at least two key elements present to formally distinguish an actual anti-pattern from a simple bad habit, bad practice, or bad idea:

  • Some repeated pattern of action, process or structure that initially appears to be beneficial, but ultimately produces more bad consequences than beneficial results, and
  • An alternative solution exists that is clearly documented, proven in actual practice and repeatable

 

Procedural Modularity

Modularity starts from the idea that a complex design can generally be broken down into a set of less complex component modules that is easier to work with. In programming terms, a long main program would be broken down into smaller subroutines, with a much shorter main program that calls the subroutines.

From this starting point emerges the possibility of code re-use, whereby the decomposition into modules aims at identifying common logic that can be placed in generic modules and called in multiple places. A simple example of this would be an error-logging module in PL/SQL that would write any Oracle errors to a table along with call stack information, that could be called wherever such errors need to be trapped. This might be termed an error-logging pattern, and it's clear that this kind of code re-use can lead to simpler and more maintainable systems.

SQL Modularity: Design Patterns

Transactional APIs

The concept of transactions is important for modular design within a database application.

The Oracle manual, Oracle Database Concepts, defines a transaction thus:
A transaction is a logical unit of work that contains one or more SQL statements. A transaction is an atomic unit. The effects of all the SQL statements in a transaction can be either all committed (applied to the database) or all rolled back (undone from the database).

When a transaction needs to be performed in more than one place, then the code can be placed in a PL/SQL module, sometimes called a 'transactional API'. This is really just the database-specific version of standard modularity, and is obviously a good design pattern to follow.

Data Access Layers

Transactional APIs are often used to form a Data Access Layer (DAL) for front end applications written in languages such as Java. Where the front end requires a record set from the database, the APIs may return a reference cursor, which is essentially a pointer to the data, and avoids the overhead of passing the whole data set at once. The data access layer pattern has a number of important advantages:

  • performance is enhanced through reduced network traffic between application server and database
  • SQL operates in an efficient set-based fashion for retrieving data in batches
  • the PL/SQL language, highly integrated with SQL, is specifically designed for database processing
  • storing the database processing code in database packages promotes modularity and code re-use

It is considered best practice to use data access layers even for clients, such as Oracle Forms, that have an embedded PL/SQL engine.

Of course, in order to achieve these benefits the data access layer has to be correctly written, avoiding the anti-pattern pitfalls discussed later. In particular, 'kitchen sink' style APIs that return far more data than required, to promote re-use, must be avoided; different client programs requiring different data should have separate APIs.

Views

Database views have been available in Oracle SQL from the earliest versions and can be used to avoid duplicating a complex SQL query that might be needed in multiple places.

This approach could be seens as a special case of transactional modularity, where a single query is the transaction, and might be regarded as a design pattern for re-use of SQL statements.

Views may form an alternative kind of data access layer, typically used by reporting tools such as Business Objects, and may also be used in conjumction with an API-based layer, which is a common approach in Oracle Forms applications.

Within-SQL Modularity

SQL is essentially a declarative, rather than procedural language for retrieving (and updating etc.) data from relational databases. The original idea was that the programmer specifies the tables and columns where the data are stored, as well as how the tables are related through key values, but does not specify algorithms for retrieving the data: The retrieval algorithms are performed by the SQL engine 'under the covers'. There might therefore seem to be little scope for modularity within a SQL select statement. However, this is not quite true for a couple of reasons: First, logical paths have to be specified between the tables, and the same path may need to be specified multiple times from different starting points; for example, the path to billing and shipping addresses on a sales order would typically involve the same sequence of steps from different id columns; second, as SQL has evolved, procedural capabilities have been added, such as analytic functions and recursion.

In Oracle in-line views were introduced in v7.2, and are in a sense a first step in modularising an SQL statement, followed in v9.2 by the 'WITH' clause for subquery factoring. Analytic functions were introduced in v8i.

Here is an example based on Oracle's HR demo schema. Suppose we want a list of employees with their current and previous jobs (if any), the same for their manager, and a count of the number of subordinates they have. To get the previous jobs, we need to find the latest records in the job_history table for the employee and his manager separately. This can be done using subqueries, but that is inefficient and it is normally better to join to aggregation views that use the DENSE_RANK clause to allow the required previous records to be obtained in a single pass each. Similarly, the subordinate count could be done by a scalar subquery, but again performance would usually dictate the use of another aggregation view.

Here is a query using in-line views to achieve this:

SELECT emp.last_name || ', ' || emp.first_name name,
       job.job_title,
       job_p.job_title             job_title_prior,
       emp_m.last_name || ', ' || emp_m.first_name name_mgr,
       job_m.job_title             job_title_mgr,
       job_pm.job_title            job_title_mgr_prior,
       sub.n_sub
  FROM hr.employees                emp
  JOIN hr.jobs                     job
    ON job.job_id                  = emp.job_id
  LEFT JOIN (SELECT employee_id,
                    Max (job_id) KEEP (DENSE_RANK LAST ORDER BY end_date) job_id
               FROM hr.job_history
              GROUP BY employee_id
            )                      jhs
    ON jhs.employee_id             = emp.employee_id
  LEFT JOIN hr.jobs                job_p
    ON job_p.job_id                = jhs.job_id
  LEFT JOIN hr.employees           emp_m
    ON emp_m.employee_id           = emp.manager_id
  LEFT JOIN hr.jobs                job_m
    ON job_m.job_id                = emp_m.job_id
  LEFT JOIN (SELECT employee_id,
                    Max (job_id) KEEP (DENSE_RANK LAST ORDER BY end_date) job_id
               FROM hr.job_history
              GROUP BY employee_id
            )                      jhs_m
    ON jhs_m.employee_id           = emp.manager_id
  LEFT JOIN hr.jobs                job_pm
    ON job_pm.job_id               = jhs_m.job_id
  LEFT JOIN (SELECT manager_id,
                    Count(*)       n_sub
               FROM hr.employees
              GROUP BY manager_id
            )                      sub
    ON sub.manager_id              = emp.employee_id
 WHERE emp.department_id           = 30
 ORDER BY 1

Here is a query using subquery factors to achieve the same:

WITH jhs_f AS (
SELECT employee_id,
       Max (job_id) KEEP (DENSE_RANK LAST ORDER BY end_date) job_id
  FROM hr.job_history
 GROUP BY employee_id
), sub_f AS (
SELECT manager_id,
       Count(*)                    n_sub
  FROM hr.employees
 GROUP BY manager_id
)
SELECT emp.last_name || ', ' || emp.first_name name,
       job.job_title,
       job_p.job_title             job_title_prior,
       emp_m.last_name || ', ' || emp_m.first_name name_mgr,
       job_m.job_title             job_title_mgr,
       job_pm.job_title            job_title_mgr_prior,
       sub.n_sub
  FROM hr.employees                emp
  JOIN hr.jobs                     job
    ON job.job_id                  = emp.job_id
  LEFT JOIN jhs_f                  jhs
    ON jhs.employee_id             = emp.employee_id
  LEFT JOIN hr.jobs                job_p
    ON job_p.job_id                = jhs.job_id
  LEFT JOIN hr.employees           emp_m
    ON emp_m.employee_id           = emp.manager_id
  LEFT JOIN hr.jobs                job_m
    ON job_m.job_id                = emp_m.job_id
  LEFT JOIN jhs_f                  jhs_m
    ON jhs_m.employee_id           = emp.employee_id
  LEFT JOIN hr.jobs                job_pm
    ON job_pm.job_id               = jhs_m.job_id
  LEFT JOIN sub_f                  sub
    ON sub.manager_id              = emp.employee_id
 WHERE emp.department_id           = 30
 ORDER BY 1

The second query, although only a line shorter, could be said to be more modular in two ways:

  1. The more complex processing is placed at the beginning, prior to the main select, which now contains only simple joins. This might be said to parallel the procedural modularity practice of having a simple main program calling subroutines, and may help maintainability
  2. A single subquery factor replaces the two inline views for previous jobs, a more modular design, and one that may be more efficient for larger data sets since Oracle generally materialises subquery factors referenced multiple times

This approach might be regarded as a design pattern for modularity within individual SQL statements.

ANSI Join Syntax

The queries above are written using ANSI join syntax, introduced in v9. Oracle SQL originally used its own proprietary syntax, as shown below for the same query requirement:

WITH jhs_f AS (
SELECT employee_id,
       Max (job_id) KEEP (DENSE_RANK LAST ORDER BY end_date) job_id
  FROM hr.job_history
 GROUP BY employee_id
), sub_f AS (
SELECT manager_id,
       Count(*)                    n_sub
  FROM hr.employees
 GROUP BY manager_id
)
SELECT emp.last_name || ', ' || emp.first_name name,
       job.job_title,
       job_p.job_title             job_title_prior,
       emp_m.last_name || ', ' || emp_m.first_name name_mgr,
       job_m.job_title             job_title_mgr,
       job_pm.job_title            job_title_mgr_prior,
       sub.n_sub
  FROM hr.employees                emp,
       hr.jobs                     job,
       jhs_f                       jhs,
       hr.jobs                     job_p,
       hr.employees                emp_m,
       hr.jobs                     job_m,
       jhs_f                       jhs_m,
       hr.jobs                     job_pm,
       sub_f                       sub
 WHERE emp.department_id           = 30
   AND job.job_id                  = emp.job_id
   AND jhs.employee_id (+)         = emp.employee_id
   AND job_p.job_id (+)            = jhs.job_id
   AND emp_m.employee_id (+)       = emp.manager_id
   AND job_m.job_id (+)            = emp_m.job_id
   AND jhs_m.employee_id (+)       = emp.employee_id
   AND job_pm.job_id (+)           = jhs_m.job_id
   AND sub.manager_id (+)          = emp.employee_id
 ORDER BY 1

The tables are listed together, join clauses are in a single block not separated from constraints, and outer joins are specified using a (+) token against every column in the 'left' table. The outer join syntax leads to widespread bugs when developers miss the (+) from one of the columns, which silently converts the join to an inner join.

Some of the advantages of the newer syntax are:

  • Greater functionality is available, including full outer joining
  • Outer joining is much harder to get wrong
  • The syntax follows an ANSI standard
  • Locating the join conditions with the table being joined appears to be more modular and readable

ANSI join syntax might therefore be considered a good design pattern to follow.

SQL Modularity: Design Anti-patterns

everything-but-the-kitchen-sink-IDIOM

Here is a thread from Tom Kyte's AskTom forum dealing with an SQL anti-pattern that is unfortunately common, and strongly opposed by Tom Kyte: Considering SQL as a Service. The idea behind the anti-pattern seems to be to avoid repeating even simple table joins in SQL by hiding them in a special type of data access layer designed to be called within individual SQL statements. This results in over-complex 'kitchen-sink' SQL within the layer itself and performance problems in the 'client' SQL. In addition, complex PL/SQL involving object types and arrays tends to be needed to glue it all together; the approach thus achieves the opposite of its intended purpose - simplification - in the manner of a classic anti-pattern.

We'll illustrate the anti-pattern by extending the HR example used above and working through an example. First we'll use the PL/SQL packaged procedure variant, then look at an older form based on views.

APIs as SQL Building Blocks Anti-pattern

Let's suppose that we start from the idea that we should centralise the SQL for employee information in a re-useable API. We could take the SQL above and add in department name, address and manager information to make it more general. We might think initially of making the API a function taking an employee id as input and returning a record. But what if we needed the information for a list of employees? It would be inefficient to call a function for every record in the list, which might lead us to think of making the function take a list as input and return a list of records. We might therefore define object and array types, and a function with the following signature:

FUNCTION Emp_Info_List (p_emp_id_list SYS.ODCINumberList) RETURN emp_info_list_type;

[All code and output referenced is attached to this article.]

Now let's consider a scenario in which we have to provide an API for a web front end following the design pattern of returning a reference cursor. The data required are the following details for all employees in a given department:

  • employee name
  • manager name
  • list of subordinates

The output for department 30 would be:

NAME                      NAME_MGR               NAME_SUB
------------------------- ---------------------- -------------------
Baida, Shelli             Raphaely, Den
Colmenares, Karen         Raphaely, Den
Himuro, Guy               Raphaely, Den
Khoo, Alexander           Raphaely, Den
Raphaely, Den             King, Steven           Baida, Shelli
Raphaely, Den             King, Steven           Colmenares, Karen
Raphaely, Den             King, Steven           Himuro, Guy
Raphaely, Den             King, Steven           Khoo, Alexander
Raphaely, Den             King, Steven           Tobias, Sigal
Tobias, Sigal             Raphaely, Den

10 rows selected.

Here is a possible procedure implementation:

PROCEDURE Get_Mgr_Subs_KS (p_dept_id PLS_INTEGER, x_mgr_sub_cur OUT SYS_REFCURSOR) IS
  l_emp_id_list SYS.ODCINumberList;
BEGIN

  SELECT employee_id
    BULK COLLECT INTO l_emp_id_list
    FROM hr.employees
   WHERE department_id = p_dept_id;

  OPEN x_mgr_sub_cur FOR
  SELECT t.name,
         t.name_mgr,
         e.last_name || ', ' || e.first_name
    FROM TABLE (KSink_Emp.Emp_Info_List (l_emp_id_list)) t
    LEFT JOIN hr.employees e
      ON e.manager_id = t.employee_id
   ORDER BY 1, 2, 3;

END Get_Mgr_Subs_KS;

The first step is to get the list of employees for the department, which we then pass into the API, wrapped in the TABLE key word, and join the employees table to get the subordinates. Three SQL select statements are executed. You might argue that I have over-complicated this by having the API take a list of employees rather than the department id, but remember that in this design anti-pattern the API can't be designed for one specific caller, and the list input is more general. It is intended to cater for all calls for employee information so in practice such compromises will happen frequently.

We can compare this to an alternative implementation in which we simply join the tables required:

PROCEDURE Get_Mgr_Subs_SQL (p_dept_id PLS_INTEGER, x_mgr_sub_cur OUT SYS_REFCURSOR) IS
BEGIN

  OPEN x_mgr_sub_cur FOR
  SELECT e.last_name || ', ' || e.first_name,
         m.last_name || ', ' || m.first_name,
         s.last_name || ', ' || s.first_name
    FROM hr.employees e
    LEFT JOIN hr.employees m
      ON m.employee_id = e.manager_id
    LEFT JOIN hr.employees s
      ON s.manager_id = e.employee_id
   WHERE e.department_id = p_dept_id
   ORDER BY 1, 2, 3;

END Get_Mgr_Subs_SQL;

This joins three tables in one statement while the earlier procedure effectively makes a join through PL/SQL using an array, which is arguably slightly more complicated. In any case the real problems become apparent when you compare the execution plans. I have written a test driver program that calls each of the APIs and loops over the returned cursor.

Taking the plan for the straight SQL implementation first:

-------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                   |      1 |        |     10 |00:00:00.01 |      14 |       |       |          |
|   1 |  SORT ORDER BY                         |                   |      1 |     35 |     10 |00:00:00.01 |      14 |  2048 |  2048 | 2048  (0)|
|   2 |   NESTED LOOPS OUTER                   |                   |      1 |     35 |     10 |00:00:00.01 |      14 |       |       |          |
|*  3 |    HASH JOIN OUTER                     |                   |      1 |      6 |      6 |00:00:00.01 |      10 |  1281K|  1281K|  544K (0)|
|   4 |     TABLE ACCESS BY INDEX ROWID BATCHED| EMPLOYEES         |      1 |      6 |      6 |00:00:00.01 |       2 |       |       |          |
|*  5 |      INDEX RANGE SCAN                  | EMP_DEPARTMENT_IX |      1 |      6 |      6 |00:00:00.01 |       1 |       |       |          |
|   6 |     VIEW                               | index$_join$_002  |      1 |    107 |    107 |00:00:00.01 |       8 |       |       |          |
|*  7 |      HASH JOIN                         |                   |      1 |        |    107 |00:00:00.01 |       8 |  1245K|  1245K| 1439K (0)|
|   8 |       INDEX FAST FULL SCAN             | EMP_NAME_IX       |      1 |    107 |    107 |00:00:00.01 |       4 |       |       |          |
|   9 |       INDEX FAST FULL SCAN             | EMP_EMP_ID_PK     |      1 |    107 |    107 |00:00:00.01 |       4 |       |       |          |
|  10 |    TABLE ACCESS BY INDEX ROWID BATCHED | EMPLOYEES         |      6 |      6 |      5 |00:00:00.01 |       4 |       |       |          |
|* 11 |     INDEX RANGE SCAN                   | EMP_MANAGER_IX    |      6 |      6 |      5 |00:00:00.01 |       3 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("M"."EMPLOYEE_ID"="E"."MANAGER_ID")
   5 - access("E"."DEPARTMENT_ID"=:B1)
   7 - access(ROWID=ROWID)
  11 - access("S"."MANAGER_ID"="E"."EMPLOYEE_ID")

This is a relatively simple plan for the single SQL statement, with 14 buffers read.

For the anti-pattern version there are thee SQL select statements, but we'll ignore the plan for initial bulk collect SQL and consider the other two execution plans. First, the client API SQL:

---------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name             | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                  |      1 |        |     10 |00:00:00.14 |    1195 |     41 |      1 |       |       |          |
|   1 |  SORT ORDER BY                      |                  |      1 |  48554 |     10 |00:00:00.14 |    1195 |     41 |      1 |  2048 |  2048 | 2048  (0)|
|*  2 |   HASH JOIN RIGHT OUTER             |                  |      1 |  48554 |     10 |00:00:00.14 |    1195 |     41 |      1 |  1368K|  1368K| 1322K (0)|
|   3 |    VIEW                             | index$_join$_002 |      1 |    107 |    106 |00:00:00.02 |       8 |     12 |      0 |       |       |          |
|*  4 |     HASH JOIN                       |                  |      1 |        |    106 |00:00:00.02 |       8 |     12 |      0 |  1519K|  1519K| 1575K (0)|
|   5 |      INDEX FAST FULL SCAN           | EMP_MANAGER_IX   |      1 |    107 |    106 |00:00:00.01 |       4 |      6 |      0 |       |       |          |
|   6 |      INDEX FAST FULL SCAN           | EMP_NAME_IX      |      1 |    107 |    107 |00:00:00.01 |       4 |      6 |      0 |       |       |          |
|   7 |    COLLECTION ITERATOR PICKLER FETCH| EMP_INFO_LIST    |      1 |   8168 |      6 |00:00:00.13 |    1187 |     29 |      1 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("E"."MANAGER_ID"=SYS_OP_ATG(VALUE(KOKBF$),1,2,2))
   4 - access(ROWID=ROWID)

Note the extreme inaccuracy of the cardinality estimates at steps 1 and 2, which originate in the step 7 estimate of 8168, which is a database-level default for an array function call. This is exposing the general problem that joining to arrays prevents accurate cardinality estimates. A total of 1195 buffers were read.

Next, the plan for the inner API SQL:

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                       | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                |                           |      1 |        |      6 |00:00:00.01 |      94 |      1 |      1 |       |       |          |
|   1 |  TEMP TABLE TRANSFORMATION                      |                           |      1 |        |      6 |00:00:00.01 |      94 |      1 |      1 |       |       |          |
|   2 |   LOAD AS SELECT                                |                           |      1 |        |      0 |00:00:00.01 |       6 |      0 |      1 |  1036K|  1036K|          |
|   3 |    SORT GROUP BY NOSORT                         |                           |      1 |      7 |      7 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|   4 |     TABLE ACCESS BY INDEX ROWID                 | JOB_HISTORY               |      1 |     10 |     10 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|   5 |      INDEX FULL SCAN                            | JHIST_EMP_ID_ST_DATE_PK   |      1 |     10 |     10 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|*  6 |   HASH JOIN OUTER                               |                           |      1 |      6 |      6 |00:00:00.01 |      85 |      1 |      0 |   735K|   735K|  506K (0)|
|*  7 |    HASH JOIN OUTER                              |                           |      1 |      6 |      6 |00:00:00.01 |      78 |      1 |      0 |   736K|   736K|  891K (0)|
|*  8 |     HASH JOIN OUTER                             |                           |      1 |      6 |      6 |00:00:00.01 |      75 |      1 |      0 |   737K|   737K|  550K (0)|
|*  9 |      HASH JOIN OUTER                            |                           |      1 |      6 |      6 |00:00:00.01 |      68 |      1 |      0 |   739K|   739K|  883K (0)|
|* 10 |       HASH JOIN OUTER                           |                           |      1 |      6 |      6 |00:00:00.01 |      62 |      0 |      0 |   740K|   740K|  903K (0)|
|* 11 |        HASH JOIN OUTER                          |                           |      1 |      6 |      6 |00:00:00.01 |      55 |      0 |      0 |   746K|   746K|  541K (0)|
|* 12 |         HASH JOIN OUTER                         |                           |      1 |      6 |      6 |00:00:00.01 |      48 |      0 |      0 |   754K|   754K|  534K (0)|
|* 13 |          HASH JOIN OUTER                        |                           |      1 |      6 |      6 |00:00:00.01 |      41 |      0 |      0 |   766K|   766K|  418K (0)|
|* 14 |           HASH JOIN OUTER                       |                           |      1 |      6 |      6 |00:00:00.01 |      33 |      0 |      0 |   773K|   773K|  414K (0)|
|  15 |            NESTED LOOPS OUTER                   |                           |      1 |      6 |      6 |00:00:00.01 |      26 |      0 |      0 |       |       |          |
|* 16 |             HASH JOIN OUTER                     |                           |      1 |      6 |      6 |00:00:00.01 |      23 |      0 |      0 |   833K|   833K|  414K (0)|
|* 17 |              HASH JOIN OUTER                    |                           |      1 |      6 |      6 |00:00:00.01 |      16 |      0 |      0 |   876K|   876K|  415K (0)|
|* 18 |               HASH JOIN                         |                           |      1 |      6 |      6 |00:00:00.01 |       9 |      0 |      0 |   905K|   905K| 1259K (0)|
|  19 |                MERGE JOIN                       |                           |      1 |    107 |    107 |00:00:00.01 |       9 |      0 |      0 |       |       |          |
|  20 |                 TABLE ACCESS BY INDEX ROWID     | JOBS                      |      1 |     19 |     19 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|  21 |                  INDEX FULL SCAN                | JOB_ID_PK                 |      1 |     19 |     19 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|* 22 |                 SORT JOIN                       |                           |     19 |    107 |    107 |00:00:00.01 |       7 |      0 |      0 | 18432 | 18432 |16384  (0)|
|  23 |                  TABLE ACCESS FULL              | EMPLOYEES                 |      1 |    107 |    107 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  24 |                COLLECTION ITERATOR PICKLER FETCH|                           |      1 |      6 |      6 |00:00:00.01 |       0 |      0 |      0 |       |       |          |
|  25 |               TABLE ACCESS FULL                 | DEPARTMENTS               |      1 |     27 |     27 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  26 |              TABLE ACCESS FULL                  | LOCATIONS                 |      1 |     23 |     23 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|* 27 |             INDEX UNIQUE SCAN                   | COUNTRY_C_ID_PK           |      6 |      1 |      6 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  28 |            TABLE ACCESS FULL                    | REGIONS                   |      1 |      4 |      4 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  29 |           VIEW                                  | index$_join$_024          |      1 |    107 |    107 |00:00:00.01 |       8 |      0 |      0 |       |       |          |
|* 30 |            HASH JOIN                            |                           |      1 |        |    107 |00:00:00.01 |       8 |      0 |      0 |  1245K|  1245K| 1550K (0)|
|  31 |             INDEX FAST FULL SCAN                | EMP_NAME_IX               |      1 |    107 |    107 |00:00:00.01 |       4 |      0 |      0 |       |       |          |
|  32 |             INDEX FAST FULL SCAN                | EMP_EMP_ID_PK             |      1 |    107 |    107 |00:00:00.01 |       4 |      0 |      0 |       |       |          |
|  33 |          TABLE ACCESS FULL                      | EMPLOYEES                 |      1 |    107 |    107 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  34 |         TABLE ACCESS FULL                       | JOBS                      |      1 |     19 |     19 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  35 |        VIEW                                     |                           |      1 |     18 |     19 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  36 |         HASH GROUP BY                           |                           |      1 |     18 |     19 |00:00:00.01 |       7 |      0 |      0 |  1558K|  1558K| 1185K (0)|
|  37 |          TABLE ACCESS FULL                      | EMPLOYEES                 |      1 |    107 |    107 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  38 |       VIEW                                      |                           |      1 |      7 |      7 |00:00:00.01 |       6 |      1 |      0 |       |       |          |
|  39 |        TABLE ACCESS FULL                        | SYS_TEMP_0FD9D6604_5813E5 |      1 |      7 |      7 |00:00:00.01 |       6 |      1 |      0 |       |       |          |
|  40 |      TABLE ACCESS FULL                          | JOBS                      |      1 |     19 |     19 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  41 |     VIEW                                        |                           |      1 |      7 |      7 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  42 |      TABLE ACCESS FULL                          | SYS_TEMP_0FD9D6604_5813E5 |      1 |      7 |      7 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  43 |    TABLE ACCESS FULL                            | JOBS                      |      1 |     19 |     19 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   6 - access("JOB_P"."JOB_ID"="JHS"."JOB_ID")
   7 - access("JHS"."EMPLOYEE_ID"="EMP"."EMPLOYEE_ID")
   8 - access("JOB_MP"."JOB_ID"="JHS_M"."JOB_ID")
   9 - access("JHS_M"."EMPLOYEE_ID"="EMP"."EMPLOYEE_ID")
  10 - access("SUB"."MANAGER_ID"="EMP"."EMPLOYEE_ID")
  11 - access("JOB_M"."JOB_ID"="EMP_M"."JOB_ID")
  12 - access("EMP_M"."EMPLOYEE_ID"="EMP"."MANAGER_ID")
  13 - access("EMP_DM"."EMPLOYEE_ID"="DEP"."MANAGER_ID")
  14 - access("REG"."REGION_ID"="COU"."REGION_ID")
  16 - access("LOC"."LOCATION_ID"="DEP"."LOCATION_ID")
  17 - access("DEP"."DEPARTMENT_ID"="EMP"."DEPARTMENT_ID")
  18 - access("EMP"."EMPLOYEE_ID"=VALUE(KOKBF$))
  22 - access("JOB"."JOB_ID"="EMP"."JOB_ID")
       filter("JOB"."JOB_ID"="EMP"."JOB_ID")
  27 - access("COU"."COUNTRY_ID"="LOC"."COUNTRY_ID")
  30 - access(ROWID=ROWID)

This is pretty complex. We can't pretend to do a real performance analysis on such a small database (107 employees), but the potential for performance problems in real cases is clear. It's important to understand that any performance analysis on the client API has to take into account not just the client code, but the full complexity of the centralised SQL, so any apparent simplification from using it is to a great extent illusory.

Database Inter-Schema Data Access Layer Anti-pattern

There is a variant of the anti-pattern above in which data access layers are used to retrieve data across schema boundaries. This variant suffers from exactly the same problems as the first of course, and should equally be avoided.

Views as SQL Building Blocks Anti-Pattern

The same ideas as are behind the APIs as SQL Building Blocks Anti-Pattern can also be implemented through views, and in fact this variant form of the anti-pattern has been around longer I think. We can illustrate it on the same example, by creating a view instead of the central API cursor.

CREATE OR REPLACE VIEW emp_ks_v (
       employee_id,
       name,
       job_title,
       job_title_p,
       name_mgr,
       job_title_mgr,
       job_title_mgr_p,
       n_sub,
       department_id,
       department_name,
       name_d_mgr,
       street_address,
       country_name,
       region_name) AS
WITH jhs_f AS (
SELECT employee_id,
     Max (job_id) KEEP (DENSE_RANK LAST ORDER BY end_date) job_id
  FROM hr.job_history
 GROUP BY employee_id
), sub AS (
SELECT manager_id,
       Count(*)                  n_sub
  FROM hr.employees
 GROUP BY manager_id
)
SELECT emp.employee_id,
       emp.last_name || ', ' || emp.first_name,
       job.job_title,
       job_p.job_title,
       emp_m.last_name || ', ' || emp_m.first_name,
       job_m.job_title,
       job_mp.job_title,
       sub.n_sub,
       dep.department_id,
       dep.department_name,
       emp_dm.last_name || ', ' || emp_dm.first_name,
       loc.street_address,
       cou.country_name,
       reg.region_name
  FROM hr.employees              emp
  JOIN hr.jobs                   job
    ON job.job_id                = emp.job_id
  LEFT JOIN jhs_f                jhs
    ON jhs.employee_id           = emp.employee_id
  LEFT JOIN hr.jobs              job_p
    ON job_p.job_id              = jhs.job_id
  LEFT JOIN hr.employees         emp_m
    ON emp_m.employee_id         = emp.manager_id
  LEFT JOIN hr.jobs              job_m
    ON job_m.job_id              = emp_m.job_id
  LEFT JOIN jhs_f                jhs_m
    ON jhs_m.employee_id         = emp.employee_id
  LEFT JOIN hr.jobs              job_mp
    ON job_mp.job_id             = jhs_m.job_id
  LEFT JOIN sub
    ON sub.manager_id            = emp.employee_id
  LEFT JOIN hr.departments       dep
    ON dep.department_id         = emp.department_id
  LEFT JOIN hr.employees         emp_dm
    ON emp_dm.employee_id        = dep.manager_id
  LEFT JOIN hr.locations         loc
    ON loc.location_id           = dep.location_id
  LEFT JOIN hr.countries         cou
    ON cou.country_id            = loc.country_id
  LEFT JOIN hr.regions           reg
    ON reg.region_id             = cou.region_id

The view can then be called to get the employee details for example for a given department, thus:

SELECT t.name,
       t.name_mgr,
       CASE WHEN e.last_name IS NOT NULL THEN e.last_name || ', ' || e.first_name END name_sub
  FROM emp_ks_v t
  LEFT JOIN hr.employees e
    ON e.manager_id = t.employee_id
 WHERE t.department_id = 30
 ORDER BY 1, 2, 3

This is actually quite a lot better than the API-based approach as it's much simpler, avoiding the need for object arrays, and allowing use simply by joining. Let's look at the execution plan though (we'll just run the query rather than put it into a client API returning a reference cursor):

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                    | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                             |                           |      1 |        |     10 |00:00:00.01 |      42 |      1 |      1 |       |       |          |
|   1 |  SORT ORDER BY                               |                           |      1 |     35 |     10 |00:00:00.01 |      42 |      1 |      1 |  2048 |  2048 | 2048  (0)|
|   2 |   NESTED LOOPS OUTER                         |                           |      1 |     35 |     10 |00:00:00.01 |      42 |      1 |      1 |       |       |          |
|   3 |    VIEW                                      | EMP_KS_V                  |      1 |      6 |      6 |00:00:00.01 |      38 |      1 |      1 |       |       |          |
|   4 |     TEMP TABLE TRANSFORMATION                |                           |      1 |        |      6 |00:00:00.01 |      38 |      1 |      1 |       |       |          |
|   5 |      LOAD AS SELECT                          |                           |      1 |        |      0 |00:00:00.01 |       6 |      0 |      1 |  1036K|  1036K|          |
|   6 |       SORT GROUP BY NOSORT                   |                           |      1 |      7 |      7 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|   7 |        TABLE ACCESS BY INDEX ROWID           | JOB_HISTORY               |      1 |     10 |     10 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|   8 |         INDEX FULL SCAN                      | JHIST_EMP_ID_ST_DATE_PK   |      1 |     10 |     10 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|*  9 |      HASH JOIN OUTER                         |                           |      1 |      6 |      6 |00:00:00.01 |      29 |      1 |      0 |   883K|   883K|  517K (0)|
|* 10 |       HASH JOIN OUTER                        |                           |      1 |      6 |      6 |00:00:00.01 |      21 |      1 |      0 |   890K|   890K|  857K (0)|
|* 11 |        HASH JOIN OUTER                       |                           |      1 |      6 |      6 |00:00:00.01 |      14 |      1 |      0 |   895K|   895K|  886K (0)|
|* 12 |         HASH JOIN OUTER                      |                           |      1 |      6 |      6 |00:00:00.01 |      11 |      1 |      0 |   905K|   905K|  893K (0)|
|  13 |          NESTED LOOPS                        |                           |      1 |      6 |      6 |00:00:00.01 |       5 |      0 |      0 |       |       |          |
|  14 |           NESTED LOOPS OUTER                 |                           |      1 |      1 |      1 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  15 |            TABLE ACCESS BY INDEX ROWID       | DEPARTMENTS               |      1 |      1 |      1 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|* 16 |             INDEX UNIQUE SCAN                | DEPT_ID_PK                |      1 |      1 |      1 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|* 17 |            INDEX UNIQUE SCAN                 | LOC_ID_PK                 |      1 |      1 |      1 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|  18 |           TABLE ACCESS BY INDEX ROWID BATCHED| EMPLOYEES                 |      1 |      6 |      6 |00:00:00.01 |       2 |      0 |      0 |       |       |          |
|* 19 |            INDEX RANGE SCAN                  | EMP_DEPARTMENT_IX         |      1 |      6 |      6 |00:00:00.01 |       1 |      0 |      0 |       |       |          |
|  20 |          VIEW                                |                           |      1 |      7 |      7 |00:00:00.01 |       6 |      1 |      0 |       |       |          |
|  21 |           TABLE ACCESS FULL                  | SYS_TEMP_0FD9D6606_5813E5 |      1 |      7 |      7 |00:00:00.01 |       6 |      1 |      0 |       |       |          |
|  22 |         VIEW                                 |                           |      1 |      7 |      7 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  23 |          TABLE ACCESS FULL                   | SYS_TEMP_0FD9D6606_5813E5 |      1 |      7 |      7 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
|  24 |        VIEW                                  |                           |      1 |     18 |     19 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  25 |         HASH GROUP BY                        |                           |      1 |     18 |     19 |00:00:00.01 |       7 |      0 |      0 |  1558K|  1558K| 1211K (0)|
|  26 |          TABLE ACCESS FULL                   | EMPLOYEES                 |      1 |    107 |    107 |00:00:00.01 |       7 |      0 |      0 |       |       |          |
|  27 |       VIEW                                   | index$_join$_013          |      1 |    107 |    107 |00:00:00.01 |       8 |      0 |      0 |       |       |          |
|* 28 |        HASH JOIN                             |                           |      1 |        |    107 |00:00:00.01 |       8 |      0 |      0 |  1245K|  1245K| 1410K (0)|
|  29 |         INDEX FAST FULL SCAN                 | EMP_NAME_IX               |      1 |    107 |    107 |00:00:00.01 |       4 |      0 |      0 |       |       |          |
|  30 |         INDEX FAST FULL SCAN                 | EMP_EMP_ID_PK             |      1 |    107 |    107 |00:00:00.01 |       4 |      0 |      0 |       |       |          |
|  31 |    TABLE ACCESS BY INDEX ROWID BATCHED       | EMPLOYEES                 |      6 |      6 |      5 |00:00:00.01 |       4 |      0 |      0 |       |       |          |
|* 32 |     INDEX RANGE SCAN                         | EMP_MANAGER_IX            |      6 |      6 |      5 |00:00:00.01 |       3 |      0 |      0 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   9 - access("EMP_M"."EMPLOYEE_ID"="EMP"."MANAGER_ID")
  10 - access("SUB"."MANAGER_ID"="EMP"."EMPLOYEE_ID")
  11 - access("JHS_M"."EMPLOYEE_ID"="EMP"."EMPLOYEE_ID")
  12 - access("JHS"."EMPLOYEE_ID"="EMP"."EMPLOYEE_ID")
  16 - access("DEP"."DEPARTMENT_ID"=30)
  17 - access("LOC"."LOCATION_ID"="DEP"."LOCATION_ID")
  19 - access("EMP"."DEPARTMENT_ID"=30)
  28 - access(ROWID=ROWID)
  32 - access("E"."MANAGER_ID"="T"."EMPLOYEE_ID")

There is only one SQL statement, and the plan is better too, with better cardinality estimates owing to the absence of array processing, and with 42 buffers read. It's still a bad idea though because the client caller would be executing far more complex SQL than is required and as before performance analysis on the client requires the full complexity of the 'centralised' SQL to be included. Using complex views as SQL building blocks is generally considered to have poor performance characteristics.

SQL Modularity: Other Design Options

Splitting Up Long SQL Statements

Oracle's Cost Based Optimiser (CBO) has been greatly enhanced since it's introduction in v7, but remains imperfect. The combinatorial nature of the problem that it tries to solve suggests that there will always be larger queries where it makes a bad choice of plan. In some cases splitting a large query into smaller ones and using temporary tables to join them can give better performance. This may arise from new indexing options for the CBO, or by dynamic sampling capabilities on the temporary tables, or just from the CBO algorithms happening to work better on the divided queries.

It's important to understand though that any such splitting should be done purely on performance grounds: the splitting increases the code complexity and breaking a sequence of declarative joins into several subsequences is not comparable with standard modularisation of programs into subprograms.

Long SQL statements are not necessarily problematic, but obviously should only be as long as necessary, and avoiding the design anti-patterns mentioned helps to ensure this.

Simple Views

Simple views, without joins, are often used in areas such as access control; for example Oracle Applications multi-org features (upto release 11) generally involve transactional tables being referenced by such simple views. These do not cause the performance problems seen with the complex building-block views anti-pattern.

Data Access Layers for Back-end Programs

It is quite possible to use a similar approach for database programs as for front-end programs in terms of a data access layer. One could adopt a standard that stand-alone database PL/SQL programs should access data through packaged APIs rather than directly. This obviously does not have the performance or language advantages of the design pattern in relation to Java front-ends for example, but it may in some circumstances be a preferred method of code organisation. It is therefore not an anti-pattern of the kind we have considered - as long as it is for stand-alone programs only.

Conclusions

The main aim of this article has been to distinguish between good approaches to modularity in SQL (patterns) and bad ones (anti-patterns) based on personal experience of seeing both types applied.

  • The Data Access Layer design pattern is an excellent approach for client applications developed in Java, .net etc. to access a database
  • Using Data Access Layers for internal access within a database is a classic anti-pattern leading to overcomplication and performance problems
  • A good design pattern used in an inappropriate context can become an anti-pattern

SQL Modularity Code






 

Design Patterns for Extracting Relational Data from XML

I recently replicated a very complicated Informatica data load from XML files into two Oracle staging tables in a much simpler way using just three SQL insert statements. I was able to load over 13,000 XML files into the tables in around 3 minutes on a windows PC running Oracle 11.2 XE, populating about 2 million records. This article will focus on the general design patterns involved in selecting relational data from XML using SQL in Oracle 11.2.

XML Selection Scenarios

The hierarchical structure of XML files means that the data may be stored at various different levels, but a relational SELECT statement returns data in a flat format. One way of converting between hierarchical and flat formats is to have separate SELECT statements for each level of data, and have any additional post-processing performed after inserting into staging tables. However, it is also possible to flatten the hierarchy within a single SELECT query clause in the case of a strict linear hierarchy.

It is instructive to consider the general case where any number of entities can occur within a linear hierarchy. If we understand how to deal with the case of two entities in a master-detail relationship, along with global values, then we will know how to deal with the general case, and so I will construct just such a test example.

XML Test Data

Here is the test XML file

<elem-0-body>
    <elem-1-global attr-1-global="id_1_global">
        <field-1-global>val_global</field-1-global>
    </elem-1-global>
    <list-1-master>
        <elem-1-master>
            <field-1-master>val_master_m1</field-1-master>
            <list-2-detail>
                  <elem-2-detail>
                       <field-2-detail>val_detail_m1_d1</field-2-detail>
                  </elem-2-detail>
                  <elem-2-detail>
                       <field-2-detail>val_detail_m1_d2</field-2-detail>
                  </elem-2-detail>
            </list-2-detail>
        </elem-1-master>
        <elem-1-master>
            <field-1-master>val_master_m2</field-1-master>
            <list-2-detail>
                  <elem-2-detail>
                       <field-2-detail>val_detail_m2_d1</field-2-detail>
                  </elem-2-detail>
                  <elem-2-detail>
                       <field-2-detail>val_detail_m2_d2</field-2-detail>
                  </elem-2-detail>
            </list-2-detail>
        </elem-1-master>
        <elem-1-master>
            <field-1-master>val_master_m3</field-1-master>
        </elem-1-master>
    </list-1-master>
</elem-0-body>

The file represents data in a master-detail relationship, plus data that are global to the file. As can be seen, there is a global entity, elem-1-global, that occurs exactly once, a master entity, elem-1-master, that may occur multiple times and that contains a child entity, elem-2-detail, that may occur multiple times. Each entity has been assigned a single sample field. One entity has an XML attribute.

There are three master records, having two, two and zero detail records respectively. We will filter out one of the second master's detail records.

In an article from January 2012, Data Modelling of XML SOAP Documents, I introduced my own diagram notation for hierarchical data structures, and re-use it below, showing the links to entities in relational form. I have added rounded corners to distinguish attributes from fields.

XMLSQL

SQL
Reading the XML File

CREATE TABLE xml_design_pattern (
       xml_field   XMLTYPE) 
       XMLTYPE COLUMN xml_field STORE AS BINARY XML
/
INSERT INTO xml_design_pattern VALUES (
       XMLTYPE (BFilename ('BRENDAN_IN_DIR', 'DESIGN_PATTERN.xml'),                      
                           NLS_Charset_id ('AL32UTF8'))
)
/

Unfiltered, Outer Join on Detail

SELECT /*+ GATHER_PLAN_STATISTICS XMLOJA */ 
       x1.global_id, x1.global_val, x2.master, x3.detail
  FROM xml_design_pattern t,
     XMLTable ('/elem-0-body'
                   PASSING t.xml_field
                   COLUMNS global_id           VARCHAR2(100) PATH 'elem-1-global/@attr-1-global',
                           global_val          VARCHAR2(100) PATH 'elem-1-global/field-1-global',
                           l2_xml              XMLTYPE       PATH 'list-1-master') x1,
     XMLTable ('/list-1-master/elem-1-master'
                   PASSING x1.l2_xml
                   COLUMNS master              VARCHAR2(100) PATH 'field-1-master',
                           l3_xml              XMLTYPE       PATH 'list-2-detail') x2,
     XMLTable ('/list-2-detail/elem-2-detail'
                   PASSING x2.l3_xml
                   COLUMNS detail              VARCHAR2(100) PATH 'field-2-detail') (+) x3
ORDER BY 1, 2, 3, 4

Output

GLOBAL_ID       GLOBAL_VAL      MASTER          DETAIL
--------------- --------------- --------------- --------------------
id_1_global     val_global      val_master_m1
id_1_global     val_global      val_master_m2
id_1_global     val_global      val_master_m3

The result shows that none of the detail records have been joined, while the expected result would be that all detail records would be joined with null detail only for m3.

Filtered, Outer Join on Detail

SELECT x1.global_id, x1.global_val, x2.master, x3.detail
  FROM xml_design_pattern t,
     XMLTable ('/elem-0-body'
                   PASSING t.xml_field
                   COLUMNS global_id           VARCHAR2(100) PATH 'elem-1-global/@attr-1-global',
                           global_val          VARCHAR2(100) PATH 'elem-1-global/field-1-global',
                           l2_xml              XMLTYPE       PATH 'list-1-master') x1,
     XMLTable ('/list-1-master/elem-1-master'
                   PASSING x1.l2_xml
                   COLUMNS master              VARCHAR2(100) PATH 'field-1-master',
                           l3_xml              XMLTYPE       PATH 'list-2-detail') x2,
     XMLTable ('/list-2-detail/elem-2-detail[field-2-detail != "val_detail_m2_d1"]'
                   PASSING x2.l3_xml
                   COLUMNS detail              VARCHAR2(100) PATH 'field-2-detail') (+) x3
ORDER BY 1, 2, 3, 4

Output

no rows selected

The result shows that no records have been returned, while the expected result would be that all master records would be returned, with detail records joined for all except the filtered out detail, with null detail only for m3.

Unfiltered, Outer Joins on all
SQL

SELECT x1.global_id, x1.global_val, x2.master, x3.detail
  FROM xml_design_pattern t,
     XMLTable ('/elem-0-body'
                   PASSING t.xml_field
                   COLUMNS global_id           VARCHAR2(100) PATH 'elem-1-global/@attr-1-global',
                           global_val          VARCHAR2(100) PATH 'elem-1-global/field-1-global',
                           l2_xml              XMLTYPE       PATH 'list-1-master') (+) x1,
    XMLTable ('/list-1-master/elem-1-master'
                   PASSING x1.l2_xml
                   COLUMNS master              VARCHAR2(100) PATH 'field-1-master',
                           l3_xml              XMLTYPE       PATH 'list-2-detail') (+) x2,
     XMLTable ('/list-2-detail/elem-2-detail'
                   PASSING x2.l3_xml
                   COLUMNS detail              VARCHAR2(100) PATH 'field-2-detail') (+) x3
ORDER BY 1, 2, 3, 4

Output

GLOBAL_ID       GLOBAL_VAL      MASTER          DETAIL
--------------- --------------- --------------- --------------------
id_1_global     val_global      val_master_m1   val_detail_m1_d1
id_1_global     val_global      val_master_m1   val_detail_m1_d2
id_1_global     val_global      val_master_m2   val_detail_m2_d1
id_1_global     val_global      val_master_m2   val_detail_m2_d2
id_1_global     val_global      val_master_m3

The result shows that all records are returned, as expected.

Unfiltered, Inner Joins
The attached file shows that, without the outer joins, records are returned only for the first two master records that have detail records, as expected.

Filtered, Outer Joins on all

SQL

SELECT x1.global_id, x1.global_val, x2.master, x3.detail
  FROM xml_design_pattern t,
     XMLTable ('/elem-0-body'
                   PASSING t.xml_field
                   COLUMNS global_id           VARCHAR2(100) PATH 'elem-1-global/@attr-1-global',
                           global_val          VARCHAR2(100) PATH 'elem-1-global/field-1-global',
                           l2_xml              XMLTYPE       PATH 'list-1-master') (+) x1,
     XMLTable ('/list-1-master/elem-1-master'
                   PASSING x1.l2_xml
                   COLUMNS master              VARCHAR2(100) PATH 'field-1-master',
                           l3_xml              XMLTYPE       PATH 'list-2-detail') (+) x2,
     XMLTable ('/list-2-detail/elem-2-detail[field-2-detail != "val_detail_m2_d1"]'
                   PASSING x2.l3_xml
                   COLUMNS detail              VARCHAR2(100) PATH 'field-2-detail') (+) x3
ORDER BY 1, 2, 3, 4

Output

GLOBAL_ID       GLOBAL_VAL      MASTER          DETAIL
--------------- --------------- --------------- --------------------
id_1_global     val_global      val_master_m1   val_detail_m1_d1
id_1_global     val_global      val_master_m1   val_detail_m1_d2
id_1_global     val_global      val_master_m2   val_detail_m2_d2
id_1_global     val_global      val_master_m3

The result shows that, with all joins outer joins, all records are returned except for the filtered-out detail record, as expected.

Filtered, Ansi Outer Joins on all

SQL

SELECT x1.global_id, x1.global_val, x2.master, x3.detail
  FROM xml_design_pattern t
    LEFT JOIN
     XMLTable ('/elem-0-body'
                   PASSING t.xml_field
                   COLUMNS global_id           VARCHAR2(100) PATH 'elem-1-global/@attr-1-global',
                           global_val          VARCHAR2(100) PATH 'elem-1-global/field-1-global',
                           l2_xml              XMLTYPE       PATH 'list-1-master') x1 ON 1=1
    LEFT JOIN
     XMLTable ('/list-1-master/elem-1-master'
                   PASSING x1.l2_xml
                   COLUMNS master              VARCHAR2(100) PATH 'field-1-master',
                           l3_xml              XMLTYPE       PATH 'list-2-detail') x2 ON 1=1
    LEFT JOIN
     XMLTable ('/list-2-detail/elem-2-detail[field-2-detail != "val_detail_m2_d1"]'
                   PASSING x2.l3_xml
                   COLUMNS detail              VARCHAR2(100) PATH 'field-2-detail') x3 ON 1=1
ORDER BY 1, 2, 3, 4

Output: The result in the attached file shows that, with all joins Ansi outer joins, all records are returned except for the filtered-out detail record, as expected.

Notes on SQL

XMLTable and XPath Syntax
Thh XMLTable function represents a rowset retrieved from an XML fragment. The first string within the call represents an XPath expression for the root element defining the rowset in the XML fragment passed. The number of occurrences in the fragment is the rowset cardinality.

The PASSING clause passes in the XMLTYPE field from a prior table or XMLTable instance from which the XML fragment is extracted. For a detail entity, the field will be passed from a master record in a a prior instance, and the instance order matters.

The COLUMNS clause defines the columns that can be included in the select list, and specifies a field for each column by an XPath expression. The expression is relative to the XMLTable root and must specify a single element instance.

XQuery Error (ORA-19279)
A common error in development is:
'ORA-19279: XPTY0004 - XQuery dynamic type mismatch: expected singleton sequence - got multi-item sequence'
The error occurs when the XPath expression for a column selects more than one instance.

Filtering
Filtering of the XNL elements is effected using standard XPath notation, with conditions placed in square brackets after the element name.

Fields and Attributes
Elements may contain attributes, which are denoted in standard XML syntax by preceding the attribute name with '@'. Further details on XML syntax for Oracle, including additional features such as namespaces, can be found in Oracle XML DB Developer's Guide

Ansi and Oracle Join Syntaxes
Oracle introduced the Ansi standard join syntax in version 9, and it is generally to be preferred to its older proprietary syntax. However, this is debatable in the special case of SQL incorporating XMLTable because joining occurs in a non-standard way within the PASSING and other clauses of XMLTable, and not in the mandatory (except for cross joins) ON clause. In my examples, I have had to join ON 1=1 as a work-around.

Outer Joins
The examples show that outer-joining only the detail table does not work correctly. This appears to be a bug in Oracle 11.2. We have worked around it by outer-joining all tables.

Also note that the outer-join (+) needs to be after the table instance, unlike in standard SQL, where it goes after the join columns.

XMLTYPE Storage Clause
The XMLTYPE column in the table used to load the XML file has a storage clause that can specify either CLOB or BINARY XML (and maybe others) as the storage mode. It is vital for performance to choose BINARY XML if the table is going to be queried using XMLTable.

XPlan Statistics
I included calls to DBMS_XPlan in some of the queries in the attached files, and it can be seen that the CBO cardinalities are extermely inaccurate. This is perhaps not surprising as there is only one record in the table, which is exploded within the SQL, and the CBO is obviously not designed to optimise this.
SQL XML Design Patterns Files






Notes on Profiling Oracle PL/SQL

'Everything should be made as simple as possible, but not simpler'

This phrase is often attributed to Albert Einstein, although the attribution is apparently questionable:
Everything Should Be Made as Simple as Possible, But Not Simpler. In any case it's not a bad approach to follow, even if the quote did come from a non-Oracle guy :).

I recently started looking at the hierarchical profiler tool with a view to using it in an upcoming project. In order to understand the tool properly, I felt it would be a good idea to start by using it to profile a test program that would be as simple as possible while covering as wide a range of scenarios as possible. This article documents the results of that profiling, highlighting the different scenarios covered, discusses the output from the profiler, and includes a query I wrote to display the function call tree.

The article goes on to illustrate profiling through manual code instrumentation, and by the old flat profiler (DBMS_Profiler) on the same test program, concluding that each method has its own strengths and weaknesses.

Setup
The hierarchical profiler setup and use is described in Oracle® Database Advanced Application Developer's Guide 11g Release 2 (11.2), and some code snippets are available here:PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1

Scenarios
The test program consists of a driving script, Test_Rep_p.sql (attached), that calls a package (HProf_Test) and an object type (Table_Count_Type), both defined in the attached script, HProf_Test_Code.sql. The test program covers the following scenarios:

  • Multiple root calls (__plsql_vm, A_CALLS_B)
  • Recursive procedure calls (procedure calling itself: R_CALLS_R)
  • Mutually recursive procedure calls (procedures call each other: A_CALLS_B and B_CALLS_A)
  • Procedure called by multiple procedures (child with multiple parents: PUT_LINE)
  • Procedure 'inlined' within PL/SQL (Rest_a_While)
  • Static SQL within PL/SQL (__static_sql_exec_line8)
  • Dynamic SQL within PL/SQL (__dyn_sql_exec_line12)
  • 'Everything should be made as simple as possible, but not simpler'

    This phrase is often attributed to Albert Einstein, although the attribution is apparently questionable:
    Everything Should Be Made as Simple as Possible, But Not Simpler. In any case it's not a bad approach to follow, even if the quote did come from a non-Oracle guy :).

    I recently started looking at the hierarchical profiler tool with a view to using it in an upcoming project. In order to understand the tool properly, I felt it would be a good idea to start by using it to profile a test program that would be as simple as possible while covering as wide a range of scenarios as possible. This article documents the results of that profiling, highlighting the different scenarios covered, discusses the output from the profiler, and includes a query I wrote to display the function call tree.

    The article goes on to illustrate profiling through manual code instrumentation, and by the old flat profiler (DBMS_Profiler) on the same test program, concluding that each method has its own strengths and weaknesses.

    Setup
    The hierarchical profiler setup and use is described in Oracle® Database Advanced Application Developer's Guide 11g Release 2 (11.2), and some code snippets are available here:PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1

    Scenarios
    The test program consists of a driving script, Test_Rep_p.sql (attached), that calls a package (HProf_Test) and an object type (Table_Count_Type), both defined in the attached script, HProf_Test_Code.sql. The test program covers the following scenarios:

    • Multiple root calls (__plsql_vm, A_CALLS_B)
    • Recursive procedure calls (procedure calling itself: R_CALLS_R)
    • Mutually recursive procedure calls (procedures call each other: A_CALLS_B and B_CALLS_A)
    • Procedure called by multiple procedures (child with multiple parents: PUT_LINE)
    • Procedure 'inlined' within PL/SQL (Rest_a_While)
    • Static SQL within PL/SQL (__static_sql_exec_line8)
    • Dynamic SQL within PL/SQL (__dyn_sql_exec_line12)
    • Database function called from SQL in SQL*Plus (DBFUNC)
    • Database function called from SQL in PL/SQL (DBFUNC)
    • Object constructor call (TABLE_COUNT_TYPE)

    Call Structure Diagram
    HProf - CSD

    Raw Results
    The attached script Test_Rep_h.sql was used to report on the results. The record produced in the run table, DBMSHP_RUNS, was:

         RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
    ---------- ---------------------------- ---------- ---------- ------------------------------------------------------------
            11 04-MAR-13 07.07.36.803000        890719        .89 Profile for small test program with recursion

    The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

    OWNER MODULE               FUNCTION                         ID  LINE#      SUB_T      FUN_T  CALLS
    ----- -------------------- ------------------------------ ---- ------ ---------- ---------- ------
    NET   HPROF_TEST           A_CALLS_B                         4     40      62340       4450      1
    NET   HPROF_TEST           A_CALLS_B@1                       5     40      43729      13663      1
    NET   HPROF_TEST           B_CALLS_A                         6     38      57890      14161      1
    NET   HPROF_TEST           B_CALLS_A@1                       7     38      30066      30066      1
    NET   HPROF_TEST           DBFUNC                            8     84      32629      32629      2
    NET   HPROF_TEST           R_CALLS_R                         9     70      12823       4159      1
    NET   HPROF_TEST           R_CALLS_R@1                      10     70       8633       8618      1
    NET   HPROF_TEST           STOP_PROFILING                   11     16         21         21      1
    NET   TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                 12      3      55049         82      1
    NET   TABLE_COUNT_TYPE     __static_sql_exec_line6          22      6      54967      54967      1
    SYS   DBMS_HPROF           STOP_PROFILING                   13     59          0          0      1
    SYS   DBMS_OUTPUT          GET_LINE                         14    129          8          8      3
    SYS   DBMS_OUTPUT          GET_LINES                        15    160         68         60      3
    SYS   DBMS_OUTPUT          NEW_LINE                         16    117          7          7      2
    SYS   DBMS_OUTPUT          PUT                              17     77         28         28      2
    SYS   DBMS_OUTPUT          PUT_LINE                         18    109         46         11      2
                               __anonymous_block                 1      0     809839        521      5
                               __dyn_sql_exec_line12            19     12        226        226      1
                               __plsql_vm                        2      0     828379         58      6
                               __plsql_vm@1                      3      0      14158         11      1
                               __sql_fetch_line13               20     13     726713     726713      1
                               __static_sql_exec_line8          21      8      14418        260      1
    
    22 rows selected.

    The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing.

    The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, were:

    OWNER_P MODULE_P             FUNCTION_P                     OWNER_C MODULE_C             FUNCTION_C                          SUB_T      FUN_T  CALLS
    ------- -------------------- ------------------------------ ------- -------------------- ------------------------------ ---------- ---------- ------
    NET     HPROF_TEST           STOP_PROFILING                 SYS     DBMS_HPROF           STOP_PROFILING                          0          0      1
    NET     HPROF_TEST           R_CALLS_R@1                    SYS     DBMS_OUTPUT          PUT_LINE                               15          6      1
    NET     HPROF_TEST           R_CALLS_R                      SYS     DBMS_OUTPUT          PUT_LINE                               31          5      1
    NET     HPROF_TEST           R_CALLS_R                      NET     HPROF_TEST           R_CALLS_R@1                          8633       8618      1
    NET     HPROF_TEST           B_CALLS_A                      NET     HPROF_TEST           A_CALLS_B@1                         43729      13663      1
    NET     HPROF_TEST           A_CALLS_B@1                    NET     HPROF_TEST           B_CALLS_A@1                         30066      30066      1
    NET     HPROF_TEST           A_CALLS_B                      NET     HPROF_TEST           B_CALLS_A                           57890      14161      1
    NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE               NET     TABLE_COUNT_TYPE     __static_sql_exec_line6             54967      54967      1
    SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          NEW_LINE                                7          7      2
    SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          PUT                                    28         28      2
    SYS     DBMS_OUTPUT          GET_LINES                      SYS     DBMS_OUTPUT          GET_LINE                                8          8      3
                                 __anonymous_block              NET     HPROF_TEST           STOP_PROFILING                         21         21      1
                                 __anonymous_block              SYS     DBMS_OUTPUT          GET_LINES                              68         60      3
                                 __anonymous_block                                           __dyn_sql_exec_line12                 226        226      1
                                 __anonymous_block              NET     HPROF_TEST           R_CALLS_R                           12823       4159      1
                                 __anonymous_block                                           __static_sql_exec_line8             14418        260      1
                                 __plsql_vm                     NET     HPROF_TEST           DBFUNC                              18482      18482      1
                                 __anonymous_block                                           __sql_fetch_line13                 726713     726713      1
                                 __static_sql_exec_line8                                     __plsql_vm@1                        14158         11      1
                                 __plsql_vm                                                  __anonymous_block                  809839        521      5
                                 __plsql_vm@1                   NET     HPROF_TEST           DBFUNC                              14147      14147      1
                                 __anonymous_block              NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                    55049         82      1
    
    22 rows selected.

    The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

    Function Call Tree
    The raw data above can be used to identify processing bottlenecks at a function level, but it's also useful to process the data in order to display the function hierarchies, both for performance tuning and also for understanding the program structure. This is not quite as trivial as it may seem. The oracle-base article provides an SQL statement that attempts to do this:

    SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
           fi.function,
           pci.subtree_elapsed_time,
           pci.function_elapsed_time,
           pci.calls
    FROM   dbmshp_parent_child_info pci
           JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid
    WHERE  pci.runid = :RUN_ID
    CONNECT BY PRIOR childsymid = parentsymid
    START WITH pci.parentsymid = :START_ID

    Here, bind variables replace the original hard-coded values. On running this query I often got the following result:

    ERROR at line 1:
    ORA-01436: CONNECT BY loop in user data

    On the run used in this article, the query returned 157 records, which is obviously incorrect. There is of course a NOCYCLE keyword that can be used to return results in the case of loops. However, it is not worth adding in this case, because there are in fact no loops in the data (at least no cyclic loops - apparent loops are discussed later). Oracle avoids loops by treating a function call that is a descendant of itself as a call to a new function, identified by suffices @1, @2 etc. as we can see from the recursive procedures above (eg R_CALLS_R@1 is the second call of R_CALLS_R, this one from itself). The problem here is that the query is incorrect in its handling of runid, with the result that the tree-walk traverses records from other runs as well as the intended one. A further problem is that there may be several roots, and it would be best to calculate these within a subquery. We can correct these problems by the following query:

    SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
           fi.symbolid || ': ' || fi.function function,
           pci.subtree_elapsed_time sub_t,
           pci.function_elapsed_time fun_t,
           pci.calls
      FROM dbmshp_parent_child_info	pci
      JOIN dbmshp_function_info		fi 
        ON pci.runid	              = fi.runid 
       AND pci.childsymid	       = fi.symbolid
     WHERE pci.runid                   = :RUN_ID
    CONNECT BY PRIOR pci.childsymid    = pci.parentsymid 
           AND pci.runid	              = :RUN_ID
    START WITH pci.parentsymid         IN (SELECT f.symbolid FROM dbmshp_function_info f WHERE NOT EXISTS 
           (SELECT 1 FROM dbmshp_parent_child_info i WHERE i.childsymid = f.symbolid AND i.runid = :RUN_ID) AND f.runid = :RUN_ID)
           AND pci.runid	              = :RUN_ID

    This query returns the results:

    NAME                           FUNCTION                            SUB_T      FUN_T  CALLS
    ------------------------------ ------------------------------ ---------- ---------- ------
      .                            1: __anonymous_block              809,839        521      5
        NET.HPROF_TEST             9: R_CALLS_R                       12,823      4,159      1
          NET.HPROF_TEST           10: R_CALLS_R@1                     8,633      8,618      1
            SYS.DBMS_OUTPUT        18: PUT_LINE                           15          6      1
              SYS.DBMS_OUTPUT      16: NEW_LINE                            7          7      2
              SYS.DBMS_OUTPUT      17: PUT                                28         28      2
          SYS.DBMS_OUTPUT          18: PUT_LINE                           31          5      1
            SYS.DBMS_OUTPUT        16: NEW_LINE                            7          7      2
            SYS.DBMS_OUTPUT        17: PUT                                28         28      2
        NET.HPROF_TEST             11: STOP_PROFILING                     21         21      1
          SYS.DBMS_HPROF           13: STOP_PROFILING                      0          0      1
        NET.TABLE_COUNT_TYPE       12: TABLE_COUNT_TYPE               55,049         82      1
          NET.TABLE_COUNT_TYPE     22: __static_sql_exec_line6        54,967     54,967      1
        SYS.DBMS_OUTPUT            15: GET_LINES                          68         60      3
          SYS.DBMS_OUTPUT          14: GET_LINE                            8          8      3
        .                          19: __dyn_sql_exec_line12             226        226      1
        .                          20: __sql_fetch_line13            726,713    726,713      1
        .                          21: __static_sql_exec_line8        14,418        260      1
          .                        3: __plsql_vm@1                    14,158         11      1
            NET.HPROF_TEST         8: DBFUNC                          14,147     14,147      1
      NET.HPROF_TEST               8: DBFUNC                          18,482     18,482      1
      NET.HPROF_TEST               6: B_CALLS_A                       57,890     14,161      1
        NET.HPROF_TEST             5: A_CALLS_B@1                     43,729     13,663      1
          NET.HPROF_TEST           7: B_CALLS_A@1                     30,066     30,066      1
    
    24 rows selected.

    This is better, but we can identify some further issues.

    Missing Roots
    The true root results are missing: For example, A_CALLS_B is missing. This arises because the query is traversing the link records (DBMSHP_PARENT_CHILD_INFO), while the root information is stored in the nodes (DBMSHP_FUNCTION_INFO). This suggests a change from the CONNECT BY syntax to Oracle's v11.2 recursive subquery factoring syntax, which allows you easily to start from the nodes, then traverse recursively via the links. (Incidentally, moving the start of profiling to its own block would result in A_CALLS_B appearing under __anonymous_block, but I prefer to retain the current structure in order to deal with the general case in which multiple roots are possible.)

    Duplicate Links
    Notice that function PUT_LINE is reported separately under R_CALLS_R and R_CALLS_R@1, and the timings differ. Also, its own child calls appear under each of its instances, but in those cases the timings are identical. The reason for this is that in the first case, there are separate records of the times used in each call, whereas in the second, the child calls have only a single record giving the total times across both instances of the parent call. The call from R_CALLS_R shows (9 - 4 = ) 5µs used in child calls, while the call from R_CALLS_R@1 shows 14µs. The child calls show totals of (3 + 16 = ) 19µs, equalling the sum across the parent calls.

    At this point it is worth looking at this from the more general perspective of a hierarchical data structure where parents can have multiple children and children multiple parents, with one or more roots. If a network diagram were constructed there would be loops apparent indicating multiple routes between nodes. In these situations, Oracle's hierarchical queries effectively traverse all routes, and this is what causes the link duplication (in other scenarios this behaviour can cause big performance problems, but probably not here). Oracle's cycle detection mechanism does not trigger because the loops do not result in any node being a descendant of itself (as noted above, extra nodes are generated by the profiler to avoid this).

    It seems to me better to avoid this duplication, and also to signal those cases where times are not aggregated up the tree. We can achieve this by the use of analytic functions. Note that, although the query below refers to the specific tables and attributes for this problem, the proposed solution could be used for any member of this general class of problem. The new query, which orders sibling records by descending subtree elapsed time, is:

    WITH last_run AS (
    SELECT Max (runid) runid FROM dbmshp_runs
    ), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
    SELECT fni.runid, 0, fni.symbolid, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls, 'root' || ROWNUM
      FROM dbmshp_function_info fni
      JOIN last_run lrn
        ON lrn.runid = fni.runid
     WHERE NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
     UNION ALL
    SELECT ftr.runid, 
           ftr.lev + 1, 
           pci.childsymid, 
           pci.subtree_elapsed_time, 
           pci.function_elapsed_time, 
           pci.calls,
           pci.parentsymid || '-' || pci.childsymid
      FROM full_tree ftr
      JOIN dbmshp_parent_child_info pci
        ON pci.parentsymid = ftr.node_id
       AND pci.runid = ftr.runid
    ) SEARCH DEPTH FIRST BY sub_t DESC, fun_t DESC, calls DESC, node_id SET rn
    , tree_ranked AS (
    SELECT runid, node_id, lev, rn, 
           sub_t, fun_t, calls, 
           Row_Number () OVER (PARTITION BY node_id ORDER BY rn) node_rn,
           Count (*) OVER (PARTITION BY node_id) node_cnt,
           Row_Number () OVER (PARTITION BY link_id ORDER BY rn) link_rn
      FROM full_tree
    )
    SELECT RPad (' ', trr.lev*2, ' ') || fni.function "Function tree",
           fni.symbolid sy, fni.owner, fni.module,
           CASE WHEN trr.node_cnt > 1 THEN trr.node_rn || ' of ' || trr.node_cnt END "Inst.",
           trr.sub_t, trr.fun_t, trr.calls, 
           trr.rn "Row"
      FROM tree_ranked trr
      JOIN dbmshp_function_info fni
        ON fni.symbolid = trr.node_id
       AND fni.runid = trr.runid
     WHERE trr.link_rn = 1
     ORDER BY trr.rn

    Query Structure Diagram
    HProf - QSD

    The results are then:

    Function tree                        SY OWNER MODULE               Inst.         SUB_T      FUN_T  CALLS  Row
    ----------------------------------- --- ----- -------------------- -------- ---------- ---------- ------ ----
    __plsql_vm                            2                                        828,379         58      6    1
      __anonymous_block                   1                                        809,839        521      5    2
        __sql_fetch_line13               20                                        726,713    726,713      1    3
        TABLE_COUNT_TYPE                 12 NET   TABLE_COUNT_TYPE                  55,049         82      1    4
          __static_sql_exec_line6        22 NET   TABLE_COUNT_TYPE                  54,967     54,967      1    5
        __static_sql_exec_line8          21                                         14,418        260      1    6
          __plsql_vm@1                    3                                         14,158         11      1    7
            DBFUNC                        8 NET   HPROF_TEST           1 of 2       14,147     14,147      1    8
        R_CALLS_R                         9 NET   HPROF_TEST                        12,823      4,159      1    9
          R_CALLS_R@1                    10 NET   HPROF_TEST                         8,633      8,618      1   10
            PUT_LINE                     18 SYS   DBMS_OUTPUT          1 of 2           15          6      1   11
              PUT                        17 SYS   DBMS_OUTPUT          1 of 2           28         28      2   12
              NEW_LINE                   16 SYS   DBMS_OUTPUT          1 of 2            7          7      2   13
          PUT_LINE                       18 SYS   DBMS_OUTPUT          2 of 2           31          5      1   14
        __dyn_sql_exec_line12            19                                            226        226      1   17
        GET_LINES                        15 SYS   DBMS_OUTPUT                           68         60      3   18
          GET_LINE                       14 SYS   DBMS_OUTPUT                            8          8      3   19
        STOP_PROFILING                   11 NET   HPROF_TEST                            21         21      1   20
          STOP_PROFILING                 13 SYS   DBMS_HPROF                             0          0      1   21
      DBFUNC                              8 NET   HPROF_TEST           2 of 2       18,482     18,482      1   22
    A_CALLS_B                             4 NET   HPROF_TEST                        62,340      4,450      1   23
      B_CALLS_A                           6 NET   HPROF_TEST                        57,890     14,161      1   24
        A_CALLS_B@1                       5 NET   HPROF_TEST                        43,729     13,663      1   25
          B_CALLS_A@1                     7 NET   HPROF_TEST                        30,066     30,066      1   26
    
    24 rows selected.

    Notice that we now have a single record for each of the 22 links, plus the two root nodes. Also, the "Inst." column lists the instance number of a function having more than one instance, and the children of any such function are only listed once with the gaps in the "Row" column indicating where duplicates have been suppressed.

    Network Diagrams
    It may be interesting to display the call tree in two diagrams, one for each root.
    Root __plsql_vm
    HProf - Net

    Root A_CALLS_B
    HProf - Net2

    Notes on Tree Output
    Anonymous Block (__anonymous_block)
    This function seems to correspond to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 6, because the driving program has only three such blocks, and there are none in the called PL/SQL code. I would surmise that the apparent discrepancy arises from the enabling of SERVEROUTPUT, which appears to result in a secondary block being associated with each explicit SQL*Plus block, that issues a call to GET_LINES to process buffered output.

    PL/SQL Engine (__plsql_vm)
    This function seems to correspond to external invocations of PL/SQL such as from a SQL*Plus session. There are 7 calls, 6 of them presumably being linked with the external anonymous blocks, and the seventh with DBFUNC, where a PL/SQL function is called from a SQL statement from SQL*Plus.

    Notice that the SQL statement calling a database function from within PL/SQL generates the recursive call to the engine, __plsql_vm@1

    Second Root (A_CALLS_B)
    The above function does not have the __plsql_vm/__anonymous_block ancestry that might be expected because profiling only started within the enclosing block.

    Inlined Procedure (Rest_a_While)
    I wrote a small procedure, Rest_a_While, to generate some elapsed time in the recursive procedures, but preceded it with the INLINE pragma, a new optimisation feature in 11g. This had the desired effect of removing the calls from the profiling output and including the times in the calling procedures. Rest_a_While does not make the obvious call to DBMS_Lock.Sleep because that procedure cannot be inlined. subprogram inlining in 11g provides some analysis of the inlining feature.

    Sibling Ordering
    We have ordered siblings by descending subtree elapsed time, using the SEARCH clause. It would be nice to have the option to order the siblings by initial invocation time, but Oracle does not provide the data to do this.

    Loops and Hierarchies
    The first diagram shows two loops, where there are two routes between the loop start and end points, indicated by different colours. The second loop has two child nodes coming from the end point, and hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links to be duplicated. Our query has filtered out the duplicates by analytic functions.

    It's worth remembering this because it's a general feature of SQL for querying hierarchies, and judging by Oracle forums, not one that's widely understood. For larger hierarchies it can cause serious performance problems, and may justify a PL/SQL programmed solution that need not suffer the same problem.

    Manual Instrumentation
    Oracle's hierarchical profiler clearly provides extremely useful information on both performance and structure of PL/SQL programs with very little effort. However, it does have the limitation of only providing information down to the subprogram level (which includes embedded SQL statements in this context). It is also often considered good practice to implement timing and other instrumentation permanently in production code, sometimes in a switchable fashion. In the test program, one of the called procedures, A_Calls_B, makes two calls to the inlined procedure, Rest_a_While, the second doing about twice as much work as the first. The profiler reports total within-function times of 4,450µs and 13,663µs on first and second calls, respectively (the work is scaled by a call number parameter, equal to 1, then 3).

    I created a second instance of the package and driver script (suffix _TS) to illustrate manual instrumentation. This uses an 'object-oriented' timing package that I wrote a couple of years ago Code Timing and Object Orientation and Zombies (November, 2010) to instrument at procedure and section level. I multiplied the work in Rest_a_While by a factor of ten to get larger times. This produced the output:

    Timer Set: HProf, Constructed at 05 Mar 2013 10:21:27, written at 10:21:30
    ==========================================================================
    [Timer timed: Elapsed (per call): 0.04 (0.000044), CPU (per call): 0.05 (0.000050), calls: 1000, '***' denotes corrected line below]
    
    Timer                       Elapsed          CPU          Calls        Ela/Call        CPU/Call
    ----------------------   ----------   ----------   ------------   -------------   -------------
    A_Calls_B, section one         0.06         0.05              2         0.03150         0.02500
    A_Calls_B, section two         0.12         0.12              2         0.06050         0.06000
    B_Calls_A: 2                   0.15         0.16              1         0.15400         0.16000
    B_Calls_A: 4                   0.31         0.30              1         0.30700         0.30000
    DBFunc                         0.32         0.31              2         0.15950         0.15500
    Open cursor                    0.69         0.69              1         0.68900         0.69000
    Fetch from cursor              0.70         0.70              1         0.69600         0.70000
    Close cursor                   0.00         0.00              1         0.00000         0.00000
    Construct object               0.06         0.04              1         0.05500         0.04000
    R_Calls_R                      0.14         0.14              2         0.07000         0.07000
    (Other)                        0.00         0.00              1         0.00000         0.00000
    ----------------------   ----------   ----------   ------------   -------------   -------------
    Total                          2.54         2.51             15         0.16960         0.16733
    ----------------------   ----------   ----------   ------------   -------------   -------------
    

    Notes on Code Timing

    • Calls, CPU and elapsed times have been captured at the section level for A_Calls_B
    • Observe that, while R_Calls_R and A_Calls_B aggregate over all calls, B_Calls_A records values by call; this is implemented simply by including a value that changes with call in the timer name
    • The timing set object is designed to be very low footprint; here 9 statements (calls to Increment_Time), plus a small global overhead, produced 10 result lines, plus associated information
    • The 'object-oriented' approach allows multiple programs to be be timed at multiple levels, without interference between timings
    • There are Perl and Java implementations of this timing set object included in the Scribd article mentioned

    Oracle's Flat Profiler (DBMS_Profiler)
    The hierarchical profiler was introduced in v11.1, while prior to this there was a non-hierarchical profiler, DBMS_Profiler. This package still exists in v11: It is omitted from the advanced application developer's guide for v11, but is described in the packages and types manual (Oracle® Database PL/SQL Packages and Types Reference, 11g Release 2 (11.2)); also, SQL*Developer appears to support only the newer hierarchical verion (via right-click on a package). I thought it interesting to run the older version on the same test program (package Old_Test_Prof, driver script Test_Rep_p_Old.sql and reporting script Test_Rep_h_Old.sql). The output from the first three queries is:

    Run header (PLSQL_PROFILER_RUNS)
    
         RUNID RUN_DATE        MICRO_S    SECONDS
    ---------- ------------ ---------- ----------
             3 11:03:13        2164000       2.16
    
    Profiler data summary (PLSQL_PROFILER_DATA)
    
       MICRO_S SECONDS    CALLS
    ---------- ------- --------
       2126949    2.13       72
    
    Profiler data by time (PLSQL_PROFILER_DATA)
    
       MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
    ---------- ------- -------- -------------------- ----------- ------
        729932    0.73        1                                5     13
        569563    0.57        2 OLD_PROF_TEST                  1     56
        377880    0.38        2 OLD_PROF_TEST                  1     82
        166019    0.17        2 OLD_PROF_TEST                  1     70
        150117    0.15        2 OLD_PROF_TEST                  1     43
         72742    0.07        2 OLD_PROF_TEST                  1     40
         56473    0.06        1 TABLE_COUNT_TYPE               6      6
          3338    0.00        1                                5      8
           258    0.00        1                                5     12
           109    0.00        1                                5     16
            68    0.00        2 OLD_PROF_TEST                  1     67
            66    0.00        2                                4      1
            60    0.00        2                                7      1
            60    0.00        2                                3      1
            44    0.00        1                                5     14
            42    0.00        0                                2      5
            31    0.00        1 OLD_PROF_TEST                  1     18
            26    0.00        1                                8      5
            13    0.00        0                                5      1
             9    0.00        1 TABLE_COUNT_TYPE               6     11
             9    0.00        2 OLD_PROF_TEST                  1     86
             8    0.00        0 OLD_PROF_TEST                  1     51
             8    0.00        1 TABLE_COUNT_TYPE               6     13
             7    0.00        1                                5     18
             6    0.00        0 OLD_PROF_TEST                  1     78
             6    0.00        0 OLD_PROF_TEST                  1     64
             6    0.00        0                                8      1
             6    0.00        1 TABLE_COUNT_TYPE               6      3
             5    0.00        0 OLD_PROF_TEST                  1     35
             5    0.00        0 OLD_PROF_TEST                  1     15
             4    0.00        1                                8      7
             4    0.00        1 OLD_PROF_TEST                  1     76
             3    0.00        1                                2      8
             2    0.00        1 OLD_PROF_TEST                  1     62
             2    0.00        1 OLD_PROF_TEST                  1     13
             2    0.00        1 TABLE_COUNT_TYPE               6      5
             2    0.00        2 OLD_PROF_TEST                  1     72
             2    0.00        2 OLD_PROF_TEST                  1     45
             2    0.00        2 OLD_PROF_TEST                  1     49
             2    0.00        2 OLD_PROF_TEST                  1     46
             2    0.00        2 OLD_PROF_TEST                  1     58
             1    0.00        1 OLD_PROF_TEST                  1     73
             1    0.00        1                                2      6
             1    0.00        1 OLD_PROF_TEST                  1     59
             1    0.00        1 OLD_PROF_TEST                  1     11
             1    0.00        2 OLD_PROF_TEST                  1     54
             1    0.00        2 OLD_PROF_TEST                  1     84
             0    0.00        0 OLD_PROF_TEST                  1      1
             0    0.00        0 OLD_PROF_TEST                  1     88
             0    0.00        0                                8      9
             0    0.00        0                                2      1
             0    0.00        0                                2      2
             0    0.00        0 OLD_PROF_TEST                  1      3
             0    0.00        0 OLD_PROF_TEST                  1      5
             0    0.00        0 OLD_PROF_TEST                  1      9
             0    0.00        0 OLD_PROF_TEST                  1     20
             0    0.00        1 TABLE_COUNT_TYPE               6      4
             0    0.00        1                                8      2
             0    0.00        2 OLD_PROF_TEST                  1     39
             0    0.00        2 OLD_PROF_TEST                  1     55
             0    0.00        2 OLD_PROF_TEST                  1     69
             0    0.00        2 OLD_PROF_TEST                  1     38
             0    0.00        2 OLD_PROF_TEST                  1     81
             0    0.00        2 OLD_PROF_TEST                  1     42
             0    0.00        2 OLD_PROF_TEST                  1     68
    
    65 rows selected.
    
    

    Referring to the package, type and anonymous blocks, I assigned labels to all the lines having more than 10µs, as follows:

       MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
    ---------- ------- -------- -------------------- ----------- ------
        729932    0.73        1                                5     13  B2: FETCH
        569563    0.57        2 OLD_PROF_TEST                  1     56  B_Calls_A (Rest_a_While)
        377880    0.38        2 OLD_PROF_TEST                  1     82  DBFunc (Rest_a_While)
        166019    0.17        2 OLD_PROF_TEST                  1     70  R_Calls_R (Rest_a_While)
        150117    0.15        2 OLD_PROF_TEST                  1     43  A_Calls_B (Rest_a_While, section 2)
         72742    0.07        2 OLD_PROF_TEST                  1     40  A_Calls_B (Rest_a_While, section 1)
         56473    0.06        1 TABLE_COUNT_TYPE               6      6  SELECT
          3338    0.00        1                                5      8  B2: SELECT DBFunc
           258    0.00        1                                5     12  B2: OPEN
           109    0.00        1                                5     16  B2: Assign Table_Count_Type
            68    0.00        2 OLD_PROF_TEST                  1     67  Put_Line
            66    0.00        2                                4      1  Auxiliary SERVEROUTPUT block for B2 (surmised)
            60    0.00        2                                7      1  Auxiliary SERVEROUTPUT block for B3 (surmised)
            60    0.00        2                                3      1  Auxiliary SERVEROUTPUT block for B1 (surmised)
            44    0.00        1                                5     14  B2: CLOSE
            42    0.00        0                                2      5  B1: Call to Start_Profiling 
            31    0.00        1 OLD_PROF_TEST                  1     18  RETURN DBMS_Profiler.Stop_Profiler;
            26    0.00        1                                8      5  B3: Call R_Calls_R
            13    0.00        0                                5      1  B2: DECLARE
    

    Notes on Output of Flat Profiler
    There were six units with no linked information in DBMS_PROFILER_UNITS. By examining the data, I was able to associate unit numbers 2, 5 and 8 with my anonymous blocks B1, B2 and B3. That left three unassigned, and I have surmised that these correspond to the auxiliary blocks associated with processing server output that we earlier surmised when examining the output from the hierarchical profiler.

    • The useful call tree structure is not present in the data from the old profiler
    • However, the results are at a line level, which the hierarchical profiler does not provide; for example, the two sections of A_Calls_B are reported separately
    • Deciphering the output requires significantly more manual effort than with the hierarchical profiler
    • Both old and new profiler have their own advantages, and so both should be considered of value
    • Manual code timing offers more flexibility in terms of aggregating lines and call instances, but requires more effort

    Conclusions

    • Running Oracle's hierarchical profiler would seem to be the default first step in tuning PL/SQL programs from v11.1
    • Some care is needed in interpreting the output data; I've provided a query for displaying the hierarchies
    • Performance is recorded only down to function level, so it will still often be worthwhile to use the old flat profiler in addition
    • Manually timing code sections also still has a part to play, in terms of instrumentation and greater flexibility where necessary






  • Database function called from SQL in SQL*Plus (DBFUNC)
  • Database function called from SQL in PL/SQL (DBFUNC)
  • Object constructor call (TABLE_COUNT_TYPE)

Call Structure Diagram
HProf - CSD

Raw Results
The attached script Test_Rep_h.sql was used to report on the results. The record produced in the run table, DBMSHP_RUNS, was:

     RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
---------- ---------------------------- ---------- ---------- ------------------------------------------------------------
        11 04-MAR-13 07.07.36.803000        890719        .89 Profile for small test program with recursion

The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

OWNER MODULE               FUNCTION                         ID  LINE#      SUB_T      FUN_T  CALLS
----- -------------------- ------------------------------ ---- ------ ---------- ---------- ------
NET   HPROF_TEST           A_CALLS_B                         4     40      62340       4450      1
NET   HPROF_TEST           A_CALLS_B@1                       5     40      43729      13663      1
NET   HPROF_TEST           B_CALLS_A                         6     38      57890      14161      1
NET   HPROF_TEST           B_CALLS_A@1                       7     38      30066      30066      1
NET   HPROF_TEST           DBFUNC                            8     84      32629      32629      2
NET   HPROF_TEST           R_CALLS_R                         9     70      12823       4159      1
NET   HPROF_TEST           R_CALLS_R@1                      10     70       8633       8618      1
NET   HPROF_TEST           STOP_PROFILING                   11     16         21         21      1
NET   TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                 12      3      55049         82      1
NET   TABLE_COUNT_TYPE     __static_sql_exec_line6          22      6      54967      54967      1
SYS   DBMS_HPROF           STOP_PROFILING                   13     59          0          0      1
SYS   DBMS_OUTPUT          GET_LINE                         14    129          8          8      3
SYS   DBMS_OUTPUT          GET_LINES                        15    160         68         60      3
SYS   DBMS_OUTPUT          NEW_LINE                         16    117          7          7      2
SYS   DBMS_OUTPUT          PUT                              17     77         28         28      2
SYS   DBMS_OUTPUT          PUT_LINE                         18    109         46         11      2
                           __anonymous_block                 1      0     809839        521      5
                           __dyn_sql_exec_line12            19     12        226        226      1
                           __plsql_vm                        2      0     828379         58      6
                           __plsql_vm@1                      3      0      14158         11      1
                           __sql_fetch_line13               20     13     726713     726713      1
                           __static_sql_exec_line8          21      8      14418        260      1

22 rows selected.

The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, were:

OWNER_P MODULE_P             FUNCTION_P                     OWNER_C MODULE_C             FUNCTION_C                          SUB_T      FUN_T  CALLS
------- -------------------- ------------------------------ ------- -------------------- ------------------------------ ---------- ---------- ------
NET     HPROF_TEST           STOP_PROFILING                 SYS     DBMS_HPROF           STOP_PROFILING                          0          0      1
NET     HPROF_TEST           R_CALLS_R@1                    SYS     DBMS_OUTPUT          PUT_LINE                               15          6      1
NET     HPROF_TEST           R_CALLS_R                      SYS     DBMS_OUTPUT          PUT_LINE                               31          5      1
NET     HPROF_TEST           R_CALLS_R                      NET     HPROF_TEST           R_CALLS_R@1                          8633       8618      1
NET     HPROF_TEST           B_CALLS_A                      NET     HPROF_TEST           A_CALLS_B@1                         43729      13663      1
NET     HPROF_TEST           A_CALLS_B@1                    NET     HPROF_TEST           B_CALLS_A@1                         30066      30066      1
NET     HPROF_TEST           A_CALLS_B                      NET     HPROF_TEST           B_CALLS_A                           57890      14161      1
NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE               NET     TABLE_COUNT_TYPE     __static_sql_exec_line6             54967      54967      1
SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          NEW_LINE                                7          7      2
SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          PUT                                    28         28      2
SYS     DBMS_OUTPUT          GET_LINES                      SYS     DBMS_OUTPUT          GET_LINE                                8          8      3
                             __anonymous_block              NET     HPROF_TEST           STOP_PROFILING                         21         21      1
                             __anonymous_block              SYS     DBMS_OUTPUT          GET_LINES                              68         60      3
                             __anonymous_block                                           __dyn_sql_exec_line12                 226        226      1
                             __anonymous_block              NET     HPROF_TEST           R_CALLS_R                           12823       4159      1
                             __anonymous_block                                           __static_sql_exec_line8             14418        260      1
                             __plsql_vm                     NET     HPROF_TEST           DBFUNC                              18482      18482      1
                             __anonymous_block                                           __sql_fetch_line13                 726713     726713      1
                             __static_sql_exec_line8                                     __plsql_vm@1                        14158         11      1
                             __plsql_vm                                                  __anonymous_block                  809839        521      5
                             __plsql_vm@1                   NET     HPROF_TEST           DBFUNC                              14147      14147      1
                             __anonymous_block              NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                    55049         82      1

22 rows selected.

The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

Function Call Tree
The raw data above can be used to identify processing bottlenecks at a function level, but it's also useful to process the data in order to display the function hierarchies, both for performance tuning and also for understanding the program structure. This is not quite as trivial as it may seem. The oracle-base article provides an SQL statement that attempts to do this:

SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
       fi.function,
       pci.subtree_elapsed_time,
       pci.function_elapsed_time,
       pci.calls
FROM   dbmshp_parent_child_info pci
       JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid
WHERE  pci.runid = :RUN_ID
CONNECT BY PRIOR childsymid = parentsymid
START WITH pci.parentsymid = :START_ID

Here, bind variables replace the original hard-coded values. On running this query I often got the following result:

ERROR at line 1:
ORA-01436: CONNECT BY loop in user data

On the run used in this article, the query returned 157 records, which is obviously incorrect. There is of course a NOCYCLE keyword that can be used to return results in the case of loops. However, it is not worth adding in this case, because there are in fact no loops in the data (at least no cyclic loops - apparent loops are discussed later). Oracle avoids loops by treating a function call that is a descendant of itself as a call to a new function, identified by suffices @1, @2 etc. as we can see from the recursive procedures above (eg R_CALLS_R@1 is the second call of R_CALLS_R, this one from itself). The problem here is that the query is incorrect in its handling of runid, with the result that the tree-walk traverses records from other runs as well as the intended one. A further problem is that there may be several roots, and it would be best to calculate these within a subquery. We can correct these problems by the following query:

SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
       fi.symbolid || ': ' || fi.function function,
       pci.subtree_elapsed_time sub_t,
       pci.function_elapsed_time fun_t,
       pci.calls
  FROM dbmshp_parent_child_info	pci
  JOIN dbmshp_function_info		fi 
    ON pci.runid	              = fi.runid 
   AND pci.childsymid	       = fi.symbolid
 WHERE pci.runid                   = :RUN_ID
CONNECT BY PRIOR pci.childsymid    = pci.parentsymid 
       AND pci.runid	              = :RUN_ID
START WITH pci.parentsymid         IN (SELECT f.symbolid FROM dbmshp_function_info f WHERE NOT EXISTS 
       (SELECT 1 FROM dbmshp_parent_child_info i WHERE i.childsymid = f.symbolid AND i.runid = :RUN_ID) AND f.runid = :RUN_ID)
       AND pci.runid	              = :RUN_ID

This query returns the results:

NAME                           FUNCTION                            SUB_T      FUN_T  CALLS
------------------------------ ------------------------------ ---------- ---------- ------
  .                            1: __anonymous_block              809,839        521      5
    NET.HPROF_TEST             9: R_CALLS_R                       12,823      4,159      1
      NET.HPROF_TEST           10: R_CALLS_R@1                     8,633      8,618      1
        SYS.DBMS_OUTPUT        18: PUT_LINE                           15          6      1
          SYS.DBMS_OUTPUT      16: NEW_LINE                            7          7      2
          SYS.DBMS_OUTPUT      17: PUT                                28         28      2
      SYS.DBMS_OUTPUT          18: PUT_LINE                           31          5      1
        SYS.DBMS_OUTPUT        16: NEW_LINE                            7          7      2
        SYS.DBMS_OUTPUT        17: PUT                                28         28      2
    NET.HPROF_TEST             11: STOP_PROFILING                     21         21      1
      SYS.DBMS_HPROF           13: STOP_PROFILING                      0          0      1
    NET.TABLE_COUNT_TYPE       12: TABLE_COUNT_TYPE               55,049         82      1
      NET.TABLE_COUNT_TYPE     22: __static_sql_exec_line6        54,967     54,967      1
    SYS.DBMS_OUTPUT            15: GET_LINES                          68         60      3
      SYS.DBMS_OUTPUT          14: GET_LINE                            8          8      3
    .                          19: __dyn_sql_exec_line12             226        226      1
    .                          20: __sql_fetch_line13            726,713    726,713      1
    .                          21: __static_sql_exec_line8        14,418        260      1
      .                        3: __plsql_vm@1                    14,158         11      1
        NET.HPROF_TEST         8: DBFUNC                          14,147     14,147      1
  NET.HPROF_TEST               8: DBFUNC                          18,482     18,482      1
  NET.HPROF_TEST               6: B_CALLS_A                       57,890     14,161      1
    NET.HPROF_TEST             5: A_CALLS_B@1                     43,729     13,663      1
      NET.HPROF_TEST           7: B_CALLS_A@1                     30,066     30,066      1

24 rows selected.

This is better, but we can identify some further issues.

Missing Roots
The true root results are missing: For example, A_CALLS_B is missing. This arises because the query is traversing the link records (DBMSHP_PARENT_CHILD_INFO), while the root information is stored in the nodes (DBMSHP_FUNCTION_INFO). This suggests a change from the CONNECT BY syntax to Oracle's v11.2 recursive subquery factoring syntax, which allows you easily to start from the nodes, then traverse recursively via the links. (Incidentally, moving the start of profiling to its own block would result in A_CALLS_B appearing under __anonymous_block, but I prefer to retain the current structure in order to deal with the general case in which multiple roots are possible.)

Duplicate Links
Notice that function PUT_LINE is reported separately under R_CALLS_R and R_CALLS_R@1, and the timings differ. Also, its own child calls appear under each of its instances, but in those cases the timings are identical. The reason for this is that in the first case, there are separate records of the times used in each call, whereas in the second, the child calls have only a single record giving the total times across both instances of the parent call. The call from R_CALLS_R shows (9 - 4 = ) 5µs used in child calls, while the call from R_CALLS_R@1 shows 14µs. The child calls show totals of (3 + 16 = ) 19µs, equalling the sum across the parent calls.

At this point it is worth looking at this from the more general perspective of a hierarchical data structure where parents can have multiple children and children multiple parents, with one or more roots. If a network diagram were constructed there would be loops apparent indicating multiple routes between nodes. In these situations, Oracle's hierarchical queries effectively traverse all routes, and this is what causes the link duplication (in other scenarios this behaviour can cause big performance problems, but probably not here). Oracle's cycle detection mechanism does not trigger because the loops do not result in any node being a descendant of itself (as noted above, extra nodes are generated by the profiler to avoid this).

It seems to me better to avoid this duplication, and also to signal those cases where times are not aggregated up the tree. We can achieve this by the use of analytic functions. Note that, although the query below refers to the specific tables and attributes for this problem, the proposed solution could be used for any member of this general class of problem. The new query, which orders sibling records by descending subtree elapsed time, is:

WITH last_run AS (
SELECT Max (runid) runid FROM dbmshp_runs
), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
SELECT fni.runid, 0, fni.symbolid, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls, 'root' || ROWNUM
  FROM dbmshp_function_info fni
  JOIN last_run lrn
    ON lrn.runid = fni.runid
 WHERE NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
 UNION ALL
SELECT ftr.runid, 
       ftr.lev + 1, 
       pci.childsymid, 
       pci.subtree_elapsed_time, 
       pci.function_elapsed_time, 
       pci.calls,
       pci.parentsymid || '-' || pci.childsymid
  FROM full_tree ftr
  JOIN dbmshp_parent_child_info pci
    ON pci.parentsymid = ftr.node_id
   AND pci.runid = ftr.runid
) SEARCH DEPTH FIRST BY sub_t DESC, fun_t DESC, calls DESC, node_id SET rn
, tree_ranked AS (
SELECT runid, node_id, lev, rn, 
       sub_t, fun_t, calls, 
       Row_Number () OVER (PARTITION BY node_id ORDER BY rn) node_rn,
       Count (*) OVER (PARTITION BY node_id) node_cnt,
       Row_Number () OVER (PARTITION BY link_id ORDER BY rn) link_rn
  FROM full_tree
)
SELECT RPad (' ', trr.lev*2, ' ') || fni.function "Function tree",
       fni.symbolid sy, fni.owner, fni.module,
       CASE WHEN trr.node_cnt > 1 THEN trr.node_rn || ' of ' || trr.node_cnt END "Inst.",
       trr.sub_t, trr.fun_t, trr.calls, 
       trr.rn "Row"
  FROM tree_ranked trr
  JOIN dbmshp_function_info fni
    ON fni.symbolid = trr.node_id
   AND fni.runid = trr.runid
 WHERE trr.link_rn = 1
 ORDER BY trr.rn

Query Structure Diagram
HProf - QSD

The results are then:

Function tree                        SY OWNER MODULE               Inst.         SUB_T      FUN_T  CALLS  Row
----------------------------------- --- ----- -------------------- -------- ---------- ---------- ------ ----
__plsql_vm                            2                                        828,379         58      6    1
  __anonymous_block                   1                                        809,839        521      5    2
    __sql_fetch_line13               20                                        726,713    726,713      1    3
    TABLE_COUNT_TYPE                 12 NET   TABLE_COUNT_TYPE                  55,049         82      1    4
      __static_sql_exec_line6        22 NET   TABLE_COUNT_TYPE                  54,967     54,967      1    5
    __static_sql_exec_line8          21                                         14,418        260      1    6
      __plsql_vm@1                    3                                         14,158         11      1    7
        DBFUNC                        8 NET   HPROF_TEST           1 of 2       14,147     14,147      1    8
    R_CALLS_R                         9 NET   HPROF_TEST                        12,823      4,159      1    9
      R_CALLS_R@1                    10 NET   HPROF_TEST                         8,633      8,618      1   10
        PUT_LINE                     18 SYS   DBMS_OUTPUT          1 of 2           15          6      1   11
          PUT                        17 SYS   DBMS_OUTPUT          1 of 2           28         28      2   12
          NEW_LINE                   16 SYS   DBMS_OUTPUT          1 of 2            7          7      2   13
      PUT_LINE                       18 SYS   DBMS_OUTPUT          2 of 2           31          5      1   14
    __dyn_sql_exec_line12            19                                            226        226      1   17
    GET_LINES                        15 SYS   DBMS_OUTPUT                           68         60      3   18
      GET_LINE                       14 SYS   DBMS_OUTPUT                            8          8      3   19
    STOP_PROFILING                   11 NET   HPROF_TEST                            21         21      1   20
      STOP_PROFILING                 13 SYS   DBMS_HPROF                             0          0      1   21
  DBFUNC                              8 NET   HPROF_TEST           2 of 2       18,482     18,482      1   22
A_CALLS_B                             4 NET   HPROF_TEST                        62,340      4,450      1   23
  B_CALLS_A                           6 NET   HPROF_TEST                        57,890     14,161      1   24
    A_CALLS_B@1                       5 NET   HPROF_TEST                        43,729     13,663      1   25
      B_CALLS_A@1                     7 NET   HPROF_TEST                        30,066     30,066      1   26

24 rows selected.

Notice that we now have a single record for each of the 22 links, plus the two root nodes. Also, the "Inst." column lists the instance number of a function having more than one instance, and the children of any such function are only listed once with the gaps in the "Row" column indicating where duplicates have been suppressed.

Network Diagrams
It may be interesting to display the call tree in two diagrams, one for each root.
Root __plsql_vm
HProf - Net

Root A_CALLS_B
HProf - Net2

Notes on Tree Output
Anonymous Block (__anonymous_block)
This function seems to correspond to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 6, because the driving program has only three such blocks, and there are none in the called PL/SQL code. I would surmise that the apparent discrepancy arises from the enabling of SERVEROUTPUT, which appears to result in a secondary block being associated with each explicit SQL*Plus block, that issues a call to GET_LINES to process buffered output.

PL/SQL Engine (__plsql_vm)
This function seems to correspond to external invocations of PL/SQL such as from a SQL*Plus session. There are 7 calls, 6 of them presumably being linked with the external anonymous blocks, and the seventh with DBFUNC, where a PL/SQL function is called from a SQL statement from SQL*Plus.

Notice that the SQL statement calling a database function from within PL/SQL generates the recursive call to the engine, __plsql_vm@1

Second Root (A_CALLS_B)
The above function does not have the __plsql_vm/__anonymous_block ancestry that might be expected because profiling only started within the enclosing block.

Inlined Procedure (Rest_a_While)
I wrote a small procedure, Rest_a_While, to generate some elapsed time in the recursive procedures, but preceded it with the INLINE pragma, a new optimisation feature in 11g. This had the desired effect of removing the calls from the profiling output and including the times in the calling procedures. Rest_a_While does not make the obvious call to DBMS_Lock.Sleep because that procedure cannot be inlined. subprogram inlining in 11g provides some analysis of the inlining feature.

Sibling Ordering
We have ordered siblings by descending subtree elapsed time, using the SEARCH clause. It would be nice to have the option to order the siblings by initial invocation time, but Oracle does not provide the data to do this.

Loops and Hierarchies
The first diagram shows two loops, where there are two routes between the loop start and end points, indicated by different colours. The second loop has two child nodes coming from the end point, and hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links to be duplicated. Our query has filtered out the duplicates by analytic functions.

It's worth remembering this because it's a general feature of SQL for querying hierarchies, and judging by Oracle forums, not one that's widely understood. For larger hierarchies it can cause serious performance problems, and may justify a PL/SQL programmed solution that need not suffer the same problem.

Manual Instrumentation
Oracle's hierarchical profiler clearly provides extremely useful information on both performance and structure of PL/SQL programs with very little effort. However, it does have the limitation of only providing information down to the subprogram level (which includes embedded SQL statements in this context). It is also often considered good practice to implement timing and other instrumentation permanently in production code, sometimes in a switchable fashion. In the test program, one of the called procedures, A_Calls_B, makes two calls to the inlined procedure, Rest_a_While, the second doing about twice as much work as the first. The profiler reports total within-function times of 4,450µs and 13,663µs on first and second calls, respectively (the work is scaled by a call number parameter, equal to 1, then 3).

I created a second instance of the package and driver script (suffix _TS) to illustrate manual instrumentation. This uses an 'object-oriented' timing package that I wrote a couple of years ago Code Timing and Object Orientation and Zombies (November, 2010) to instrument at procedure and section level. I multiplied the work in Rest_a_While by a factor of ten to get larger times. This produced the output:

Timer Set: HProf, Constructed at 05 Mar 2013 10:21:27, written at 10:21:30
==========================================================================
[Timer timed: Elapsed (per call): 0.04 (0.000044), CPU (per call): 0.05 (0.000050), calls: 1000, '***' denotes corrected line below]

Timer                       Elapsed          CPU          Calls        Ela/Call        CPU/Call
----------------------   ----------   ----------   ------------   -------------   -------------
A_Calls_B, section one         0.06         0.05              2         0.03150         0.02500
A_Calls_B, section two         0.12         0.12              2         0.06050         0.06000
B_Calls_A: 2                   0.15         0.16              1         0.15400         0.16000
B_Calls_A: 4                   0.31         0.30              1         0.30700         0.30000
DBFunc                         0.32         0.31              2         0.15950         0.15500
Open cursor                    0.69         0.69              1         0.68900         0.69000
Fetch from cursor              0.70         0.70              1         0.69600         0.70000
Close cursor                   0.00         0.00              1         0.00000         0.00000
Construct object               0.06         0.04              1         0.05500         0.04000
R_Calls_R                      0.14         0.14              2         0.07000         0.07000
(Other)                        0.00         0.00              1         0.00000         0.00000
----------------------   ----------   ----------   ------------   -------------   -------------
Total                          2.54         2.51             15         0.16960         0.16733
----------------------   ----------   ----------   ------------   -------------   -------------

Notes on Code Timing

  • Calls, CPU and elapsed times have been captured at the section level for A_Calls_B
  • Observe that, while R_Calls_R and A_Calls_B aggregate over all calls, B_Calls_A records values by call; this is implemented simply by including a value that changes with call in the timer name
  • The timing set object is designed to be very low footprint; here 9 statements (calls to Increment_Time), plus a small global overhead, produced 10 result lines, plus associated information
  • The 'object-oriented' approach allows multiple programs to be be timed at multiple levels, without interference between timings
  • There are Perl and Java implementations of this timing set object included in the Scribd article mentioned

Oracle's Flat Profiler (DBMS_Profiler)
The hierarchical profiler was introduced in v11.1, while prior to this there was a non-hierarchical profiler, DBMS_Profiler. This package still exists in v11: It is omitted from the advanced application developer's guide for v11, but is described in the packages and types manual (Oracle® Database PL/SQL Packages and Types Reference, 11g Release 2 (11.2)); also, SQL*Developer appears to support only the newer hierarchical verion (via right-click on a package). I thought it interesting to run the older version on the same test program (package Old_Test_Prof, driver script Test_Rep_p_Old.sql and reporting script Test_Rep_h_Old.sql). The output from the first three queries is:

Run header (PLSQL_PROFILER_RUNS)

     RUNID RUN_DATE        MICRO_S    SECONDS
---------- ------------ ---------- ----------
         3 11:03:13        2164000       2.16

Profiler data summary (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS
---------- ------- --------
   2126949    2.13       72

Profiler data by time (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
---------- ------- -------- -------------------- ----------- ------
    729932    0.73        1                                5     13
    569563    0.57        2 OLD_PROF_TEST                  1     56
    377880    0.38        2 OLD_PROF_TEST                  1     82
    166019    0.17        2 OLD_PROF_TEST                  1     70
    150117    0.15        2 OLD_PROF_TEST                  1     43
     72742    0.07        2 OLD_PROF_TEST                  1     40
     56473    0.06        1 TABLE_COUNT_TYPE               6      6
      3338    0.00        1                                5      8
       258    0.00        1                                5     12
       109    0.00        1                                5     16
        68    0.00        2 OLD_PROF_TEST                  1     67
        66    0.00        2                                4      1
        60    0.00        2                                7      1
        60    0.00        2                                3      1
        44    0.00        1                                5     14
        42    0.00        0                                2      5
        31    0.00        1 OLD_PROF_TEST                  1     18
        26    0.00        1                                8      5
        13    0.00        0                                5      1
         9    0.00        1 TABLE_COUNT_TYPE               6     11
         9    0.00        2 OLD_PROF_TEST                  1     86
         8    0.00        0 OLD_PROF_TEST                  1     51
         8    0.00        1 TABLE_COUNT_TYPE               6     13
         7    0.00        1                                5     18
         6    0.00        0 OLD_PROF_TEST                  1     78
         6    0.00        0 OLD_PROF_TEST                  1     64
         6    0.00        0                                8      1
         6    0.00        1 TABLE_COUNT_TYPE               6      3
         5    0.00        0 OLD_PROF_TEST                  1     35
         5    0.00        0 OLD_PROF_TEST                  1     15
         4    0.00        1                                8      7
         4    0.00        1 OLD_PROF_TEST                  1     76
         3    0.00        1                                2      8
         2    0.00        1 OLD_PROF_TEST                  1     62
         2    0.00        1 OLD_PROF_TEST                  1     13
         2    0.00        1 TABLE_COUNT_TYPE               6      5
         2    0.00        2 OLD_PROF_TEST                  1     72
         2    0.00        2 OLD_PROF_TEST                  1     45
         2    0.00        2 OLD_PROF_TEST                  1     49
         2    0.00        2 OLD_PROF_TEST                  1     46
         2    0.00        2 OLD_PROF_TEST                  1     58
         1    0.00        1 OLD_PROF_TEST                  1     73
         1    0.00        1                                2      6
         1    0.00        1 OLD_PROF_TEST                  1     59
         1    0.00        1 OLD_PROF_TEST                  1     11
         1    0.00        2 OLD_PROF_TEST                  1     54
         1    0.00        2 OLD_PROF_TEST                  1     84
         0    0.00        0 OLD_PROF_TEST                  1      1
         0    0.00        0 OLD_PROF_TEST                  1     88
         0    0.00        0                                8      9
         0    0.00        0                                2      1
         0    0.00        0                                2      2
         0    0.00        0 OLD_PROF_TEST                  1      3
         0    0.00        0 OLD_PROF_TEST                  1      5
         0    0.00        0 OLD_PROF_TEST                  1      9
         0    0.00        0 OLD_PROF_TEST                  1     20
         0    0.00        1 TABLE_COUNT_TYPE               6      4
         0    0.00        1                                8      2
         0    0.00        2 OLD_PROF_TEST                  1     39
         0    0.00        2 OLD_PROF_TEST                  1     55
         0    0.00        2 OLD_PROF_TEST                  1     69
         0    0.00        2 OLD_PROF_TEST                  1     38
         0    0.00        2 OLD_PROF_TEST                  1     81
         0    0.00        2 OLD_PROF_TEST                  1     42
         0    0.00        2 OLD_PROF_TEST                  1     68

65 rows selected.

Referring to the package, type and anonymous blocks, I assigned labels to all the lines having more than 10µs, as follows:

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
---------- ------- -------- -------------------- ----------- ------
    729932    0.73        1                                5     13  B2: FETCH
    569563    0.57        2 OLD_PROF_TEST                  1     56  B_Calls_A (Rest_a_While)
    377880    0.38        2 OLD_PROF_TEST                  1     82  DBFunc (Rest_a_While)
    166019    0.17        2 OLD_PROF_TEST                  1     70  R_Calls_R (Rest_a_While)
    150117    0.15        2 OLD_PROF_TEST                  1     43  A_Calls_B (Rest_a_While, section 2)
     72742    0.07        2 OLD_PROF_TEST                  1     40  A_Calls_B (Rest_a_While, section 1)
     56473    0.06        1 TABLE_COUNT_TYPE               6      6  SELECT
      3338    0.00        1                                5      8  B2: SELECT DBFunc
       258    0.00        1                                5     12  B2: OPEN
       109    0.00        1                                5     16  B2: Assign Table_Count_Type
        68    0.00        2 OLD_PROF_TEST                  1     67  Put_Line
        66    0.00        2                                4      1  Auxiliary SERVEROUTPUT block for B2 (surmised)
        60    0.00        2                                7      1  Auxiliary SERVEROUTPUT block for B3 (surmised)
        60    0.00        2                                3      1  Auxiliary SERVEROUTPUT block for B1 (surmised)
        44    0.00        1                                5     14  B2: CLOSE
        42    0.00        0                                2      5  B1: Call to Start_Profiling 
        31    0.00        1 OLD_PROF_TEST                  1     18  RETURN DBMS_Profiler.Stop_Profiler;
        26    0.00        1                                8      5  B3: Call R_Calls_R
        13    0.00        0                                5      1  B2: DECLARE

Notes on Output of Flat Profiler
There were six units with no linked information in DBMS_PROFILER_UNITS. By examining the data, I was able to associate unit numbers 2, 5 and 8 with my anonymous blocks B1, B2 and B3. That left three unassigned, and I have surmised that these correspond to the auxiliary blocks associated with processing server output that we earlier surmised when examining the output from the hierarchical profiler.

  • The useful call tree structure is not present in the data from the old profiler
  • However, the results are at a line level, which the hierarchical profiler does not provide; for example, the two sections of A_Calls_B are reported separately
  • Deciphering the output requires significantly more manual effort than with the hierarchical profiler
  • Both old and new profiler have their own advantages, and so both should be considered of value
  • Manual code timing offers more flexibility in terms of aggregating lines and call instances, but requires more effort...
  • ...but not as much as I thought. As noted later on the second example, after reading another article on the profiler, I realised that I could join the system table ALL_SOURCE to see the text of the line (where available)

Second example: Flat profiler omits some detail timings
After posting the first draft of this article, which was about the newer hierarchical profiler only, I noticed a new post on an old AskTom thread on the older flat profiler. The post concerned a discrepancy between reported times at the aggregate level and detail levels. I suggested using the hierarchical profiler might resolve the problem Try the hierarchical profiler..., and then added sections on the old profiler and on manual timing to this article for comparison. However, my example programs above do not include the AskTom scenario, so I later decided to add a new small scenario to illustrate it and now report the results here. The new test code consists of a PL/SQL block with two calls to DBMS_Lock.Sleep, for 3 and 6 seconds, with the profiling code around them. The driving scripts and output files are included in the zip file attached, and I list summary results below:

I later came upon another artilce on the flat profiler, Profiling PL/SQL with dbms_profiler where the author has joined the system table ALL_SOURCE to get the text of the line profiled, which makes interpretation easier. I have then updated the line-level query as follows:

PROMPT Profiler data by time (PLSQL_PROFILER_DATA)
SELECT Round (dat.total_time/1000, 0)  micro_s,
       Round (dat.total_time/1000000000, 2) seconds,
       dat.total_occur calls,
       unt.unit_name,
       dat.unit_number,
       dat.line#,
       Trim (src.text) text
  FROM plsql_profiler_data dat
  LEFT JOIN plsql_profiler_units unt
    ON unt.runid            = dat.runid
   AND unt.unit_number      = dat.unit_number
  LEFT JOIN all_source      src
    ON src.type             IN ('PACKAGE BODY','FUNCTION','PROCEDURE','TRIGGER')
   AND src.name             = unt.unit_name 
   AND src.line             = dat.line# 
   AND src.owner            = unt.unit_owner 
   AND src.type             = unt.unit_type
 WHERE dat.runid            = :runid
   AND dat.total_time       > 0
 ORDER BY 1 DESC, 2, 3

Of course the text is only available for stored source, so excludes lines from anonymous blocks.

Flat Profiler

Run header (PLSQL_PROFILER_RUNS)

     RUNID RUN_DATE        MICRO_S    SECONDS
---------- ------------ ---------- ----------
         5 20:34:45        9220000       9.22

Profiler data by unit (PLSQL_PROFILER_DATA)

UNIT_NAME            UNIT_NUMBER    MICRO_S SECONDS    CALLS
-------------------- ----------- ---------- ------- --------
                               2        200    0.00        3
UTILS                          1         30    0.00        3

Profiler data by time (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE# TEXT
---------- ------- -------- -------------------- ----------- ------ ------------------------------------------------
       136    0.00        1                     2      7
        21    0.00        1                     2     10
        19    0.00        1                     2     14
        14    0.00        0 UTILS                          1    343 FUNCTION Stop_D_Profiling RETURN PLS_INTEGER IS
        13    0.00        1 UTILS                          1    346 RETURN DBMS_Profiler.Stop_Profiler;
         6    0.00        1 UTILS                          1    341 END Start_D_Profiling;
         2    0.00        1 UTILS                          1    339 RETURN l_run_number;

7 rows selected.

Hierarchical Profiler

Run header (DBMSHP_RUNS)

     RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
---------- ---------------------------- ---------- ---------- -----------------------------
        16 19-MAR-13 21.37.00.571000       9000292          9 Profile for DBMS_Lock.Sleep

Functions called (DBMSHP_FUNCTION_INFO)

OWNER      MODULE               FUNCTION                LINE#      SUB_T      FUN_T  CALLS
---------- -------------------- ---------------------- ------ ---------- ---------- ------
BRENDAN    UTILS                1: STOP_H_PROFILING       322          8          8      1
SYS        DBMS_HPROF           2: STOP_PROFILING          59          0          0      1
SYS        DBMS_LOCK            3: SLEEP                  197    9000279    9000279      2
SYS        DBMS_LOCK            4: __pkg_init               0          5          5      1

Function call parent-child links (DBMSHP_PARENT_CHILD_INFO)

OWNER_P MODULE_P  FUNCTION_P            OWNER_C MODULE_C    FUNCTION_C         SUB_T FUN_T  CALLS
------- --------- --------------------- ------- ----------- ------------------ ----- ----- ------
BRENDAN UTILS     1: STOP_H_PROFILING   SYS     DBMS_HPROF  2: STOP_PROFILING      0     0      1

BPF Recursive Subquery Factor Tree Query

Function tree                              SUB_T      FUN_T  CALLS  Row
------------------------------------- ---------- ---------- ------ ----
3: SYS.DBMS_LOCK.SLEEP                   9000279    9000279      2    1
1: BRENDAN.UTILS.STOP_H_PROFILING              8          8      1    2
  2: SYS.DBMS_HPROF.STOP_PROFILING             0          0      1    3
4: SYS.DBMS_LOCK.__pkg_init                    5          5      1    4

Manual Profiler

Timer Set: Profiling DBMS_Lock.Sleep, Constructed at 19 Mar 2013 21:38:54, written at 21:39:03
==============================================================================================
[Timer timed: Elapsed (per call): 0.05 (0.000045), CPU (per call): 0.04 (0.000040), calls: 1000, '***' denotes corrected line below]

Timer               Elapsed          CPU          Calls        Ela/Call        CPU/Call
--------------   ----------   ----------   ------------   -------------   -------------
3 second sleep         3.00         0.00              1         3.00000         0.00000
6 second sleep         6.00         0.00              1         6.00100         0.00000
(Other)                0.00         0.00              1         0.00000         0.00000
--------------   ----------   ----------   ------------   -------------   -------------
Total                  9.00         0.00              3         3.00033         0.00000
--------------   ----------   ----------   ------------   -------------   -------------

Notes on Results for Second Example

  • The flat profiler shows 9s at header level but only 230µs at detail level because DBMS_Lock.Sleep does not permit profiling by the user running the script
  • The hierarchical profiler shows 9s at header level and a total of 9s in 2 calls to DBMS_Lock.Sleep
  • Manual profiling shows the two calls to DBMS_Lock.Sleep taking 3 and 6 seconds

Conclusions

  • Running Oracle's hierarchical profiler would seem to be the default first step in tuning PL/SQL programs from v11.1
  • Some care is needed in interpreting the output data; I've provided a query for displaying the hierarchies
  • Performance is recorded only down to function level, so it will still often be worthwhile to use the old flat profiler in addition
  • Manually timing code sections also still has a part to play, in terms of instrumentation and greater flexibility where necessary

Brendan HProf Code
Example 2






Data Structure Diagramming

Like many SQL developers I have always used entity-relationship diagrams to help in writing queries, and would extract sections to document them. Some years ago, however, I realised that having a single static diagram was not sufficient for complex queries with large numbers of tables, structures such as inline views, and multiple table instances. I therefore developed a diagram-based design methodology that I published in May 2009 on scribd. Since then I have extended the ideas in that approach to develop diagrams to cover various additional structures in SQL and in other areas. These diagrams were developed as needed for particular scenarios and have been published in several documents on scribd. I thought it would be a good idea to bring them together in one place, namely here, with example diagrams and the scribd document embedded thereafter. [Incidentally, I wonder what readers make of this 8-dimensional document structure?]

I would categorise them under four headings:

  • Entity-Relationship Diagrams
  • Structured Design Methodology
  • SQL Special Structures
  • Object Structures

Entity-Relationship Diagrams
Oracle Spatial Schema
The embedded document below also includes an ERD of the much simpler HR schema, but this one is more interesting as it shows extensive use of subtypes. The document is concerned with networks and I superimposed tree and non-tree network links on the diagram.

Oracle Customer Model and Multi-Org
Here I used shading to distinguish between org-striped, org-linked (my term) and other entities.

Structured Design Methodology
The methodology involves a sequence of diagrams and tables, so I have not extracted a diagram in this case.

SQL Special Structures
Multiple Table Instances with Scalar Subqueries in Where Clause
Subquery Factor

Selecting Database Function

Selecting Scalar Subqueries


Nested Analytics Subqueries

Model Clause

Recursive Subquery Factor

Object Structures
I use a different type of diagram for object structures from those for SQL and ERDs, and it's intended to be very general, being independent of programming language and applicable to any object structure, allowing arbitrary nesting of array and record types.
Code Timer Object
This object was implemented in three languages: Oracle, Perl and Java.


Excel Array Object
This object was implemented in Perl.