ORA-01031: insufficient privileges
Robert, November 05, 2003 - 6:26 pm UTC
Tom,
I want to try out tracing & tkprof HTML DB this way....
FLOWS schema flows_010309 has been granted "alter session" & "create any trigger"
SQL> connect flows_010309@rcdb
Enter password:
Connected.
SQL> create or replace trigger login_trigger
2 after logon on database
3 begin
4 execute immediate 'alter session set sql_trace=true';
5 end;
6 /
after logon on database
*
ERROR at line 2:
ORA-01031: insufficient privileges
What privileges are missing ?
Thanks
is there a traceonly for sql_trace?
streve, January 30, 2004 - 9:31 am UTC
Hi Tom,
In Sql-trace, how not to display query result on the screen but show all statistics and execution plan?
just like in autotrace, we can set traceonly?
Thanks!
Steve
January 30, 2004 - 9:39 am UTC
you can either:
alter session set sql_trace=true;
set termout off
run queries here
set termout on
exit
OR
set autotrace traceonly
alter session set sql_trace=true;
run queries here
to surpress SQL*Plus from printing data on the screen. (if you use set termout off -- make sure you are using a script -- it surpresses scripted output only)
sql_trace speeds things up?!
VA, December 02, 2005 - 9:19 pm UTC
I have a procedure that normally takes a second or so to execute
Today when I did
SQL> exec foo('xyz')
it had taken 2 minutes and still not completed. So I did a Ctrl+C to terminate it and thought I would do a sql_trace to see what it was doing.
So, I exited the session, came back in again and did
SQL> alter session set sql_trace=true;
Session altered.
SQL> exec foo('xyz')
This time it came back in a second!
This is so bizarre, I cant imagine why turning on sql trace would change the behaviour of the procedure this way.
I did this 10 more times, logging out/in each time, just to be sure I was not imagining it. The same result every time...slow without sql_trace, fast with it.
There is nothing going on in the database, no locking, no activity, nothing.
Can you think of any reason that would explain this?
December 03, 2005 - 10:27 am UTC
In fact, not only do I know why - I demonstrate this EXACT case in my "all about binds" presentation. I say "and now I will show you how to tune with SQL_TRACE=true. you are all probably thinking 'he will turn on trace, get a tkprof, tune a query - borrriiinnngg'. But no, that is not what I will do, simply by turning in SQL_TRACE=TRUE, I will make a query run faster - without it, it will run slower"
"bind variable peeking" is the reason. the 10046 (sql_trace=true) will create a child cusor, which can be shared by all other trace sessions, but it will be a child cursor. that sql_trace=true is enabled is like changing an optimizer setting, it creates a new environment and causes a hard parse.
the qery that is executing "poorly" is only executing poorly for the GIVEN bind you are using, for some other binds - it is the best plan in the world.
example:
ops$tkyte@ORA9IR2> drop table t;
Table dropped.
ops$tkyte@ORA9IR2> create table t
2 as
3 select 99 id, a.* from all_objects a;
Table created.
ops$tkyte@ORA9IR2> update t set id = 1 where rownum = 1;
1 row updated.
ops$tkyte@ORA9IR2> create index t_idx on t(id);
Index created.
ops$tkyte@ORA9IR2> exec dbms_stats.gather_table_stats( user, 'T', method_opt => 'for all indexed columns size 254', cascade=> true);
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> connect / as sysdba
Connected.
ops$tkyte@ORA9IR2> startup force
ORACLE instance started.
Total System Global Area 269554896 bytes
Fixed Size 451792 bytes
Variable Size 201326592 bytes
Database Buffers 67108864 bytes
Redo Buffers 667648 bytes
Database mounted.
Database opened.
ops$tkyte@ORA9IR2> connect /
Connected.
ops$tkyte@ORA9IR2> select sql_text from v$sql where sql_text like 'select * from t %';
no rows selected
ops$tkyte@ORA9IR2> variable n number
ops$tkyte@ORA9IR2> exec :n := 99
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> set autotrace traceonly
ops$tkyte@ORA9IR2> select * from t where id = :n;
27849 rows selected.
<b>Now, since :n = 99, and we have histograms, a full scan will be choosen and assigned to this query while the instance is up:</b>
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=41 Card=13925 Bytes=1392500)
1 0 TABLE ACCESS (FULL) OF 'T' (Cost=41 Card=13925 Bytes=1392500)
Statistics
----------------------------------------------------------
590 recursive calls
0 db block gets
2309 consistent gets
399 physical reads
308 redo size
1946947 bytes sent via SQL*Net to client
20915 bytes received via SQL*Net from client
1858 SQL*Net roundtrips to/from client
7 sorts (memory)
0 sorts (disk)
27849 rows processed
ops$tkyte@ORA9IR2> set autotrace off
ops$tkyte@ORA9IR2> exec :n := 1
PL/SQL procedure successfully completed.
<b>Even though this query with these binds would benefit from an index, it will not, the other plan got there first:</b>
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> set autotrace traceonly
ops$tkyte@ORA9IR2> select * from t where id = :n;
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=41 Card=13925 Bytes=1392500)
1 0 TABLE ACCESS (FULL) OF 'T' (Cost=41 Card=13925 Bytes=1392500)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
398 consistent gets
0 physical reads
0 redo size
1216 bytes sent via SQL*Net to client
499 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
<b>That full scanned based on the 398 consistent gets -- remember "explain plan" can lie, so we are relying on the consistent gets, which are accurate here</b>
ops$tkyte@ORA9IR2> set autotrace off
ops$tkyte@ORA9IR2> @trace
ops$tkyte@ORA9IR2> alter session set events '10046 trace name context forever, level 12';
Session altered.
ops$tkyte@ORA9IR2> set autotrace traceonly
ops$tkyte@ORA9IR2> select * from t where id = :n;
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=41 Card=13925 Bytes=1392500)
1 0 TABLE ACCESS (FULL) OF 'T' (Cost=41 Card=13925 Bytes=1392500)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
4 consistent gets
2 physical reads
0 redo size
1216 bytes sent via SQL*Net to client
499 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
ops$tkyte@ORA9IR2> set autotrace off
<b>That is showing autotrace lies (it could not have full scanned, 4 consistent gets).
</b>ops$tkyte@ORA9IR2> select sql_text from v$sql where sql_text like 'select * from t %';
SQL_TEXT
-------------------------------------------------------------------------------------------------------------------------
select * from t where id = :n
select * from t where id = :n
So, I would say you have a query that -- given the binds that were in place the first time it was executed "it was good" but the binds you were using made it "very bad". Using the trace event, you generated a "very good" plan for that query -- running with those binds -- but only when tracing is on (the environment matches)
Bind variable peeking
A reader, December 03, 2005 - 5:30 pm UTC
Wow, never thought about that. Thanks for the great explanation.
But how do I fix the situation? I dont want to run with sql_trace=true all the time. I dont want to flush the shared pool either (just for this teeny problem)
So what do I do? What if I gather stats on all the tables involved? That would invalidate all the plans in the shared pool.
But then I would again need to cross my fingers that the first time the query is encountered it has a "good" set of binds. I find this non-deterministic nature of bind variable peeking very frustrating. How would I ensure that a bad plan doesnt get there first and stick around causing that query to get doomed forever?!
Thanks
December 04, 2005 - 6:09 am UTC
but the query isn't doomed forever - it was run at some point with binds that caused this plan and in theory, that plan was good for those binds.
Most all of the time, bind variable peeking works exactly as expected, the binds supplied to that query at that point in the program are representative - leading to the best over all plans.
When it doesn't, here are somethings you can consider:
o Don't bind that particular value (that causes the issue). If the value involved is of sufficient low distinct cardinality (eg: there are 10 distinct values), then don't bind that particular bind and live with up to 10 unique plans in the shared pool.
o Don't gather statistics that would cause the bind variable to matter. (eg: don't gather histograms). You'll get the "general plan" - might not be the best plan but it will be consistent.
o use your domain knownledge. For example, you know if the bind variable of type DATE is within the last 30 days - one plan would be used, over 30 days - another. So code an if then else and use one of two different sql statements at that point in the code.
o use cursor_sharing=similar at that point. Might result in many unshared sql's in the shared pool so be careful. But Oracle will figure out which binds are "safe" and can be reused - and which ones are not (eg: don't bind this one query, but auto-bind this one query with similar).
o use a hint or query plan stability (but upon upgrades, consider looking at this query for new access paths/whatnot)
o you can disable bind variable peeking - but you'd have to work with support for that. sort of like "remove the statistics from the optimizer that cause different plans" in most cases - meaning I'd rather not gather the stats if given the choice (less work for the database to perform overall)
Autotrace and sqltrace
Anne, August 16, 2006 - 3:24 pm UTC
Hi Tom,
Could you please help me with 2 questions that I have :
1. I am slightly unclear as to when to use autotrace and sqltrace=true. My understanding is : if you want to see the plan of a single statement then use 'set autotrace traceonly'. If you want to see the plan of statments within a pl/sql block, then use 'alter session set sql_trace = true' and specify the type of trace using ' set autotrace <traceonly/on...>' - then you can tkprof the trace file that is created. Is this correct ?
2. The following code displays results twice on the screen and I am not sure why. Could you please help me out. (This is just the start of a test case I am building to see the effects of binding verses not binding...)
Structure :
create table abjtest as select object_id, object_type from all_objects where 1=0
/
alter table abjtest add constraint abjtest_pk primary key(object_id);
/
SQL> select object_type, min(object_id) min_obj, max(object_id) max_obj,
2 count(object_id) row_cnt
3 from abjtest
4 group by object_type
5 /
OBJECT_TYPE MIN_OBJ MAX_OBJ ROW_CNT
------------------ ---------- ---------- ----------
A 1 500 500
B 501 1001 501
Objective : select rows where object_type = B and print the object_id of the 100th rows.
Code :
prompt ****STATIC****
set autotrace on
/
alter session set sql_trace=true
/
declare
l_start abjtest.object_id%type := null;
l_end abjtest.object_id%type := null;
l_time number;
cursor c_cur is
select object_id, object_type
from abjtest abjstatic
where object_id between l_start and l_end
order by object_id;
type c_table_type is table of c_cur%rowtype index by binary_integer;
c_table c_table_type;
begin
l_time := dbms_utility.get_time;
select min(object_id), max(object_id)
into l_start, l_end
from abjtest
where object_type = 'B';
open c_cur;
loop
fetch c_cur bulk collect into c_table limit 200;
for i in 1 .. c_table.count
loop
if mod(i,100) = 0 then
dbms_output.put_line (c_table(i).object_id);
end if;
end loop;
exit when c_cur%notfound;
end loop;
close c_cur;
dbms_output.put_line( dbms_utility.get_time - l_time || ' hsecs ' );
exception
when others then
dbms_output.put_line (sqlerrm);
if c_cur%ISOPEN then close c_cur; end if;
raise;
end;
/
set autotrace off
/
alter session set sql_trace=false
/
Output :
SQL> @test;
****STATIC****
Session altered.
Session altered.
600
700
800
900
1000
1 hsecs
PL/SQL procedure successfully completed.
600
700
800
900
1000
0 hsecs
PL/SQL procedure successfully completed.
Session altered.
SQL>
I wonder why it is dispalying the results twice ?
I know I could do the above in just 1 sql statement, but I just want to do it the above way for benchmarking:
select object_id
from ( select object_id, rownum rnum
from abjtest
where object_type = 'B'
order by rownum;
OBJECT_ID
----------
600
700
800
900
1000
)
where mod(rnum,100) = 0
/
Thanks so much.
August 16, 2006 - 4:01 pm UTC
1) autotrace is useful for the "individual query to be tested interactively"
sql_trace is useful for tracing the activity of an application.
2) the second slash after set autotrace - that runs the contents of the buffer. sqlplus "set" commands do not go into the execution buffer - so it ran the last thing that did - your plsql block.
Tkprof output
Anne, August 17, 2006 - 10:31 am UTC
Thanks so much, Tom! One thing that I noticed is that, when I run a sql statement interactively after set autotrace on/traceonly, it show the Execution Plan and Statistics. However, if I do in the script:
set autotrace on
alter session set sql_trace=true;
/
and then tkprof the trace file using aggregate=no, I do not see the Statistics. How can I get that to work ? Thanks.
August 17, 2006 - 10:42 am UTC
sure you do see the statistics - it is in the tkprof??? Not sure what you mean by that.
you see the logical io's, physical io's, cpu time, elapsed times, rows processed, etc.
You do not see the IDENTICAL output from autotrace, but you get the information you get from tkprof.
tkprof output
Anne, August 17, 2006 - 11:29 am UTC
Thanks for the prompt reply, Tom. What I mean is - I do not see the part that says "consistent gets" like I do in autotrace... I've got timed_statistics true and I used dbms_stats.gather_table_stats. Here's my tkprof output :
*** SESSION ID:(85.5752) 2006-08-17 10:17:16.861
********************************************************************************
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
declare
l_start abjtest.object_id%type := null;
l_end abjtest.object_id%type := null;
l_time number;
cursor c_cur is
select object_id, object_type
from abjtest abjstatic7
where object_id between l_start and l_end
order by object_id;
type c_table_type is table of c_cur%rowtype index by binary_integer;
c_table c_table_type;
begin
l_time := dbms_utility.get_time;
select min(object_id), max(object_id)
into l_start, l_end
from abjtest abjstatic7
where object_type = 'B';
open c_cur;
loop
fetch c_cur bulk collect into c_table limit 200;
for i in 1 .. c_table.count
loop
if mod(i,100) = 0 then
dbms_output.put_line (c_table(i).object_id);
end if;
end loop;
exit when c_cur%notfound;
end loop;
close c_cur;
dbms_output.put_line( dbms_utility.get_time - l_time || ' hsecs ' );
exception
when others then
dbms_output.put_line (sqlerrm);
if c_cur%ISOPEN then close c_cur; end if;
raise;
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.02 0.01 0 0 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SELECT MIN(OBJECT_ID), MAX(OBJECT_ID)
FROM
ABJTEST ABJSTATIC7 WHERE OBJECT_TYPE = 'B'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 4 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
501 TABLE ACCESS FULL ABJTEST
--------------------------------------------------------------------------------
SELECT OBJECT_ID, OBJECT_TYPE
FROM
ABJTEST ABJSTATIC7 WHERE OBJECT_ID BETWEEN :B2 AND :B1 ORDER BY OBJECT_ID
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 9 0 501
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 9 0 501
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
501 FILTER
501 TABLE ACCESS BY INDEX ROWID ABJTEST
501 INDEX RANGE SCAN ABJTEST_PK (object id 481069)
--------------------------------------------------------------------------------
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SELECT DECODE('A','A','1','2')
FROM
DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 1
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.03 0.01 0 0 0 0
Execute 4 0.00 0.00 0 0 0 2
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.03 0.01 0 3 0 3
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 43 0.00 0.00
SQL*Net message from client 43 0.03 0.18
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 13 0 502
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 13 0 502
Misses in library cache during parse: 2
6 user SQL statements in session.
0 internal SQL statements in session.
6 SQL statements in session.
August 17, 2006 - 12:47 pm UTC
sure you do:
SELECT OBJECT_ID, OBJECT_TYPE
FROM
ABJTEST ABJSTATIC7 WHERE OBJECT_ID BETWEEN :B2 AND :B1 ORDER BY OBJECT_ID
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 9 0 501
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 9 0 501
query = consistent gets, 9 of them in this case.
current = db block gets, 0 of them in this case
tkprof
Anne, August 17, 2006 - 4:00 pm UTC
Oh ok, I get it, Thank you Tom. I've got a test case and I am not clear as to the effects of binding versus non-binding, and the better method, from the tkprof output. Could you please help me understand. Thanks again for your help.
Structure :
create table abjtest as select object_id, object_type from all_objects where 1=0
/
alter table abjtest add constraint abjtest_pk primary key(object_id);
/
SQL> select object_type, min(object_id) min_obj, max(object_id) max_obj,
2 count(object_id) row_cnt
3 from abjtest
4 group by object_type
5 /
OBJECT_TYPE MIN_OBJ MAX_OBJ ROW_CNT
------------------ ---------- ---------- ----------
A 1 200 200
B 201 400 200
C 401 700 300
D 701 750 50
E 751 800 50
F 801 900 100
G 901 1000 100
Objective : select rows where object_type = B and print the object_id of the 100th rows. So in this case output shoud be 300 and 400. (I could do this in 1 sql but am not, just to see the effects)
I've got 2 plsql blocks - the first is static and the second dynamic. To me, the tkprof output looks similar - so I'm not sure if "binding" is being used in the first case also or what.
Outline of script :
----------------
set autotrace on
alter session set events '10046 trace name context forever, level 12';
/
<plsql block for static method>
/
<plsql block for Dynamic method>
/
set autotrace off
alter session set sql_trace=false;
Script output:
------------
****STATIC****
Session altered.
Session altered.
300
400
0 hsecs
PL/SQL procedure successfully completed.
****DYNAMIC****
300
400
0 hsecs
PL/SQL procedure successfully completed.
Session altered.
Tkprof output:
------------
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.01 0.01
********************************************************************************
declare
l_start abjtest.object_id%type := null;
l_end abjtest.object_id%type := null;
l_time number;
cursor c_cur is
select object_id, object_type
from abjtest abjstatic9
where object_id between l_start and l_end
order by object_id;
type c_table_type is table of c_cur%rowtype index by binary_integer;
c_table c_table_type;
begin
l_time := dbms_utility.get_time;
select min(object_id), max(object_id)
into l_start, l_end
from abjtest abjstatic9
where object_type = 'B';
open c_cur;
loop
fetch c_cur bulk collect into c_table limit 200;
for i in 1 .. c_table.count
loop
if mod(i,100) = 0 then
dbms_output.put_line (c_table(i).object_id);
end if;
end loop;
exit when c_cur%notfound;
end loop;
close c_cur;
dbms_output.put_line( dbms_utility.get_time - l_time || ' hsecs ' );
exception
when others then
dbms_output.put_line (sqlerrm);
if c_cur%ISOPEN then close c_cur; end if;
raise;
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SELECT MIN(OBJECT_ID), MAX(OBJECT_ID)
FROM
ABJTEST ABJSTATIC9 WHERE OBJECT_TYPE = 'B'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 4 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
200 TABLE ACCESS FULL ABJTEST
--------------------------------------------------------------------------------
SELECT OBJECT_ID, OBJECT_TYPE
FROM
ABJTEST ABJSTATIC9 WHERE OBJECT_ID BETWEEN :B2 AND :B1 ORDER BY OBJECT_ID
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 200
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 200
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
200 FILTER
200 TABLE ACCESS BY INDEX ROWID ABJTEST
200 INDEX RANGE SCAN ABJTEST_PK (object id 481069)
--------------------------------------------------------------------------------
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
declare
l_start abjtest.object_id%type := null;
l_end abjtest.object_id%type := null;
l_type abjtest.object_type%type := null;
l_time number;
sql_str varchar2(2000);
type c_refcursor_type is REF CURSOR;
c_cur c_refcursor_type;
type c_table_type is table of abjtest%rowtype index by binary_integer;
c_table c_table_type;
begin
l_time := dbms_utility.get_time;
l_type := 'B';
execute immediate 'select min(object_id), max(object_id)
from abjtest abjdyn9
where object_type = :obj' into l_start, l_end using l_type ;
sql_str := 'select object_id, object_type
from abjtest abjdyn9
where object_id between :start_id and :end_id
order by object_id';
-- dbms_output.put_line (sql_str);
open c_cur for sql_str using l_start, l_end;
loop
fetch c_cur bulk collect into c_table limit 200;
-- dbms_output.put_line('cnt '|| c_table.count);
for i in 1 .. c_table.count
loop
if mod(i,100) = 0 then
dbms_output.put_line (c_table(i).object_id);
end if;
end loop;
exit when c_cur%notfound;
end loop;
close c_cur;
dbms_output.put_line( dbms_utility.get_time - l_time || ' hsecs ' );
exception
when others then
dbms_output.put_line (sqlerrm);
if c_cur%ISOPEN then close c_cur; end if;
raise;
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
select min(object_id), max(object_id)
from abjtest abjdyn9
where object_type = :obj
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 4 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
200 TABLE ACCESS FULL ABJTEST
--------------------------------------------------------------------------------
select object_id, object_type
from abjtest abjdyn9
where object_id between :start_id and :end_id
order by object_id
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 200
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 200
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
200 FILTER
200 TABLE ACCESS BY INDEX ROWID ABJTEST
200 INDEX RANGE SCAN ABJTEST_PK (object id 481069)
--------------------------------------------------------------------------------
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SELECT DECODE('A','A','1','2')
FROM
DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 1
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 173
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6 0.02 0.01 0 0 0 0
Execute 7 0.02 0.00 0 0 0 4
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.04 0.01 0 3 0 5
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 64 0.00 0.00
SQL*Net message from client 64 0.05 0.36
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.00 0 16 0 402
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.00 0.00 0 16 0 402
Misses in library cache during parse: 4
11 user SQL statements in session.
0 internal SQL statements in session.
11 SQL statements in session.
August 17, 2006 - 4:25 pm UTC
but both were hard parsed:
Misses in library cache during parse: 1
that clues us into that (you set up the example, the first query you run will hard parse, subsequent queries will softparse)
In order to see the effects (negative wise) of not binding you have to run hundreds of queries with different literals, eg, you would compared:
begin
for i in 1 .. 10000
loop
open l_cursor for 'select * from t where c = ' || i;
close l_cursor;
end loop;
end;
versus
begin
for i in 1 .. 10000
loop
open l-cursor for 'select * from t where c = :x' using i;
close l_cursor;
end loop;
end;
that'll show the SINGLE USER impact of not using binds - but not using binds really kicks in when you have 2 or more users trying to hard parse - they end up waiting on eachother (parsing is a somewhat serial operation since you have to modify the shared pool so much).
In your case - if 'B' never changes, well, you don't need to bind 'B', you ONLY bind that which varies from execution to execution!
tkprof
Anne, August 18, 2006 - 10:48 am UTC
Aahh... I see! Thanks for your prompt response!
I have couple of questions though :
1. In this case though, why would the dynamic statement also be hard parsed instead of softparse - aren't the sqls the same ?
SELECT OBJECT_ID, OBJECT_TYPE
FROM
ABJTEST ABJSTATIC9 WHERE OBJECT_ID BETWEEN :B2 AND :B1 ORDER BY OBJECT_ID
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 200
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 200
Misses in library cache during parse: 1
select object_id, object_type
from abjtest abjdyn9
where object_id between :start_id and :end_id
order by object_id
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 200
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 200
Misses in library cache during parse: 1
2. I followed your "test code" for the effects of non binding, and I did see the 1000 plans for the non-binding statement versus the 1 plan for the binding one!!
Now, in that tkprof, for the binding sql, is it saying that the 2nd sql is hard parsed ? I thought it would be soft parsed..
select *
from abjtest abjnonbind2
where object_id = 1000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID ABJTEST
0 INDEX UNIQUE SCAN ABJTEST_PK (object id 481069)
select *
from abjtest abjbind2
where object_id = :x
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1000 0.02 0.01 0 0 0 0
Execute 1000 0.04 0.10 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2000 0.06 0.11 0 0 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 173 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID ABJTEST
0 INDEX UNIQUE SCAN ABJTEST_PK (object id 481069)
3. My test case above was to simulate a package that I have to write - the package may be executed about 5 times a day by a multiple users - each time it will search for the latest "posted_id" and then get records from other tables
based on the "latest posted_id" and do some inserts, updates etc.... In the proc, I am getting the latest posted_id via a "select simple max(..) into ...", and then using that id in the subsequent sql statements.
Do you think that doing a dynamic sql for the "select from other tables where posted_id > :x using l_posted_id" would help performance wise, when compared to
"select from other tables where posting_id > l_posted_id"...
As always thanks so much for your help - I am learning so much from this site!
August 18, 2006 - 12:30 pm UTC
it was the first time you parsed it, they are ALL hard parsed the first time.
run it again, and they BOTH will softparse.
for the second one it states it was parsed 1000 times, and only missed in the library cache once! it hard parsed 1 time, it soft parsed 999 times.
I would suggest you use a bind for that query, it is just too simple of a query and it is doubtful that data skew would come into play (a guess on my part)
tkprof
Anne, August 18, 2006 - 12:42 pm UTC
Thanks so much, Tom. Ooops - for the second one, I see that now - it was parsed 1000 times, and only missed in the library cache once! This was a great exercise and has helped me to understand some of the key points to notice in tkprof. Thanks again!
How to get the bind varaible value using tkprof
Ajeet, March 24, 2007 - 9:16 am UTC
Hi Tom
I have 5 SQL statements as a part of an application transaction.they are all using bind variable in the where cluase - but application is failing when we run the application and we don't know why .we do get an error ORA-1403 and message that can't fetch values from a table.
but when we test from sql*plus we can see that record exist for the supplied values.
so I ran the application and took a trace -
using
alter session set tracefile_identifier ="ajeet";
exec dbms_monitor.session_trace_enable(session_id=>406, serial_num=>15, waits=>false, binds=>true);
exec dbms_monitor.session_trace_enable(session_id=>402, serial_num=>69, waits=>false, binds=>true);
exec dbms_monitor.session_trace_enable(session_id=>406, serial_num=>7, waits=>false, binds=>true);
exec dbms_monitor.session_trace_enable(session_id=>412, serial_num=>32, waits=>false, binds=>true);
select sid,serial#,module from
v$session where username='TBAGEN' and module like 'lisrvr%' ;
SQL> select sid,serial#,module from
v$session where 2 username='TBAGEN' and module like 'lisrvr%' ;
SID SERIAL# MODULE
---------- ---------- ------------------------------------------------
401 78 lisrvr@lnhpit1 (TNS V1-V3)
402 67 lisrvr@lnhpit1 (TNS V1-V3)
406 7 lisrvr@lnhpit1 (TNS V1-V3)
412 32 lisrvr@lnhpit1 (TNS V1-V3)
now, I can see the bind varaibles in the output tracefiles.
but when I ran the tkporf on these tracefiles..bind variable is not coming in the output file from tkporf.
is there a way to get them using tkprof.
or is there any better way to do it.
Regards
Ajeet