Reality Check: SQL PL Profiler and plan explain with actual row counts

I have added a TRACE procedure and renamed ENABLE/DISABLE_EXPLAIN_ACTUALS to ENABLE/DISABLE_ACTIVITY_MONITOR.
The TRACE procedure returns a formatted trace of all SQL monitored by the activity monitor.
This includes nested compiled triggers, procedure calls and function invocations as well as error conditions. 
Next on my list: trace-backs for errors and also tracing of parameters. 

 For the past months I have been tinkering on and of with the "new monitoring API" which has been introduced in DB2 9.7.

Here are the questions I wanted to get answers by system monitoring:

• Why is my procedure, function, trigger, program slow?
• Why is this query slow?

Of course there are many reasons why some routine or query can be slow, but in order to get to the "next steps" some information must be gathered:

1. Where does time go within a routine or trigger?
   Replace time with I/O or any other metric you are interested in.
2. Once I know where time/I/O etc goes then how can I find the optimizer plan for the slow statement?
3. How do I know whether the optimizer was making decision on reasonable assumptions?
   That is, if the optimizer thought a predicate would filter out 99% of the rows did it even get close?

So, I have developed a PROFILER module for DB2:
Overview

• Profile
  Given a:
  • SQL Procedure
  • compiled SQL Function
  • compiled Trigger
  • PL/SQL Package
  • Source code with DB2 Package
  provide annotated source showing:
  • Number of executions of the SQL statements within the object
  • Total execution time of the statement
  • CPU time
  • Number of rows fetched, read, written
  • Any other metrics that may be of interest 
     
• Explain
  Given a line number in the source code of any of the above statements provide the db2exfmt statement needed to display the optimizer plan. You can also get explains for all SQL in a routine or trigger, or all routines or triggers in a schema and so on.
  
  
• Find Origin
  Given a package and section number, or an executable id find the source code which produced the section
  This is an important feature to track expensive SQL statement seen in monitoring functions back to their origin
  
  
• Verify Optimizer plans
  Given an SQL statement, execute the statement, collect runtime information and provide the db2exfmt statement needed  to display the optimizer plan along with the so-called "section actuals" that is the number of rows that have been processed by the individual optimizer plan operators.
  Even better, choose an application by id, and retrieve section actuals for all SQL statements executed during the monitoring period.
  
  
• Trace SQL Execution
   Given a raw trace from the activity monitor which is started using this module against any application id, you can get a formatted trace telling you exactly who called whom and where.
  You will also find it easy to understand where errors originated.
  
  
• Binding made easy
  Bind all routines in a module, a schema or just a singel routine. Do the same with trigger. Or, even better, give DB2 a list of table you have updated statics on and let it find and rebind the related SQL routines and triggers.

Profile Example output

Trace Example output 

Installation

To install this profiler the following pre-requisites must be in place:

1. You need to use DB2 9.7 FP1 or higher
   In general for any enablement you should always use the latest fixpack to benefit from improvements in the area of PL/SQL.
2. You need a USER TEMPORARY TABLESPACE or SYSCTRL or SYSADM authority to create one
3. Authority to create a tablespace
4. You need IMPLICIT SCHEMA privileges if you plan to place the library in a new schema or CREATEIN privilege to reuse an existing schema
5. You need EXECUTE privilege on the EXPLAIN_FROM_CATALOG() table function, EXPLAIN_FROM_ACTIVITY procedure as well as EXPLAIN authority

Now for the actual installation:

1. From a shell or db2cmd window in Windows connect to your database using
   db2 connect to
2. Set the schema where you want to deploy the profiler
   db2 set schema
3. Execute the attached SQL PL and PL/SQL Profiler and Tracer  script
   db2 -tvf profiler.sql

Profiling

• Profile a SQL Procedure or compiled SQL FunctionPROFILE.ROUTINE (IN routineschema VARCHAR(128), IN routinemodulename VARCHAR(128) DEFAULT NULL, IN specificname VARCHAR(128))This procedure returns a result set that consists of the source code of the function or procedure annotated with key performance information for each line of SQL within the procedure such as execution time, number of executions, number of rows read, modified and returned.
  All information is relative to the executions since the objects was added to DB2's cache.
  
  Example:
  

  CALL PROFILE.ROUTINE('MYSCHEMA', NULL, 'MYFUNC5')

• Profile a compiled triggerPROFILE.TRIGGER (IN triggerschema VARCHAR(128), IN triggername VARCHAR(128))This procedure returns a result set that consists of the source code of the trigger annotated with key performance information for each line of SQL within the trigger such as execution time, number of executions, number of rows read, modified and returned.
  All information is relative to the executions since the object was added to DB2's cache.
  
  Example:
  

  CALL PROFILE.TRIGGER('MYSCHEMA", 'MYTRIGGER')

• Profile a PL/SQL package bodyPROFILE.PLSQLPACKAGE (IN plsqlpackageschema VARCHAR(128), IN plsqlpackagename VARCHAR(128))This procedure returns a result set that consists of the source code of the PL/SQL package body annotated with key performance information for each line of SQL within the package such as execution time, number of executions, number of rows read, modified and returned.
  All information is relative to the executions since the object was added to DB2's cache.
  
  Example:
  

  CALL PROFILE.PLSQLPACKAGE('MYSCHEMA", 'MYPACKAGE')

• PROFILE.EXTERNAL_SOURCE
  

  (IN source CLOB(2M), IN packageschema VARCHAR(128), IN packagename VARCHAR(128))

  
  This procedure returns a result set that consists of the source code provided by the user annotated with key performance information for each line of SQL within the source such as execution time, number of executions, number of rows read, modified and returned.
• All information is relative to the executions since the object was added to DB2's cache. 
  
  Example:
  

  CALL PROFILE.EXTERNAL_SOURCE(sourcecode, 'MYSCHEMA", 'MYPACKAGE')

Explain Plan

All explain procedures return the text for the db2exfmt command to run in order to get a pretty-printed optimizer plan from the gathered explain.
So each explain is a two stage event:

1. Run the appropriate procedure
   Note that there is no need to have the object to be explained shredded
2. Execute the returned command from a shell.
   The command as generated will store the plan in a file in the current working directory, so best cd to an appropriate directory before running db2exfmt.

• Explain a compiled statement within a SQL Procedure or functionPROFILE.EXPLAIN_ROUTINE_STATEMENT 
  

  (IN routineschema     VARCHAR(128),
  IN routinemodulename VARCHAR(128) DEFAULT NULL,
  IN specificname      VARCHAR(128) DEFAULT NULL,
  IN line_number       INTEGER      DEFAULT NULL,
  OUT db2exfmtcommand  VARCHAR(256) ARRAY[])

  This procedure extracts the explain information for the SQL statements of a routine at the specified line number.
  It returns the db2exfmt command required for pretty printing that information.
  For a global SQL PL or PL/SQL routine leave the routinemodulename NULL 
  For SQL PL routines make sure to pass the unique specific name of the routine.
  By ommitting the line_number, specificname or routinemodulename you can get plans for all statements in the routine, module or schema respectively.
  
  Example:
  

  CALL PROFILE.EXPLAIN_ROUTINE_STATEMENT('MYSCHEMA', NULL, 'MYPROC5', 17, ?)

• Explain a compiled statement in a triggerPROFILE.EXPLAIN_TRIGGER_STATEMENT 
  

  (IN triggerschema VARCHAR(128), IN triggername VARCHAR(128) DEFAULT NULL, IN line_number INTEGER DEFAULT NULL, OUT db2exfmtcommand VARCHAR(256) ARRAY[])

  This procedure extracts the explain information for the SQL statement of a compiled trigger at the specified line number.
  It returns the db2exfmt command required for pretty printing that information.
  By ommitting the line_number or triggername you can retriev the plans for all statements in the trigger or all triggers in the schema.
  
  Example:
  

  CALL PROFILE.EXPLAIN_TRIGGER_STATEMENT('MYSCHEMA', 'MYTRIGGER', 23, ?)

• Explain a compiled statement in a PL/SQL package bodyPROFILE.EXPLAIN_PLSQLPACKAGE_STATEMENT
  

  (IN  PKGSCHEMA      VARCHAR(128),
  IN  PKGNAME        VARCHAR(128),
  IN  SECTNO         INTEGER,
  OUT OBJECTSCHEMA   VARCHAR(128),
  OUT OBJECTMODULE   VARCHAR(128),
  OUT OBJECTNAME     VARCHAR(128),
  OUT OBJECTSPECIFIC VARCHAR(128),
  OUT OBJECTTYPE     VARCHAR(15),
  OUT LINE           INTEGER)

  This procedure extracts the explain information for the SQL statement of a PL/SQL package body at the specified line number.
  It returns the db2exfmt command required for pretty printing that information.
  By ommitting the line_number or plsqlpackagename you can retrieve all plans for a package or all packages within a schema.
  
  Example:
  

  CALL PROFILE.EXPLAIN_PLSQLPACKAGE_STATEMENT('MYSCHEMA', 'MYPACKAGE', 250, ?)

Find Origin

• Map a section in a DB2 package to a an object and line numberPROFILE.SECTION2OBJECT
  

  (IN  PKGSCHEMA      VARCHAR(128),
  IN  PKGNAME        VARCHAR(128),
  IN  SECTNO         INTEGER,
  OUT OBJECTSCHEMA   VARCHAR(128),
  OUT OBJECTMODULE   VARCHAR(128),
  OUT OBJECTNAME     VARCHAR(128),
  OUT OBJECTSPECIFIC VARCHAR(128),
  OUT OBJECTTYPE     VARCHAR(15),
  OUT LINE           INTEGER)

  Given a package schema, name and section number this procedure returns the SQL PL or PL/SQL objcet schema, module, name and line number originating the section.
  If the origin is not PL/SQL or SQL PL, but e.g. embedded C then it will only return the line-number.

• (IN EXECUTABLE_ID VARCHAR(32) FOR BIT DATA,
  OUT OBJECTSCHEMA VARCHAR(128),
  OUT OBJECTMODULE VARCHAR(128),
  OUT OBJECTNAME VARCHAR(128),
  OUT OBJECTSPECIFIC VARCHAR(128),
  OUT OBJECTTYPE VARCHAR(15),
  OUT LINE11 INTEGER)

  
  Example:
  

  CALL PROFILE.SECTION2OBJECT('MYSCHEMA', 'P12345678')

• Map a section in a DB2 package to a an object and line numberPROFILE.XID2OBJECT 
  

  (IN  EXECUTABLE_ID  VARCHAR(32) FOR BIT DATA,
  OUT OBJECTSCHEMA   VARCHAR(128),
  OUT OBJECTMODULE   VARCHAR(128),
  OUT OBJECTNAME     VARCHAR(128),
  OUT OBJECTSPECIFIC VARCHAR(128),
  OUT OBJECTTYPE     VARCHAR(15),
  OUT LINE11 INTEGER)

  OUT LINE11 INTEGER)Given an executable_id this procedure returns the SQL PL or PL/SQL object schema, module, name and line number originating the section. If the origin is not PL/SQL or SQL PL, but e.g. embedded C then it will only return the line-number.
  
  Example
  

  CALL PROFILE.XID2OBJECT(x'01000000000000006A0100000000000001000000010020110720144621750006', ?, ?, ?, ?, ?, ?, ?)

Query Actuals and Tracing

• Execute a dynamic SQL Statement and collect "section actuals"PROFILE.GET_ACTUALS  
  

  (IN stmt_text CLOB(2M), OUT db2exfmtcommand VARCHAR(256))

  The procedure executes an SQL statement (MERGE, INSERT, UPDATE, DELETE, SELECT, or VALUES) and then collects so called "section actuals" for that that statement.
  It then provides the db2exfmt command needed to retrieve the optimizer plan annotated with the number of rows which have actually passed individual plan operators.
  This procedure allows the user to see where an the optimizer made assumptions which do not match reality.
  
  Example:
  

  (CALL PROFILE.GET_ACTUALS('SELECT * FROM SYSCAT.COLUMNS WHERE COLNAME = ''ROUTINENAME''", ?)

• PROFILE.APPL_ID variableThis module variable by default is set to the applicatuon id of the current session (the result of MON_GET_APPLICATION_ID()). To set the default session for actuals monitoring to another session set this variable to teh desired sessions application id, e.g. using LIST APPLICATIONS. 
  
  Example:
  

  SET PROFILE.APPL_ID = MON_GET_APPLICATION_ID()

• PROFILE.ENABLE_ACTIVITY_MONITOR(APPL_ID VARCHAR(256) DEFAULT PROFILE.APPL_ID)This procedure turns on the activity monitor for the specified application so actual cardinalities are being collected for plans being executed in that session. If no application id is provided the value from the PROFILE.APPL_ID is used. The provided appl_id becomes the new setting for PROFILE.APPL_ID 
  
  Example:
  

  CALL PROFILE.ENABLE_ACTIVITY_MONITOR()

• PROFILE.DISABLE_ACTIVITY_MONITOR()This procedure turns the activity monitor for the currently monitored application off. 
  
  Example:
  

  CALL PROFILE.DISABLE_ACTIVITY_MONITOR()

• PROFILE.GET_ACTIVITY_ACTUALS(OUT DB2EXFMT_COMMAND VARCHAR(2048) ARRAY[])This procedure returns an array of db2exfmt commands for all SQL statements executed dynamically or as static SQL within procedural logic while explain actuals were enabled. The db2exfmt statements can then be run form a shell to produce optimizer plans with plan actuals information. 
  
  Example:
  

  CALL PROFILE.ENABLE_ACTIVITY_MONITOR()

   ... execute workload in this session or the session set in the PROFILE.APPL_ID variable... CALL PROFILE_DISABLE_ACTIVITY_MONITOR() CALL PROFILE.GET_ACTIVITY_ACTUALS(?)
  
• PROFILE.TRACE()This procedure returns a resultset which is a formatted trac eof all SQL that has been executed while the activity monitor has been enabled. When nested objects such as triggers or routines are entered indentation is used to denote deeper nesting and line numbers are displayed along with the line of source being executed. Any non-zero SQLCODEs are also displayed. 
  
  Example:
  

  CALL PROFILE.ENABLE_ACTIVITY_MONITOR() ... execute workload in this session or the session set in the PROFILE.APPL_ID variable... CALL PROFILE_DISABLE_ACTIVITY_MONITOR() CALL PROFILE.TRACE()

Binding Routines and Triggers

• PROFILE.REBIND_ROUTINE (IN ROUTINESCHEMA VARCHAR(128), IN ROUTINEMODULE VARCHAR(128) DEFAULT NULL, IN SPECIFICNAME VARCHAR(128) DEFAULT NULL, IN OPTIONS VARCHAR(256) DEFAULT NULL)This routine rebinds the DB2 Package belonging to the specified routine. If the name is ommitted all routines in the module (or PL/SQL Package) are rebound. If neither module nor name are specified all routines in the schema are rebound. With options you can specify BIND options such as STATICREADONLY. 
  
  Example:
  

  CALL PROFILE.REBIND_ROUTINE('MYSCHEMA", 'MYMODULE', 'PROC3')

• PROFILE.REBIND_TRIGGER (IN TRIGSCHEMA VARCHAR(128), IN TRIGNAME VARCHAR(128) DEFAULT NULL, IN OPTIONS VARCHAR(256) DEFAULT NULL)This routine rebinds the DB2 Package belonging to the specified trigger. If the name is ommitted all triggers in the schema are rebound. With options you can specify BIND options such as STATICREADONLY. 
  
  Example:
  

  CALL PROFILE.REBIND_TRIGGER('MYSCHEMA", 'TRIG4')

• PROFILE.REBIND_AFFECTED(IN TABLES VARCHAR(128) ARRAY[])This routine rebinds the DB2 Packages for all SQL routines and triggers which depend on the set of tables provided. Thsi routine is used after running a series of runstats or adding indexes to a set of tables. The routine returns a resultset listing all the objects that have been rebound. 
  
  Example:
  

  CALL PROFILE.REBIND_AFFECTED(ARRAY['MYSCHEMA.T', 'HISSCHEMA.S'])

Explain tables

• PROFILE.CREATE_EXPLAIN_TABLES(IN SCHEMA VARCHAR(128) DEFAULT SESSION_USER)This routine creates the explain tables in the specified schema. If no schema is provided they are created in the schema of the current session user. 
  
  Example:
  

  CALL PROFILE.DROP_EXPLAIN_TABLES('MYSCHEMA')

• PROFILE.CREATE_EXPLAIN_TABLES(IN SCHEMA VARCHAR(128) DEFAULT SESSION_USER)This routine drops the explain tables in the specified schema. If no schema is provided they are dropped from the schema of the current session user.
  
  Example:
  

  CALL PROFILE.CREATE_EXPLAIN_TABLES('MYSCHEMA')

• PROFILE.CLEAR_EXPLAIN_TABLES(IN SCHEMA VARCHAR(128) DEFAULT SESSION_USER)This routine empties the explain tables in the specified schema. If no schema is provided the explain information in the explain tables for the current session user is deleted.
  
  Example:
  

  CALL PROFILE.CLEAR_EXPLAIN_TABLES('MYSCHEMA')

Limitations

At this point the profiling part of this module relies on the global package cache instead of an event monitor.
That is the profiling information includes all data since the object was executed the first time and until it gets evicted from cache. 
At some point in the future I hope to update this module to provide profiling for a specific connection.
Also adding tracing with values may be of interest. Right now the tracer doe snot display parameters being passed.

Lastly note that optimizer procedural logic which executes fully within the Procedure Virtual Machine (PVM) is neither profiled, nor traced.

The good news is that these statements are so fast that they are typically not relevant.