Posted by: Serge Rielau
UPDATE: Feb 11, 2012
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:
- Where does time go within a routine or trigger?
Replace time with I/O or any other metric you are interested in.
- Once I know where time/I/O etc goes then how can I find the optimizer plan for the slow statement?
- 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
LINE NUM_EXEC TEXT TOTAL_TIME CPU_TIME ROWS_MODIFIED ROWS_READ ROWS_RETURNED
---- -------- ---------------------------------------- ---------- -------- ------------- --------- -------------
1 - create package body myPkg - - - - -
2 - is - - - - -
3 - procedure myProc(p1 in int, p2 in varc - - - - -
4 - is - - - - -
5 - v int; - - - - -
6 - begin - - - - -
7 - v := 10; - - - - -
8 1 insert into t select c1 from (values 0 0 99 0 0
9 1 select max(c1) into v from t; 0 0 0 357 1
10 - return v; - - - - -
11 - end; - - - - -
12 - - - - - -
13 - procedure myproc2(p1 in int, p2 in var - - - - -
14 - is - - - - -
15 - v int; - - - - -
16 - begin - - - - -
17 1 myproc(p1, p2); 2 0 0 6 1
18 1 insert into t values v; 0 0 1 0 0
19 - return v; - - - - -
20 - end; - - - - -
21 - end; - - - - -
22 - - - - - - -
Trace Example output
SQLCODE SQLSTATE TEXT
------- -------- --------------------------------------------------------------------------------------------------------------------------------------------
- INSERT INTO emp(name, salary, role, mgrid, numemp, numdirect) VALUES ('John CEO'
>SERGE.EMP_BEF_INS [ 4]: IF n.salary < minsalary(n.role) THEN
|-SERGE.MINSALARY{1}[ 4]: RETURN (SELECT min_sal FROM salaries WHERE role = minsalary.role);
|SERGE.EMP_BEF_INS [ 7]: IF NOT EXISTS(SELECT 1 FROM emp WHERE id = n.mgrid) AND n.mgrid IS NOT NULL THEN
|SERGE.EMP_BEF_INS [ 10]: CALL M.P2();
|>SERGE.M.P2{0} [ 16]: b := (SELECT 3 FROM SYSIBM.SYSDUMMY1);
||SERGE.M.P2{0} [ 17]: P;
||>SERGE.M.P{0} [ 7]: a := (SELECT 1 FROM SYSIBM.SYSDUMMY1);
||<SERGE.M.P{0} [ 8]: a := (SELECT 2 FROM SYSIBM.SYSDUMMY1);
|-SERGE.M.P2{0} [ 18]: b := (SELECT 4 FROM SYSIBM.SYSDUMMY1);
-SERGE.EMP_BEF_INS [ 11]: SET n.id = NEXT VALUE FOR empid;
100 02000 -SERGE.EMP_AFT_INS [ 6]: UPDATE emp SET numdirect = numdirect + 1 WHERE id = vmgrid;
- INSERT INTO emp(name, salary, role, mgrid, numemp, numdirect) VALUES ('Tracy', 6
>SERGE.EMP_BEF_INS [ 4]: IF n.salary < minsalary(n.role) THEN
|-SERGE.MINSALARY{1}[ 4]: RETURN (SELECT min_sal FROM salaries WHERE role = minsalary.role);
|SERGE.EMP_BEF_INS [ 7]: IF NOT EXISTS(SELECT 1 FROM emp WHERE id = n.mgrid) AND n.mgrid IS NOT NULL THEN
|SERGE.EMP_BEF_INS [ 10]: CALL M.P2();
|>SERGE.M.P2{0} [ 16]: b := (SELECT 3 FROM SYSIBM.SYSDUMMY1);
||SERGE.M.P2{0} [ 17]: P;
||>SERGE.M.P{0} [ 7]: a := (SELECT 1 FROM SYSIBM.SYSDUMMY1);
||<SERGE.M.P{0} [ 8]: a := (SELECT 2 FROM SYSIBM.SYSDUMMY1);
|-SERGE.M.P2{0} [ 18]: b := (SELECT 4 FROM SYSIBM.SYSDUMMY1);
SQLCODE SQLSTATE TEXT
------- -------- --------------------------------------------------------------------------------------------------------------------------------------------
-SERGE.EMP_BEF_INS [ 11]: SET n.id = NEXT VALUE FOR empid;
>SERGE.EMP_BEF_INS [ 4]: IF n.salary < minsalary(n.role) THEN
|-SERGE.MINSALARY{1}[ 4]: RETURN (SELECT min_sal FROM salaries WHERE role = minsalary.role);
|SERGE.EMP_BEF_INS [ 7]: IF NOT EXISTS(SELECT 1 FROM emp WHERE id = n.mgrid) AND n.mgrid IS NOT NULL THEN
|SERGE.EMP_BEF_INS [ 10]: CALL M.P2();
|>SERGE.M.P2{0} [ 16]: b := (SELECT 3 FROM SYSIBM.SYSDUMMY1);
||SERGE.M.P2{0} [ 17]: P;
||>SERGE.M.P{0} [ 7]: a := (SELECT 1 FROM SYSIBM.SYSDUMMY1);
||<SERGE.M.P{0} [ 8]: a := (SELECT 2 FROM SYSIBM.SYSDUMMY1);
|-SERGE.M.P2{0} [ 18]: b := (SELECT 4 FROM SYSIBM.SYSDUMMY1);
-SERGE.EMP_BEF_INS [ 11]: SET n.id = NEXT VALUE FOR empid;
>SERGE.EMP_AFT_INS [ 6]: UPDATE emp SET numdirect = numdirect + 1 WHERE id = vmgrid;
| [ 8]: UPDATE emp SET numemp = numemp + 1 WHERE id = vmgrid;
<SERGE.EMP_AFT_INS [ 9]: SELECT mgrid INTO vmgrid FROM emp WHERE id = vmgrid;
>SERGE.EMP_AFT_INS [ 6]: UPDATE emp SET numdirect = numdirect + 1 WHERE id = vmgrid;
| [ 8]: UPDATE emp SET numemp = numemp + 1 WHERE id = vmgrid;
<SERGE.EMP_AFT_INS [ 9]: SELECT mgrid INTO vmgrid FROM emp WHERE id = vmgrid;
Installation
To install this profiler the following pre-requisites must be in place:
- 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.
- You need a USER TEMPORARY TABLESPACE or SYSCTRL or SYSADM authority to create one
- Authority to create a tablespace
- You need IMPLICIT SCHEMA privileges if you plan to place the library in a new schema or CREATEIN privilege to reuse an existing schema
- 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:
- From a shell or db2cmd window in Windows connect to your database using
db2 connect to
- Set the schema where you want to deploy the profiler
db2 set schema
- 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:
- Run the appropriate procedure
Note that there is no need to have the object to be explained shredded
- 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 plsqlpackageschema VARCHAR(128),
IN plsqlpackagename 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 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.
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)
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
variable
This 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.
#Db2