Based on a Presentation By Karen Morton, Oracle Performance Consultant

“If you can’t measure it, you can’t manage it.” -David Garvin

The hardest part is getting the “right” information by collecting properly scoped, un-aggregated profile data. This is where instrumentation comes in. Performance instrumentation is a little extra code that developers put into their PL/SQL applications that tells everyone — including the software developers themselves — exactly where your software is spending your time. With it, managing performance is a snap.

Good instrumentation makes it so normal people, not just specialists, can diagnose and solve performance problems quickly and permanently, often before your users even sense something is wrong. However, without good time-based performance instrumentation, managing performance becomes nightmarishly complex and expensive.

With as little as two lines of code you will be able to monitor specific tasks in your application and make one of the most difficult steps of implementing response-time based problem diagnosis (Method R) into one of the easiest. In addition, these techniques will enable you to correlate database statistics back to business tasks and help discover those tasks that are heavy resource consumers.

Let’s start by analyzing procedure p and see how it is running slow.   First, we have to define what is “slow”?

SQL> set timing on
SQL> exec p

PL/SQL procedure successfully completed.
Elapsed 00:02:09:98

Once we have our base timing, we open up our code and add some additional code to help us track timing within the routine itself.

create or replace procedure p as
t0 number;
t1 number;
t2 number;
t3 number;
begin
t0 := dbms_utility.get_time;
q;
t1 := dbms_utility.get_time ;
dbms_output.put_line (‘Procedure q: ‘ || to_char((t1 – t0)/100)); r;
t2 := dbms_utility.get_time ;
dbms_output.put_line (‘Procedure r: ‘ || to_char((t2 – t1)/100));
s;
t3 := dbms_utility.get_time ;
dbms_output.put_line (‘Procedure s: ‘ || to_char((t3 – t2)/100));
dbms_output.put_line (‘Total R : ‘ || to_char((t3 – t0)/100));
end;
/

Now that this additional code to help us get timing data for our procedure is in place, we can execute it again.

SQL> set timing on
SQL> exec p

Procedure q: 1
Procedure r: 114
Procedure s: 15
Total R : 130
Elapsed 00:02:09:99


What was the cost? Response time increased by .01 seconds (From 129.99 to 129.98) Code additions 4 Variable declarations and 8 lines of code These new lines of code are called performance instrumentation. With this data, we now know where to focus our attention.


Where would you start if you didn’t have this data? More importantly, what would happen if you started work on Procedure Q or S based on the times we collected?

Profiling is a requirement of good development hygiene. It makes your apps faster and cheaper.

Without profiling… With profiling…
• Can’t tell where time goes • Know where code spends time
• “Tune” everything you can • Optimize only relevant code path
• Learn about everything possible • Learn first in high-impact areas
• “Tuning” continues even when improvement is impossible • “Tuning” ceases when objective is achieved

Performance Instrumentation In Real Life

Instrumentation is important because it not only tracks and measures performance, but also measures the attributes of a system and creates monitoring mechanisms. Proper instrumentation is lightweight, easy to activate, leverages built-in functionality, and captures timings of business-critical tasks. Having it available allows your application to provide you with appropriately scoped trace data and more meaningful information through proper identification of each business task.

 

Compare These Two Graphs of Top Clients

 

or These Two Graphs of Top Actions

With instrumentation, we can easily answer questions like – “Why did this take so long?”, “What would happen if…?”, “Is this thing efficient?”, “Am I done yet?” Plus, instrumentation can provide the final word on disputes between DBAs, developers, managers, and users. So, the next logical question becomes, “How do I instrument my code?”

First, we are going to start with Oracle supplied packages – DBMS_SESSION, DBMS_APPLICATION_INFO, and DBMS_MONITOR.

Using DBMS_SESSION

DBMS_SESSION.set_identifier identifies the current session to make tracing easier. It lets the instance know which end users are on which connection.  Below, we manually set a friendly alias on a client id.

DBMS_SESSION.set_identifier (client_id => ‘jqpublic~ora11r1’)

A more practical option is having the system set the identifer based on a logon trigger.  This session information is already available from SYS_CONTEXT and you can pick from six different values for your identifer.

SYS_CONTEXT(‘USERENV’, ‘CLIENT_IDENTIFIER’) SYS_CONTEXT(‘USERENV’, ‘SERVICE_NAME’)
SYS_CONTEXT(‘USERENV’, ‘IP_ADDRESS’)
SYS_CONTEXT(‘USERENV’, ‘TERMINAL’)
SYS_CONTEXT(‘USERENV’, ‘OS_USER’)
SYS_CONTEXT(‘USERENV’, ‘SESSIONID’)

Below is an example of a procedure and its corresponding trigger that would automatically set the identifier.

create or replace procedure set_client_id
as
begin
dbms_session.set_identifier (
sys_context(‘userenv’,’os_user’));
end;

create or replace trigger set_client_id
after logon on database
begin
secuser.set_client_id;
end;

 

Once you have the identifier set, you can reference it in V$SESSION or almost 40 other views to track that session.

SELECT client_identifier, … FROM V$SESSION


Using DBMS_SYSTEM

Using DBMS_SYSTEM procedures, you can call ksdddt to write a date/time stamp while ksdwrt writes any message.

DBMS_SYSTEM.ksdddt
2008-10-02 15:36:51.314

DBMS_SYSTEM.ksdwrt (dest=>1,’Here I am!’)
Here I am!

Using DBMS_APPLICATION_INFO

You can use the DBMS_APPLICATION_INFO package to organize tasks into work units. The set_module procedure registers business tasks and related logical units of work. Calling the read_module determines current business task and logical unit of work while set_session_longops monitors the progress of long-running operations.

DBMS_APPLICATION_INFO.set_module( module_name=>’Order Entry’, action_name=>’Get Order Items’)

SELECT module, action, … FROM V$SESSION

SELECT module, action, … FROM V$SESSION_LONGOPS

…plus almost 40 other views

Using DBMS_MONITOR for SQL Tracing

You can use DBMS_MONITOR to start extended SQL tracing. Using any of the procedures below enables that level of trace activity.

  • client_id_trace_enable
  • database_trace_enable
  • session_trace_enable
  • serv_mod_act_trace_enable  (trace on a particular combination of service, module, and action)

DBMS_MONITOR.serv_mod_act_trace_enable( service_name=>’ora11r1′, module_name=>’Order Entry’, action_name=>’Get Order Items’)

The trace file generated will contain
*** ACTION NAME:(Get Order Items) 2008-10-02 01:48:56.573
*** MODULE NAME:(Order Entry) 2008-10-02 01:48:56.573

In addition to the trace file output, we can check the DBA_ENABLED_TRACES view to display enabled and disabled traces.

SELECT * FROM DBA_ENABLED_TRACES

TRACE_TYPE SERVICE_MODULE_ACTION
PRIMARY_ID ora11r1
QUALIFIER_ID1 Order Entry
QUALIFIER_ID2 Get Order Items
WAITS TRUE
BINDS TRUE
PLAN_STATS FIRST_EXEC
INSTANCE_NAME

 

Using DBMS_MONITOR to Gather Performance Statistics

In addition to traces, you can use DBMS_MONITOR to collect statistics based on either a client ID or a combination of service, module, action.  The client_id_stat_enable procedure enables statistics collection for all sessions with the specified client ID.  

DBMS_MONITOR. client_id_stat_enable (client_id => ‘jqpublic~ora11r1’)

Then, the resulting information is available under the V$CLIENT_STATS view.

SELECT * FROM V$CLIENT_STATS

 

CLIENT_IDENTIFIER STAT_NAME TIME_SECS
jqpublic~ora11r1 DB CPU .009
jqpublic~ora11r1 DB time .009
jqpublic~ora11r1 sql execute elapsed time .007
jqpublic~ora11r1 parse time elapsed .001


If we collect stats on a combination of service, module, and action instead of a client id, then we would use serv_mod_stat_enable instead.

DBMS_MONITOR.serv_mod_stat_enable (service_name=>’ora11r1′, module_name=>’Order Entry’, action_name=>’Get Order Items’)

Its output would be visible under the V$SERV_MOD_ACT_STATS view.

Placement of Instrumentation

Where should I place instrumentation?

  • Set the module and action below the “BEGIN” statement.
  • Update the module and action for any new business tasks.
  • Place above all “end” and “return” statements (set to null)
  • Place inside all “exception” handlers (set to null)
  • Avoid placing calls inside loops

Example…

PROCEDURE get_emp_simple_instr IS
    fnlist_stack fnlist_tab;
    lnlist_stack lnlist_tab;
BEGIN
DBMS_APPLICATION_INFO.set_module(module_name => ‘Human Resources’ ,action_name => ‘Get Employees’);

        SELECT first_name, last_name BULK COLLECT
INTO fnlist_stack, lnlist_stack
FROM employees;

    DBMS_APPLICATION_INFO.set_module(NULL, NULL);
EXCEPTION
    WHEN OTHERS THEN
        DBMS_APPLICATION_INFO.set_module(NULL, NULL);
DBMS_OUTPUT.PUT_LINE(‘HR_Package.get_emp_simple_instr => ERROR’); END get_emp_simple_instr;

08:00:00 MODULE = ‘Human resources’ Action = ‘get employees’
08:02:04 MODULE = null Action = null


PROCEDURE get_emp_jobs_instr_flawed IS
     jtlist_stack jtlist_tab;
     lnlist_stack lnlist_tab;
BEGIN
DBMS_APPLICATION_INFO.set_module(module_name => ‘Human Resources’, action_name => ‘Get Employees and Jobs’);

     get_emp_simple_instr;
        SELECT last_name, job_title
        BULK COLLECT
        INTO lnlist_stack, jtlist_stack
        FROM employees e, jobs j
        WHERE e.job_id = j.job_id;
     DBMS_APPLICATION_INFO.set_module(NULL, NULL);
EXCEPTION
WHEN OTHERS THEN
DBMS_APPLICATION_INFO.set_module(NULL, NULL);
DBMS_OUTPUT.PUT_LINE(‘get_emp_jobs_instr_flawed => ERROR’);

END get_emp_jobs_instr_flawed;

08:10:00 MODULE = ‘Human resources’ Action = ‘get employees and jobs’
08:12:04 MODULE = null Action = null
08:10:01 MODULE = ‘Human resources’ Action = ‘get employees’
08:13:32


Problems can occur when one similarly instrumented procedure calls another. Remember to store module and action in variables and “reset” as needed throughout the code.
PROCEDURE get_emp_instr_good IS
     fnlist_stack fnlist_tab;
     lnlist_stack lnlist_tab;
     preModuleName VARCHAR2(48) := NULL;
     preActionName VARCHAR2(32) := NULL;
BEGIN
     DBMS_APPLICATION_INFO.read_module( module_name => preModuleName, action_name => preActionName);
     DBMS_APPLICATION_INFO.set_module( module_name => ‘Human Resources’, action_name => ‘Get Employees’);
         SELECT first_name, last_name BULK COLLECT
         INTO fnlist_stack, lnlist_stack
         FROM employees;

     DBMS_APPLICATION_INFO.set_module( module_name => preModuleName, action_name => preActionName);
EXCEPTION
WHEN OTHERS THEN
DBMS_OUTPUT.PUT_LINE(‘HR_Package.get_emp_instr_good ERROR’);
DBMS_APPLICATION_INFO.set_module( module_name => preModuleName, action_name => preActionName);
END get_emp_instr_good;

Instrumentation Library for Oracle (ILO)

A free open source instrumentation package used to simplify the process of instrumenting your code. Its cost on every level is free, and the significant collateral benefits that can be achieved will make code instrumentation part of your coding standards. With ILO, there are three packages – ILO_TASK, ILO_TIMER, and ILO_SYSUTIL.

ILO requires Oracle version 9.2.0.1 or above and makes instrumenting code easy. It encapsulates and simplifies the use of DBMS_APPLICATION_INFO and DBMS_SESSION. ILO can be modified to meet your needs and is available for download from http://www.method-r.com or SourceForge.net.

Place the first call below the “BEGIN” statement

ILO_TASK.begin_task( module_name=>’Human Resources’, action_name=>’Get Employees’)
Change for any new business tasks
ILO_TASK.begin_task( module_name=>’Human Resources’, action_name=>’Get Jobs’)

Place End calls above all “end” and “Return” Statements and inside all “exception” handlers.

ILO_TASK.end_task

That’s it!  Below is our procedure, now reworked to use the ILO package.

PROCEDURE get_emp_instr_better IS
     fnlist_stack fnlist_tab;
     lnlist_stack lnlist_tab;
BEGIN
ILO_TASK.BEGIN_TASK(module_name => ‘Human Resources’ ,action_name => ‘Get Employees’);

        SELECT first_name, last_name BULK COLLECT
        INTO fnlist_stack, lnlist_stack
        FROM employees;
     ILO_TASK.END_TASK;
EXCEPTION
WHEN OTHERS THEN
DBMS_OUTPUT.PUT_LINE(‘get_emp_instr_better ERROR’);

     ILO_TASK.END_TASK;
END get_emp_instr_better;

Turning on trace using ILO

Activating trace is a run-time decision. The developer begins by adding BEGIN_TASK and END_TASK calls to the code. The DBA starts tracing with DBMS_MONITOR and the developer starts tracing with

ILO_TASK. SET_MARK_ALL_TASKS_INTERESTING (TRUE, TRUE)

 

Case Study

THE PROBLEM: Business critical task was taking 40 seconds, but the maximum tolerated execution time is 15 seconds. The team spent weeks searching for a root cause and fix. Task was a single PL/SQL package with 2,300 lines of code. Code was executed over 100 times per hour and running on Multi-node RAC. Trace collection was not very helpful due to improper scoping. Needed instrumentation to provide proper scoping. Code contained 36 business tasks, all marked with in-line comments.

THE SOLUTION: We used in-line comments to guide instrumentation with ILO. Spent 40 minutes to instrument 36 tasks. Instrumented code placed into production and tracing activated using DBMS_MONITOR for the instrumented module & actions.

Problem code was executed. Tracing deactivated and then the trace file was retrieved and profiled.


As you can see above, the majority of time was spent waiting for gc cr multi block request.

Further drilldown showed one insert statement and one delete statement to be the largest “R” contributors. Reviewed the insert statement

INSERT INTO MAA_TECH_SPEC_ANSWERS_DAT
(TS_ROW_SEQ, TS_STRUCT_ROW_SEQ, TS_OPTION_ROW_SEQ, TS_ANSWER_TEXT, GROUP_INDEX)
SELECT :B2, TS_STRUCT_ROW_SEQ, TS_OPTION_ROW_SEQ, TS_ANSWER_TEXT, GROUP_INDEX
FROM MAA_TECH_SPEC_ANSWERS_DAT
WHERE TS_ROW_SEQ = :B1

1) Noted excessive LIO
2) Plan showed use of full table scan

THE FIX ADDED INDEX ON TS_ROW_SEQ. Then, the problem code was executed and traced again.

Total measured task response time: R=t1-t0 = 10.118209 seconds
Oracle release 10.1.0.4.0
Oracle session id 78.41
Transactions 9 commits, 0 rollbacks
Errors and warnings 0 parse errors, 0 other errors, 0 Profiler kernel warnings
Service / module / action: ORCL10g / ConfigMove / Select Config Rec

New response time is around 10.118 seconds and it took us less than an hour to find and fix the problem.

SUMMARY

You should consider performance instrumentation any time there is code whose performance you might ever care about. Performance instrumentation matters because when it isn’t in place, managing performance is too complex and expensive.

How should performance instrumentation be done? By adding a few extra lines of code to register each business task. Performance doesn’t need to be hard. Let your software help you! It’s a mindless task your computer is willing to do for you . . . If you just ask it to.

Why guess? When you can know.


Karen Morton is an Independent Oracle Performance Consultant and Educator and previously served as the Director of Education for Method R Corporation. For over 20 years, Karen has worked in information technology starting out as a mainframe programmer and then growing and changing with the times to do development, DBA, and data architect work. She has been using Oracle since the early 90s and began teaching others how to use Oracle over a decade ago. She has authored several Oracle training coursebooks, including leading the development of the Hotsos/Method R SQL Optimization curriculum. In 2008, Oracle Corporation granted her the status of Oracle Ace.  She is also a member of the Oak Table Network and maintains a blog at http://karenmorton.blogspot.com.