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’) Below is an example of a procedure and its corresponding trigger that would automatically set the identifier. create or replace procedure set_client_id create or replace trigger set_client_id |
Once you have the identifier set, you can reference it in V$SESSION or almost 40 other views to track that 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.