Tuesday, 10 February 2009

Use of Bind Variables

What is bind variables?
A bind variable is simply a mechanism through which you can create a placeholder for a literal (constant) value within an SQL statement. For example, to retrieve the record for employee id is 198, 199, 200.... we can write SQL like:

SELECT first_name, last_name, email FROM employees WHERE employee_id = 199;
SELECT first_name, last_name, email FROM employees WHERE employee_id = 200;
SELECT first_name, last_name, email FROM employees WHERE employee_id = 201;

To use bind variable, we can use following instead:

SQL> variable emp_id number
SQL> exec :emp_id := 199

PL/SQL procedure successfully completed.

SQL> select first_name, last_name, email from employees where employee_id = :emp_id;

FIRST_NAME LAST_NAME EMAIL
-------------------- ------------------------- -------------------------
Douglas Grant DGRANT

SQL> exec :emp_id := 200

PL/SQL procedure successfully completed.

SQL> select first_name, last_name, email from employees where employee_id = :emp_id;

FIRST_NAME LAST_NAME EMAIL
-------------------- ------------------------- -------------------------
Jennifer Whalen JWHALEN

SQL>

Why use bind variables?
Every time we submit a brand new sql statement to the database , it must be parsed, qualified, security checked, optimized, and so on. All of these will consume a large amount of CPU. Hence, the fewer new SQL statements that are presented to the system, the better your system will scale and perform. To minimize the number of different SQL statements that are parsed by the database, we must make the use of bind variables. Let’s have a look at the next example. Here I created 2 procedures, proc1 is using bind variables and proc2 is not using bind variable.

drop table demo;
/
create table demo(x int);
/
create or replace procedure proc1 as
begin
for i in 1 .. 100000 loop
execute immediate 'insert into demo values (:x)'
using i;
end loop;
end;
/
create or replace procedure proc2 as
begin
for i in 1 .. 100000 loop
execute immediate 'insert into demo values ( ' || i || ')';
end loop;
end;
/

Now we use runstats package to compare the cost of above two procedures. For details on setting up runstats, please see my last post.

Connected to Oracle Database 10g Enterprise Edition Release 10.2.0.3.0
Connected as appuser

SQL> set serveroutput on size 100000;
SQL> exec runstats_pkg.rs_start

PL/SQL procedure successfully completed

SQL> exec proc1

PL/SQL procedure successfully completed

SQL> exec runstats_pkg.rs_middle

PL/SQL procedure successfully completed

SQL> exec proc2

PL/SQL procedure successfully completed

SQL> exec runstats_pkg.rs_stop

Run1 ran in 1637 hsecs
Run2 ran in 3180 hsecs
run 1 ran in 51.48% of the time

Name Run1 Run2 Diff
STAT...parse time elapsed 2 1,444 1,442
STAT...parse time cpu 1 1,481 1,480
STAT...Elapsed Time 1,638 3,181 1,543
STAT...DB time 261 1,851 1,590
STAT...recursive cpu usage 218 1,836 1,618
STAT...CPU used when call star 242 1,873 1,631
STAT...CPU used by this sessio 241 1,875 1,634
STAT...bytes received via SQL* 4,428 2,403 -2,025
LATCH.shared pool sim alloc 0 2,109 2,109
LATCH.messages 535 3,204 2,669
STAT...redo size 23,705,976 23,701,772 -4,204
LATCH.simulator lru latch 7,476 107,418 99,942
STAT...calls to get snapshot s 139 100,130 99,991
STAT...recursive calls 101,212 201,203 99,991
STAT...enqueue requests 56 100,049 99,993
STAT...enqueue releases 56 100,049 99,993
STAT...parse count (total) 53 100,048 99,995
STAT...parse count (hard) 10 100,007 99,997
LATCH.simulator hash latch 7,671 107,720 100,049
STAT...consistent gets 685 100,802 100,117
STAT...consistent gets from ca 685 100,802 100,117
STAT...db block gets 102,757 302,556 199,799
STAT...db block gets from cach 102,757 302,556 199,799
LATCH.enqueues 376 200,713 200,337
LATCH.enqueue hash chains 424 200,844 200,420
STAT...session logical reads 103,442 403,358 299,916
STAT...physical read bytes 32,768 352,256 319,488
STAT...physical read total byt 360,448 679,936 319,488
LATCH.kks stats 483 552,311 551,828
STAT...session pga memory 131,072 -458,752 -589,824
LATCH.library cache lock 456 600,524 600,068
LATCH.library cache pin 455 600,540 600,085
LATCH.cache buffers chains 511,275 1,111,634 600,359
LATCH.row cache objects 871 1,201,081 1,200,210
LATCH.shared pool simulator 60 1,792,124 1,792,064
LATCH.library cache 1,238 2,569,396 2,568,158
LATCH.shared pool 1,181 3,413,797 3,412,616

Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
545,818 12,481,378 11,935,560 4.37%

PL/SQL procedure successfully completed

SQL>

Now, you can see the proc1 is the clear winner, which took significantly less time to run also with much less latches.

When to use bind variables?
Do we need to use bind variables explicitly in our PL/SQL store procedures? The answer may surprise you? Most of time we don’t need to, because every reference to a PL/SQL variable is in fact a bind variable. This is just how PL/SQL works. Want a prove? Look at the next example:

create or replace procedure find_emp(p_empno in number) as
type rc is ref cursor;
l_cursor rc;
begin
open l_cursor for
select * from emp where empno = p_empno;
end;
/

Execute the procedure and trace the execution plan using TKPROF.

SQL*Plus: Release 10.2.0.3.0 - Production on Sun Feb 8 23:53:32 2009

Copyright (c) 1982, 2006, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set sql_trace = true;

Session altered.

SQL> exec find_emp(7839);

PL/SQL procedure successfully completed.

SQL> SELECT pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||
2 '_ora_' || p.spid || '.trc' AS trace_file
3 FROM v$session s,
4 v$process p,
5 v$parameter pa
6 WHERE pa.name = 'user_dump_dest'
7 AND s.paddr = p.addr
8 AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

TRACE_FILE
--------------------------------------------------------------------------------
D:\ORACLE\PRODUCT\10.2.0\ADMIN\ORCL\UDUMP/orcl_ora_4328.trc

SQL> alter session set sql_trace = false;

Session altered.

SQL>

Use TKPFRO generate SQL trace report: Please refer here for detail set up.

D:\> tkprof D:\ORACLE\PRODUCT\10.2.0\ADMIN\ORCL\UDUMP/orcl_ora_4328.trc d:\trcout.txt
Tkprof shows us:


SELECT *
FROM
EMP WHERE EMPNO = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.02 0 1 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.02 0 1 0 0

ALL plsql variable references were bound. However it is not always the case, the only time we need to specifically use bind variables is when you're putting together dynamic SQL. For example, when we put DML statement after ‘execute immediate’ in plsql program.

-- Not using Bind Variable. Hard parse required when exec the procedure each time
create or replace procedure no_bv(p_empno number) as
begin
execute immediate 'update emp set sal = sal*2 where empno = ' || p_empno;
end;
/
-- Bind Variable, no hard parse required
create or replace procedure bv(p_empno number) as
begin
execute immediate 'update emp set sal = sal*2 where empno = :x '
using p_empno;
end;
/

When not to use bind variables?
Every rule has its exception. In performance tuning world, nothing is absolute. In a data warehouse environment, it’s normal you would have a bunch of SQL queries which can take seconds or minutes or even hours to run, because most of data warehouse jobs are running over night, so nobody is actually waiting for the result of each query, users are waiting for all queries to finish getting the answer. In this scenario, the overhead of parsing time is a tiny propotion of the overall execution time. In data warehouse system, the goal is to get the best query optimization plan possible to reduce the runtime, not to execute as many queries as possible like we do in OLTP system. In this case, not to use bind variables could allow CBO to see actual literal so that it can come up with a optimal plan for your query.

Friday, 6 February 2009

Oracle Performance Analysis Tool – SQL_Trace and TKPROF

As a DBA/Developer we often hear users complaining that certain part of the web or desktop applications run too slow, it would be very helpful if we are able to trace an Oracle session to pinpoint the root cause. Here is when SQL_Trace and TKPROF utility come to play. Unlike switching on AUTOTRACE in sql plus to test a single query in isolation, TKPROF shows you a different set of data for all sql statments executed by your application as it runs.

What is SQL_Tace and TKPROF? In short SQL_TRACE is the used to write performance information on individual SQL statement down to trace files in the file system of the database server. These trace files are not in a proper readable format, for that reason we need TKPROF utility to transform the trace file into a text-based report for performance analysis.

To be able to run the following simulation test, we need to create a user and grant alter session directly to that user.

drop user demo cascade;
create user demo identified by demo;
grant connect, resource to demo;
grant alter session to demo;
grant all on plan_table to demo;
grant select on v_$session to demo;
grant select on v_$process to demo;
grant select on v_$parameter to demo;



Create a test table and a package to simulate a typical work load.

create table test
(
col1 varchar2(30)
);
/
CREATE OR REPLACE procedure simulate_workload_with_binds as
var1 varchar2(30);
begin
-- This parameter enables the collection of certain vital statistics
-- such as CPU execution time, wait events, and elapsed times.
execute immediate 'alter session set timed_statistics = true';
-- Set the maximum size of trace file as unlimited
execute immediate 'alter session set max_dump_file_size = unlimited';
-- Set a suffix of the trace file
execute immediate 'alter session set tracefile_identifier = ''test1_binds_single_process''';
-- turn on extended SQL tracing
execute immediate 'alter session set events ''10046 trace name context forever, level 8''';

-- main body of code
for c in 1 .. 500 loop
insert into test (col1) values (c);
commit;
end loop;
commit;

for c in 1 .. 50 loop
update test set col1 = col1;
commit;
end loop;

for c in 1 .. 500 loop
begin
select col1 into var1 from test where col1 = c;
exception
when others then
null;
end;
end loop;

for c in 1 .. 500 loop
insert into test (col1) values (c);
commit;
end loop;
commit;

for c in 1 .. 500 loop
delete from test where col1 = c;
commit;
end loop;
commit;
-- turn off extended SQL tracing
execute immediate 'alter session set events ''10046 trace name context off''';
end;

The trace files will be written into the directory pointed to by the parameter user_dump_dest. You can query for the value by issuing a following statement:

SELECT s.sid,
s.serial#,
pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||
'_ora_' || p.spid || '.trc' AS trace_file
FROM v$session s,
v$process p,
v$parameter pa
WHERE pa.name = 'user_dump_dest'
AND s.paddr = p.addr
AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

Use TKPROF utility to generate report:

D:\>tkprof D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_8288_test1_binds_single_process.trc d:\trcout.txt.

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 28 0.00 0.72 0 1 0 0
Execute 3625 0.48 0.47 0 3880 8123 27000
Fetch 545 0.10 0.07 0 3578 0 533
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4198 0.59 1.27 0 7459 8123 27533

Misses in library cache during parse: 18
Misses in library cache during execute: 16

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
undo segment extension 1 0.00 0.00
log file sync 1 0.00 0.00

17 user SQL statements in session.
17 internal SQL statements in session.
34 SQL statements in session.
********************************************************************************
Trace file: D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_8288_test1_binds_single_process.trc
Trace file compatibility: 10.01.00
Sort options: default

1 session in tracefile.
17 user SQL statements in trace file.
17 internal SQL statements in trace file.
34 SQL statements in trace file.
20 unique SQL statements in trace file.
5981 lines in trace file.
1 elapsed seconds in trace file.

A list of key elements to analyse TKPROF report:

1. Compare the number of parses to number of executions. A well-tuned system will have one parse per n executions of a statement and will eliminate the re-parsing of the same statement.

2. Search for SQL statements that do not use bind variables (:variable). These statements should be modified to use bind variables.

3. Identify those statements that perform full table scans, multiple disk reads, and high CPU consumption. These performance benchmarks are defined by the DBA and need to be tailored to each database. What may be considered a high number of disk reads for an OLTP application may not even be minimal for a data warehouse implementation.

Wednesday, 4 February 2009

Oracle Performance Analysis Tool – Runstats

A few years ago I learnt this package from Tom Kyte’s famous book, Expert one to one. The package has become as my first option when I need to benchmark a number of different solutions since then. Basically RUNSTATS is a simple test tool that allows comparison of two executions of code and displays the costs of each in terms of the elapsed time, session-level statistics (such as parse calls), and latching differences. The latter of these, latching, is the key piece of information that this tool provides.

In this entry I have included two quick demos on how to install and test RUNSTATS package in Oracle. My working environment is Oracle 10g release 2 on IBM AIX, my oracle client is SQL*Plus: Release 10.2.0.1.0 on Windows XP Proffessional Console.

Before we start to install the package, we need to make sure the user have access to V$STATNAME, V$MYSTAT, and V$LATCH. You must be granted direct SELECT privileges (not via a role) on SYS.V_$STATNAME, SYS.V_$MYSTAT, and SYS.V_$LATCH.

drop user demo cascade;
create user demo identified by demo;
grant connect, resource to demo;
grant create view to demo;
grant select on v_$statname to demo;
grant select on v_$mystat to demo;
grant select on v_$latch to demo;
grant select on v_$timer to demo;
conn demo/demo@orcl

What the following script do are:
- Create a view to gather the statistics
- Create a temporary table to store the statistics.
- Runstats package.

create global temporary table run_stats
( runid varchar2(15),
name varchar2(80),
value int )
on commit preserve rows;

create or replace view stats
as select 'STAT...' || a.name name, b.value
from v$statname a, v$mystat b
where a.statistic# = b.statistic#
union all
select 'LATCH.' || name, gets
from v$latch
union all
select 'STAT...Elapsed Time', hsecs from v$timer;

create or replace package runstats_pkg
as
procedure rs_start;
procedure rs_middle;
procedure rs_stop( p_difference_threshold in number default 0 );
end;
/

create or replace package body runstats_pkg
as

g_start number;
g_run1 number;
g_run2 number;

procedure rs_start
is
begin
delete from run_stats;

insert into run_stats
select 'before', stats.* from stats;

g_start := dbms_utility.get_time;
end;

procedure rs_middle
is
begin
g_run1 := (dbms_utility.get_time-g_start);

insert into run_stats
select 'after 1', stats.* from stats;
g_start := dbms_utility.get_time;

end;

procedure rs_stop(p_difference_threshold in number default 0)
is
begin
g_run2 := (dbms_utility.get_time-g_start);

dbms_output.put_line
( 'Run1 ran in ' || g_run1 || ' hsecs' );
dbms_output.put_line
( 'Run2 ran in ' || g_run2 || ' hsecs' );
dbms_output.put_line
( 'run 1 ran in ' || round(g_run1/g_run2*100,2) ||
'% of the time' );
dbms_output.put_line( chr(9) );

insert into run_stats
select 'after 2', stats.* from stats;

dbms_output.put_line
( rpad( 'Name', 30 ) || lpad( 'Run1', 12 ) ||
lpad( 'Run2', 12 ) || lpad( 'Diff', 12 ) );

for x in
( select rpad( a.name, 30 ) ||
to_char( b.value-a.value, '999,999,999' ) ||
to_char( c.value-b.value, '999,999,999' ) ||
to_char( ( (c.value-b.value)-(b.value-a.value)), '999,999,999' ) data
from run_stats a, run_stats b, run_stats c
where a.name = b.name
and b.name = c.name
and a.runid = 'before'
and b.runid = 'after 1'
and c.runid = 'after 2'
-- and (c.value-a.value) > 0
and abs( (c.value-b.value) - (b.value-a.value) )
> p_difference_threshold
order by abs( (c.value-b.value)-(b.value-a.value))
) loop
dbms_output.put_line( x.data );
end loop;

dbms_output.put_line( chr(9) );
dbms_output.put_line
( 'Run1 latches total versus runs -- difference and pct' );
dbms_output.put_line
( lpad( 'Run1', 12 ) || lpad( 'Run2', 12 ) ||
lpad( 'Diff', 12 ) || lpad( 'Pct', 10 ) );

for x in
( select to_char( run1, '999,999,999' ) ||
to_char( run2, '999,999,999' ) ||
to_char( diff, '999,999,999' ) ||
to_char( round( run1/run2*100,2 ), '99,999.99' ) || '%' data
from ( select sum(b.value-a.value) run1, sum(c.value-b.value) run2,
sum( (c.value-b.value)-(b.value-a.value)) diff
from run_stats a, run_stats b, run_stats c
where a.name = b.name
and b.name = c.name
and a.runid = 'before'
and b.runid = 'after 1'
and c.runid = 'after 2'
and a.name like 'LATCH%'
)
) loop
dbms_output.put_line( x.data );
end loop;
end;

end;
/

Compare the performance between the HEAP table and IOT table:

Connected to Oracle Database 10g Enterprise Edition Release 10.2.0.1.0
Connected as demo

SQL>
SQL> create table heap as select * from dual;

Table created
SQL> create table iot(dummy primary key)
2 organization index
3 as select * from DUAL;

Table created
SQL> analyze table HEAP compute statistics;

Table analyzed
SQL> analyze table IOT compute statistics;

Table analyzed
SQL> set serveroutput on size 1000000;
SQL> exec RUNSTATS_PKG.rs_start;

PL/SQL procedure successfully completed
SQL> declare
2 x varchar(1);
3 begin
4 for i in 1 .. 10000 loop
5 select dummy into x from heap;
6 end loop;
7 end;
8 /

PL/SQL procedure successfully completed
SQL> exec RUNSTATS_PKG.rs_middle;

PL/SQL procedure successfully completed
SQL> declare
2 x varchar2(1);
3 begin
4 for i in 1 .. 10000 loop
5 select dummy into x from iot;
6 end loop;
7 end;
8 /

PL/SQL procedure successfully completed
SQL> exec RUNSTATS_PKG.rs_stop;

Run1 ran in 151 hsecs
Run2 ran in 110 hsecs
run 1 ran in 137.27% of the time

Name Run1 Run2 Diff
LATCH.session timer 1 0 -1
LATCH.session allocation 3 2 -1
LATCH.session idle bit 38 37 -1
LATCH.library cache lock alloc 1 2 1
LATCH.simulator hash latch 2 3 1
LATCH.active checkpoint queue 1 0 -1
STAT...free buffer requested 5 6 1
STAT...calls to kcmgcs 4 5 1
STAT...calls to kcmgas 0 1 1
STAT...redo entries 9 10 1
STAT...redo ordering marks 0 1 1
LATCH.KWQP Prop Status 1 0 -1
LATCH.KMG MMAN ready and start 1 0 -1
LATCH.job_queue_processes para 1 0 -1
LATCH.OS process allocation 0 1 1
LATCH.channel operations paren 6 8 2
STAT...bytes received via SQL* 1,021 1,019 -2
STAT...session cursor cache hi 5 7 2
LATCH.bufq statistics 2 0 -2
LATCH.Memory Queue 2 0 -2
LATCH.kks stats 6 4 -2
LATCH.In memory undo latch 2 0 -2
LATCH.undo global data 0 2 2
LATCH.redo allocation 2 0 -2
LATCH.redo writing 1 3 2
LATCH.object queue header oper 9 7 -2
LATCH.simulator lru latch 1 3 2
STAT...db block changes 47 43 -4
STAT...enqueue releases 7 3 -4
STAT...enqueue requests 8 3 -5
STAT...consistent changes 37 32 -5
LATCH.kwqbsn:qsga 6 0 -6
LATCH.qmn task queue latch 6 0 -6
LATCH.active service list 7 0 -7
LATCH.library cache pin 20,116 20,109 -7
LATCH.Shared B-Tree 8 0 -8
LATCH.shared pool 10,081 10,073 -8
LATCH.messages 14 6 -8
STAT...db block gets from cach 39 30 -9
STAT...db block gets 39 30 -9
STAT...workarea memory allocat -14 -4 10
STAT...recursive cpu usage 58 46 -12
LATCH.row cache objects 21 33 12
LATCH.library cache lock 96 81 -15
LATCH.library cache 20,227 20,212 -15
STAT...CPU used when call star 64 48 -16
STAT...CPU used by this sessio 64 48 -16
STAT...undo change vector size 2,140 2,160 20
LATCH.checkpoint queue latch 9 32 23
LATCH.JS queue state obj latch 30 0 -30
STAT...DB time 156 116 -40
STAT...Elapsed Time 162 120 -42
STAT...redo size 2,892 2,940 48
LATCH.SQL memory manager worka 6 73 67
LATCH.enqueues 80 9 -71
LATCH.enqueue hash chains 79 8 -71
STAT...index scans kdiixs1 0 10,000 10,000
STAT...table scan rows gotten 10,000 0 -10,000
STAT...table scans (short tabl 10,000 0 -10,000
STAT...no work - consistent re 10,001 1 -10,000
STAT...shared hash latch upgra 0 10,000 10,000
STAT...table scan blocks gotte 10,000 0 -10,000
STAT...consistent gets from ca 30,009 10,010 -19,999
STAT...consistent gets 30,009 10,010 -19,999
STAT...calls to get snapshot s 30,005 10,004 -20,001
STAT...session logical reads 30,048 10,040 -20,008
LATCH.cache buffers chains 60,183 20,137 -40,046
STAT...session uga memory max 130,816 65,408 -65,408
STAT...session pga memory max 131,072 0 -131,072
STAT...session pga memory -196,608 0 196,608

Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
111,061 70,857 -40,204 156.74%

PL/SQL procedure successfully completed

SQL>

From the test result we can easily find out the IOT performs much less latching and runs a lot faster than the heap.

RUNSTATS is a very handy tool when we need to compare a number of different solutions. I recommend every Oracle DBA or developer have it installed in your environment.