Oracle Performance and Engineering

First one was this.

A big query takes 'forever' (about 385 secs. on DB CPU and a total of 685 secs. elapsed). It looks like -

/* Formatted on 2006/03/31 14:32 (Formatter Plus v4.8.5) */
SELECT t1.cessation_date, t1.commence_date, t1.confirm_date, t1.alias,
t1.birth_date, t1.emp_card_one, t1.employee_id, t1.employee_name,
t1.employment_type_code, t1.family_name, t1.gender, t1.given_name,
t1.language_spoke, t1.language_written, t1.mail_id,
t1.marital_stat_eff_date, t1.marital_stat_code, t1.nationality_code,
t1.native_name, t1.original_commence_date, t1.permit_expiry_date,
t1.permit_issue_date, t1.permit_type, t1.national_id, t1.race_code,
t1.religion_code, t1.religion_born, t1.religion_convert_date,
t1.security_id, t1.service_reference_date, t1.status_code,
t1.title_code
FROM hrm_employee t1, hrm_curr_career_v t0
WHERE ( ( ( ( (t0.job_level_code IN
('JL1-S0',
'JL1-SF',
'JL1-SG',
'JL1-SH',
'JL1-SI',
'JL1-SJ',
'JL1-SK',
'JL1-SL',
'JL1-SM',
'JL1-SN',
'JL1-SO',
'JL1-SP',
'JL1-SQ',
'JL1-SR',
'JL5-S0',
'JL8-S9',
'JL9-SC',
'JLA-S0',
'JL8EHR26',
'JL8EHR29'
)
)
AND (t0.leave_scheme_code = 'LSA')
)
AND (t0.employee_id = t1.employee_id)
)
AND t1.employee_id <> 'SG02514373'
AND t1.employee_id IN (
SELECT t1.employee_id
FROM sec_gpprofile t2,
sa_userprofile t1,
sec_profilegroupmap t0
WHERE (( (t2.object_id = 'Time.Attendance Adj')
AND ( (t0.GROUP_ID = t2.GROUP_ID)
AND (t1.user_id = t0.profile_id)
)
)
))
)
AND (t0.employee_id IN (
SELECT e.employee_id
FROM hrm_curr_career_v c, hrm_employee e
WHERE c.employee_id = e.employee_id
AND e.employee_id LIKE 'SG%'
AND (e.cessation_date IS NULL
OR e.cessation_date >= SYSDATE
)
AND ( c.employee_id = 'SG02514373'
OR c.supervisor_3 = ('SG02514373')
OR c.employee_id IN (
SELECT cc1.employee_id
FROM hrm_cost_centre cc1, hrm_curr_career_v c
WHERE c.employee_id = ('SG02514373')
AND c.remarks LIKE
'%/' || cc1.cost_centre_code || '%'
AND cc1.employee_id LIKE 'SG%'
AND cc1.eff_date =
(SELECT MAX (cc2.eff_date)
FROM hrm_cost_centre cc2
WHERE cc2.employee_id =
cc1.employee_id
AND cc2.eff_date <= SYSDATE))
)
UNION
(SELECT e.employee_id
FROM hrm_curr_career_v c,
hrm_employee e,
ihr_covering_officer r2
WHERE c.employee_id = e.employee_id
AND e.employee_id LIKE 'SG%'
AND ( e.cessation_date IS NULL
OR e.cessation_date >= SYSDATE
)
AND r2.covering_officer_id = ('SG02514373')
AND r2.start_date <= SYSDATE
AND r2.end_date >= SYSDATE
AND ( c.supervisor_3 = r2.officer_id
OR c.employee_id IN (
SELECT cc1.employee_id
FROM hrm_cost_centre cc1,
hrm_curr_career_v c2
WHERE c2.employee_id = r2.officer_id
AND c2.remarks LIKE
'%/' || cc1.cost_centre_code || '%'
AND cc1.employee_id LIKE 'SG%'
AND cc1.eff_date =
(SELECT MAX (cc2.eff_date)
FROM hrm_cost_centre cc2
WHERE cc2.employee_id =
cc1.employee_id
AND cc2.eff_date <= SYSDATE))
)))
)
);

They have the execution plan attached.

(I also commented on this - as oracle_doc ;) ).

But here's how I would analyze this, if I were at a completely unknown site with this query.

(1) The part in the given plan that is most expensive is -

Rows Execution Plan
------- ---------------------------------------------------
40928544 NESTED LOOPS
13428 INDEX (RANGE SCAN) OF 'HRM_CAREER_PK' (UNIQUE)
40928544 TABLE ACCESS (BY INDEX ROWID) OF 'HRM_CAREER'
3048 INDEX (RANGE SCAN) OF 'HRM_CAREER_PK' (UNIQUE)

(2) I see no 'HRM_CAREER' table in the given SQL. Thus, the table HRM_CAREER is part of the view hrm_curr_career_v.

(3) I would open SQL*plus and execute two queries -- one each for each UNION part -- with "set autot on". Typically, it's just one part that's sluggish.

(4) Since I see a VIEW OF 'VW_NSO_1' in the explain plan - I will also try
"alter session set "_unnest_subquery"=false", or alternately UNNEST_SUBQUERY hint.

WHY?

What is "VW_NSO_1" View?
------------------------

"VW_NSO_1" is a dynamic view which is created at query run time. It is utilized for
nested subquery optimization.

It is used to transform an IN subquery to a join, and to transform a NOT IN
subquery to an anti-join.

Thus, a guess would be -- without looking into the view or data-distribution mentioned in this query -- that Oracle transforms the entire unbounded IN-list to a join, and that could be a pain in this case.

(5) Check the data distribution and indexing of supervisor_3 and eff_date columns from hrm_curr_career_v view

(6) Possibly use ANALYTIC FUNCTION - MAX(eff_date) to replace this part of the query -

cc1.eff_date =
(SELECT MAX (cc2.eff_date)
FROM hrm_cost_centre cc2
WHERE cc2.employee_id =
cc1.employee_id
AND cc2.eff_date <= SYSDATE)

(7) And of course, bind this statement and execute it. Without binding, and especially if histograms were calculated, Oracle could arrive at a completely different plan.

The second post I took a look at is this. There was a statspack analysis, about 75% of the load could be attributed to a single SQL (look at the buffer_gets) that looks like a "space check" monitoring query - and definitely not recursive.

This guy also wrote - "the server also hosts a number of automated programs that
access the database. "

I would start with looking into these "automated programs" too. It executed about 779 times over a period of 68 mins. 68 secs. -- very close to once in 5 secs.

In a 10g (or, 9i) database with DB_BLOCK_SIZE 8KB, we create a tablespace with UNIFORM EXTENT allocation with each EXTENT sized 16KB.

CREATE TABLESPACE auto_test DATAFILE '/u0/oracle/oradata/G1010/auto_test1.dbf'--EXTENT MANAGEMENT
SIZE 20M UNIFORM SIZE 16K;

It is created fine.

Now, I try to create a table with a LOB column -

CREATE TABLE lob_test
(id NUMBER,
large_string CLOB)
TABLESPACE auto_test;

ERROR at line 1:
ORA-03237: Initial Extent of specified size cannot be allocated in tablespace (AUTO_TEST)

Now, let's drop and recreate the tablespace with an uniform extent allocation of 24KB.

DROP TABLE lob_test;
DROP TABLESPACE auto_test;

CREATE TABLESPACE auto_test DATAFILE '/u0/oracle/oradata/G1010/auto_test2.dbf'
SIZE 20M UNIFORM SIZE 24K;

CREATE TABLE lob_test
(id NUMBER,
large_string CLOB)
TABLESPACE auto_test;

Table Created.

So, to create a LOB table the tablespace extent must be greater than or equal to the value of THREE database blocks.

Jonathan Lewis explains why -

"So when you create a LOB, Oracle has to allocate at least the first three blocks - one for the segment header block, one for the master bitmap, and one for 'any other data'. In fact, things can be a little more subtle - if you decide to allocate multiple freelist groups as part of the lob storage clause (it seems a little unlikely that you would actually need to do so unless running Oracle Parallel Server), then your initial extent has to be big enough for these as well, so if you set freelist groups 2, then your initial extent would have to be at least 5 blocks (1 seg header, plus 2 freelist groups, plus 1 master bitmap, plus one spare)."

I traced the session for the LOB Table creation and found the following recursive SQLs are extra from the trace of non-LOB table creation -

1)
insert into icol$(obj#,bo#,intcol#,pos#,segcol#,segcollength,offset,col#,
spare1,spare2)
values
(:1,:2,:3,:4,0,0,0,:5,:6,:7);

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 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 1 0.00 0.00 0 0 0 0

WHY? I found the obj# of the LOB_TEST. This should be the BO# (Base Object# - on which the index is created). But when I query -

SELECT * FROM icol$ WHERE bo# = 2605313;

No Row Returned

Trace file correctly shows that 0 row was processed during execution. So, why Oracle is even firing an INSERT when it knows there will not be any record? Or is it that the DML on icol$ (a part of the c_obj$ cluster) is faster than the IF - ELSE logic they would have to do otherwise.

2)
insert into ind$(bo#,obj#,ts#,file#,block#,intcols,type#,flags,property,
pctfree$,initrans,maxtrans,blevel,leafcnt,distkey,lblkkey,dblkkey,clufac,
cols,analyzetime,samplesize,dataobj#,degree,instances,rowcnt,pctthres$,
indmethod#,trunccnt,spare1,spare4,spare2,spare6)
values
(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,
:22,decode(:23,1,null,:23),decode(:24,1,null,:24),:25, :32*256+:26,:27,:28,
:29,:30,:31,:33)


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 2 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 2 3 1

So, 1 row inserted here in IND$ table.

The OBJ# for this entry in IND$ is 2605315 (boj# = LOB_TEST OBJECT# = 2605315).
The corresponding entry for this OBJ# from OBJ$ table -

SELECT obj#, dataobj#, owner#, name FROM obj$ WHERE obj# = 2605315;

obj# dataobj# owner# name
2605315 2605315 304 SYS_IL0002605313C00002$$

This object can *not* be searched through an usual query through DBA_OBJECTS.

SELECT * FROM dba_objects WHERE object_id =2605315;

No Row Returned.

This is Oracle internal placeholder for LOB Index.

3)

insert into lob$(obj#, intcol#, col#, lobj#, part#, ind#, ts#, file#, block#,
chunk, pctversion$, flags, property, retention, freepools)
values
(:1, :2, :3, :4, 0, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14)


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 2 5 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 2 5 1

Again, 1 row inserted in the LOB$.

SELECT obj#, col#, lobj#, ind# FROM LOB$ WHERE obj# = 2605313;

obj# col# lobj# ind#
2605313 2 2605314 2605315

2605313 is the LOB_TEST table. 2605314 is the LOB_OBJECT (on Column #2 of LOB_TEST) and 2605315 is the Oracle created LOB index (locator) on the LOB column.

After the three statements above Oracle inserts the space values into SEG$ -


update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=
:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),
groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=
DECODE(:17,0,NULL,:17),scanhint=:18
where
ts#=:1 and file#=:2 and block#=:3


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.01 0.00 0 15 3 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.00 0 15 3 3

We get the values for TS# (tablespace), file# and block# of the LOB_OBJECT from IND$ as -

SELECT obj#, dataobj#, ts#, file#, block#, bo# FROM ind$ WHERE bo# = 2605313;

obj# dataobj# ts# file# block# bo#
2605315 2605315 26 46 15 2605313

Again,
2605313 is the table containing LOB (TEST_LOB)
2605314 is the LOB object created by Oracle (SYS_IL0002605313C00002$$)
2605315 is the internal index on LOB column

So, when we query for the above ts#, file# and block# in SEG$ -

SELECT blocks, extents, iniexts, extsize FROM seg$ WHERE ts# = 26 AND FILE#= 46 AND BLOCK# =15;

blocks extents iniexts extsize
3 1 3 3

Thus, LOB objects are created with THREE database blocks to start with!


Yet another reason to let Oracle choose both the extent manegement (LOCAL) and allocation policy (AUTOALLOCATE) rather than picking values randomly.

I

[Well, I am back. I took time off from blogging for last 8-9 months because I got married in between and took it kind of easy outside work.]

The view V$SGA_RESIZE_OPS gives information about if the SGA has been increased / decreased. This keeps information about last 100 resize information. Very cool to see when I see a new customer database and want to know what all have changed in between. This is kind of .bash_history for SGA.

Here's how the output looks -

Select * from v$sga_resize_ops;

component oper_type oper_mode parameter initial_size target_size final_size status start_time end_time
===============================================================
shared pool SHRINK MANUAL shared_pool_size 637534208 553648128 637534208 ERROR 3/29/2006 11:54:57 AM 3/29/2006 11:54:57 AM

shared pool GROW MANUAL shared_pool_size 637534208 671088640 654311424 ERROR 3/29/2006 11:55:10 AM 3/29/2006 11:55:10 AM

Good to see that even operations that did not succeed are recorded in this view. That could also be useful for security purpose.

Resize operations, apart from in the V$SGA_RESIZE_OPS, also get recorded in alert.log. Of course! That's how we knew it on pre-9i days.

Here's what got recorded in the alert.log when I tried to shrink and failed -


Wed Mar 29 11:55:10 2006
MEMORY TRACING: MANUAL request
MEMORY TRACING: FG request
MEMORY TRACING: Receiver of memory is shared pool
MEMORY TRACING: Receiver size is 39 granules
MEMORY TRACING: Donor of memory is System Memory
MEMORY TRACING: Donor size is 0 granules
MEMORY TRACING: Amount of memory requested is 33554432 bytes
MEMORY TRACING: Amount of memory to be got is 16777216 bytes
MEMORY TRACING: Amount of memory received is 16777216 bytes
MEMORY TRACING: Min contig requirement is 0 bytes
MEMORY TRACING: Granule size is 16777216 bytes
MEMORY TRACING: Request status is ERROR due to 4033


Next post - Reading 4030 heapdump and analyzing a particular case of memory leak from it.