Fairlie Rego

Subscribe to Fairlie Rego feed
Fairlie Regohttps://plus.google.com/112092317463773401834noreply@blogger.comBlogger59125
Updated: 16 hours 47 min ago

Using dbx collector

Sat, 2007-07-14 08:45
It is quite possible that you have a single piece of sql which consumes more and more cpu over time without an increase in logical i/o for the statement or due to increased amount of hard parsing.

The reason could be extra burning of cpu in an Oracle source code function with time which has not been instrumented as a wait in the RDBMS kernel. One way to find out which function in the Oracle source code is the culprit is via the dbx collector function available in the Sun Studio 11. I guess dtrace would also help but I haven’t played with it. This tool can also be used in diagnosing increased cpu usage of Oracle tools across different RDBMS versions.

Let us take a simple example on how to run this tool on a simple insert statement.

SQL> create table foo ( a number);

Table created.

> sqlplus

SQL*Plus: Release 10.2.0.3.0 - Production on Sat Jul 14 23:46:03 2007

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

Enter user-name: /

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

SQL> set sqlp sess1>>
sess1>>

Session 2
Find the server process servicing the previously spawned sqlplus session and attach to it via the debugger.

> ps -ef | grep sqlplus
oracle 20296 5857 0 23:47:38 pts/1 0:00 grep sqlplus
oracle 17205 23919 0 23:46:03 pts/4 0:00 sqlplus
> ps -ef | grep 17205
oracle 20615 5857 0 23:47:48 pts/1 0:00 grep 17205
oracle 17237 17205 0 23:46:04 ? 0:00 oracleTEST1 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 17205 23919 0 23:46:03 pts/4 0:00 sqlplus

> /opt/SUNWspro/bin/dbx $ORACLE_HOME/bin/oracle 17237

Reading oracle
==> Output trimmed for brevity.

dbx: warning: thread related commands will not be available
dbx: warning: see `help lwp', `help lwps' and `help where'
Attached to process 17237 with 2 LWPs
(l@1) stopped in _read at 0xffffffff7bfa8724
0xffffffff7bfa8724: _read+0x0008: ta 64
(dbx) collector enable


Session 1
==================================================================
begin
for i in 1..1000
loop
insert into foo values(i);
end loop;
end;
/

Session 2
==================================================================

(dbx) cont
Creating experiment database test.3.er ...
Reading libcollector.so

Session 1
==================================================================
PL/SQL procedure successfully completed.

sess1>>exit
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

Session 2
=========

execution completed, exit code is 0
(dbx) quit

The debugger creates a directory called test.1.er.
You can analyse the collected data by using analyser which is a GUI tool.

> export DISPLAY=10.59.49.9:0.0
> /opt/SUNWspro/bin/analyzer test.3.er



You can also generate a callers-callees report using the following syntax

/opt/SUNWspro/bin/er_print test.3.er
test.3.er: Experiment has warnings, see header for details
(/opt/SUNWspro/bin/er_print) callers-callees

A before and after image of the performance problem would help in diagnosing the function in the code which consumes more CPU with time.

Fix Control

Sat, 2007-06-30 08:59
Oracle has introduced a fix control mechanism in 10.2 which allows customers to turn off fixes for optimizer related bugs. This is governed by the underscore parameter _fix_control. The bugs for which fixes can be turned off are listed in v$session_fix_control and v$system_fix_control and can also be seen in a 10053 output.

On a 10.2.0.2 database

SQL> select distinct bugno from v$session_fix_control;

BUGNO
----------
3499674
4556762
4569940
3118776
4519016
4175830
4663698
4631959
4550003
4584065
4487253
4611850
4663804
4602374
4728348
4723244
4554846
4545833
4488689
4519340

20 rows selected.

SQL> select distinct sid from v$mystat;

SID
----------
143

SQL> alter session set "_fix_control"='4728348:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno=4728348;

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4728348 0 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

A value of 0 indicates the fix is off.

SQL> alter session set "_fix_control"='4728348:ON';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno=4728348;

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4728348 1 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

It appears to me that if you need two fixes off in a session you have to specify them together else you lose the first change.

SQL> alter session set "_fix_control"='4728348:OFF';

Session altered.

SQL> alter session set "_fix_control"='4663698:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno in (4728348,4663698);

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4663698 0 for cached NL table set tab_cost_io to zero 10.2.0.2 0 0
143 4728348 1 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

Hence if you need more than one fix OFF you need to supply both bug numbers in the same command

SQL> alter session set "_fix_control"='4728348:OFF','4663698:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno in (4728348,4663698);

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4663698 0 for cached NL table set tab_cost_io to zero 10.2.0.2 0 0
143 4728348 0 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

DBA_HIST_FILEMETRIC_HISTORY

Sat, 2007-06-02 08:25
There are so many new views in 10G that you begin to wonder if many of them are
actually populated correctly. For example there are quite a few bugs with some of the DBA_HIST* views not being populated correctly. One such view DBA_HIST_TBSPC_SPACE_USAGE is notorious for incorrect values .But the view DBA_HIST_FILEMETRIC_HISTORY which supposedly stores alerts only for 7 days does not even seem to be getting populated.


So on a 10.1.0.5 database

SQL> select count(*) from dba_hist_filemetric_history;

COUNT(*)
----------
0

If you have a look at the definition of the view from catawrvw.sql

create or replace view DBA_HIST_FILEMETRIC_HISTORY
(SNAP_ID, DBID, INSTANCE_NUMBER, FILEID, CREATIONTIME, BEGIN_TIME,
END_TIME, INTSIZE, GROUP_ID, AVGREADTIME, AVGWRITETIME, PHYSICALREAD,
PHYSICALWRITE, PHYBLKREAD, PHYBLKWRITE)
as
select fm.snap_id, fm.dbid, fm.instance_number,
fileid, creationtime, begin_time,
end_time, intsize, group_id, avgreadtime, avgwritetime,
physicalread, physicalwrite, phyblkread, phyblkwrite
from wrm$_snapshot sn, WRH$_FILEMETRIC_HISTORY fm
where sn.snap_id = fm.snap_id
and sn.dbid = fm.dbid
and sn.instance_number = fm.instance_number
and sn.status = 0


SQL> select count(*) from WRH$_FILEMETRIC_HISTORY;

COUNT(*)
----------
0

I have tried various ways to get this base table populated but
am not sure when information is flushed to WRH$_FILEMETRIC_HISTORY.
This behaviour is also consistent in 10.2.0.3

What is Timeout?

Fri, 2007-05-18 22:29
The problem with semi documented APIs like DBMS_SPACE is that some of the subprograms might not work as you might expect them to.
For example the object_space_usage procedure has a parameter called timeout_value which I would assume to mean the amount of time after the procedure will abort if it cannot complete its space calculations. But this does not work as I would expect it to

SQL> set timing on
SQL> set serveroutput on

SQL> declare
v_space_used number;
v_space_allocated number;
begin
dbms_space.object_space_usage('SCOTT','EMP','TABLE',0,v_space_used, v_space_allocated,'',TRUE,5);
dbms_output.put_line('SPACE USED = '||v_space_used);
dbms_output.put_line('SPACE ALLOCATED = '||v_space_allocated);
end;
/

SPACE USED = 0
SPACE ALLOCATED = 68034756608

PL/SQL procedure successfully completed.

Elapsed: 00:00:36.12

So even if I specify a timeout value of 5 the procedure completes in 36 seconds.

This behaviour reproduces on 10.1.0.5 and 10.2.0.3.

Pages