Skip to Main Content

Breadcrumb

May 4th

Question and Answer

Tom Kyte

Thanks for the question, abhishek .

Asked: May 22, 2006 - 9:02 am UTC

Last updated: February 22, 2007 - 8:52 am UTC

Version: 9.2.0.6

Viewed 1000+ times

You Asked

Hi Tom,

One of our production Server performance is slow all of sudden. As per users Performance is slow almost 5 times. Below is part of Statpack report.

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
ORA9I 1505135597 ORA9I 1 9.2.0.5.0 NO SRVPRD

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 3252 24-Apr-06 15:27:34 177 9.1
End Snap: 3253 24-Apr-06 15:42:37 169 9.0
Elapsed: 15.05 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 304M Std Block Size: 8K
Shared Pool Size: 152M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,110.61 14,044.42
Logical reads: 1,515.63 6,843.06
Block changes: 18.38 82.98
Physical reads: 506.34 2,286.13
Physical writes: 1.02 4.60
User calls: 22.44 101.34
Parses: 18.59 83.93
Hard parses: 0.51 2.32
Sorts: 4.58 20.69
Logons: 0.08 0.34
Executes: 28.13 127.02
Transactions: 0.22

% Blocks changed per Read: 1.21 Recursive Call %: 85.01
Rollback per transaction %: 47.00 Rows per Sort: 25.21

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 66.59 In-memory Sort %: 100.00
Library Hit %: 98.58 Soft Parse %: 97.24
Execute to Parse %: 33.93 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 25.87 % Non-Parse CPU: 90.97

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 89.56 91.62
% SQL with executions>1: 41.44 42.28
% Memory for SQL w/exec>1: 36.85 38.30

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 148,603 4,782 74.51
db file scattered read 23,161 1,359 21.18
control file parallel write 265 86 1.34
CPU time 85 1.33
db file parallel write 165 37 .58
-------------------------------------------------------------
Wait Events for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 148,603 0 4,782 32 743.0
db file scattered read 23,161 0 1,359 59 115.8
control file parallel write 265 0 86 324 1.3
db file parallel write 165 0 37 227 0.8
db file parallel read 391 0 24 61 2.0
log file parallel write 418 345 22 53 2.1
log file sync 132 2 10 77 0.7
control file sequential read 396 0 6 14 2.0




SQL ordered by Gets for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
78,131 2 39,065.5 5.7 8.47 222.53 571400938
select distinct orli.prod_prds_product_code prod_prds_product_co
de, orli.prod_item_number prod_item_number, prod.product_type pr
oduct_type, prod.full_title full_title from order_line_items orl
i, orders orde, products prod where orli.orde_no = orde.no and o
rde.status not in ('H','V','C') and orli.prod_prds_product_code

64,584 1 64,584.0 4.7 15.64 227.89 1502691368
select wcta . ta_terr_code , coll . user_id collector , a . acco
_no , nvl ( c . organization_name , b . first_name || ' ' || b
. last_name ) , a . invo_no , a . artc_code , b . crco_code_havi
ng_new , a . company_code , a . transaction_date , a . amount +
a . pst_charge + a . gst_charge + a . shipping_handling_charge +

61,524 1 61,524.0 4.5 8.00 180.75 1404675027
SELECT ROWID,CR_COLL_ACTION,NO,COMPANY_CODE,CUSTOMER_PO_NUMBER,O
RDER_PLACED_BY,ACCO_NO,CREATED_BY,CREATED_DATE,MODIFIED_DATE,MOD
IFIED_BY,APPROVED_DATE,APPROVED_BY,SHIN_CODE,INVOICE_COPIES,NATI
ONAL_CONTRACT_FLAG,ORDER_TYPE,STATUS,PAYMENT_METHOD,CRV_NO,ORRE_
NO FROM ORDERS WHERE ACCO_NO IN ( SELECT D.NO from collector_ter

SQL ordered by Reads for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
58,926 1 58,926.0 12.9 8.00 180.75 1404675027
SELECT ROWID,CR_COLL_ACTION,NO,COMPANY_CODE,CUSTOMER_PO_NUMBER,O
RDER_PLACED_BY,ACCO_NO,CREATED_BY,CREATED_DATE,MODIFIED_DATE,MOD
IFIED_BY,APPROVED_DATE,APPROVED_BY,SHIN_CODE,INVOICE_COPIES,NATI
ONAL_CONTRACT_FLAG,ORDER_TYPE,STATUS,PAYMENT_METHOD,CRV_NO,ORRE_
NO FROM ORDERS WHERE ACCO_NO IN ( SELECT D.NO from collector_ter

58,479 1 58,479.0 12.8 15.64 227.89 1502691368
select wcta . ta_terr_code , coll . user_id collector , a . acco
_no , nvl ( c . organization_name , b . first_name || ' ' || b
. last_name ) , a . invo_no , a . artc_code , b . crco_code_havi
ng_new , a . company_code , a . transaction_date , a . amount +
a . pst_charge + a . gst_charge + a . shipping_handling_charge +

54,002 2 27,001.0 11.8 8.47 222.53 571400938
select distinct orli.prod_prds_product_code prod_prds_product_co
de, orli.prod_item_number prod_item_number, prod.product_type pr
oduct_type, prod.full_title full_title from order_line_items orl
i, orders orde, products prod where orli.orde_no = orde.no and o
rde.status not in ('H','V','C') and orli.prod_prds_product_code

25,247 1 25,247.0 5.5 6.64 1126.69 2706485961
Module: dllhost.exe
SELECT /*+ FIRST_ROWS(1) */ /* Sales By Product. Params. Territ
ory :ALL MonthFrom : 5 DayFrom : 01 YearFrom : 2005 MonthTo : 2
DayTo : 28 YearTo : 2006 */ DISTINCT terr.code territory_code,
SUBSTR(FCT_TERR_ACCOUNT_MANAGER(terr.code),1,40) manager_name,
buut.name AS buut_name, a.no AS accno, a.cusi_no AS cusi_no,

22,057 32 689.3 4.8 2.00 82.65 2965217885
SELECT SUM(APPLIED_AMOUNT) FROM AR_MANUAL_PAYMENTS WHERE CRV_
NO = :b1
Instance Activity Stats for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session 8,507 9.4 42.5
CPU used when call started 8,515 9.4 42.6
CR blocks created 233 0.3 1.2
DBWR buffers scanned 93,734 103.8 468.7
DBWR checkpoint buffers written 27 0.0 0.1
DBWR checkpoints 0 0.0 0.0
DBWR free buffers found 93,022 103.0 465.1
DBWR lru scans 230 0.3 1.2
DBWR make free requests 240 0.3 1.2
DBWR summed scan depth 93,734 103.8 468.7
DBWR transaction table writes 9 0.0 0.1
DBWR undo block writes 199 0.2 1.0
SQL*Net roundtrips to/from client 38,927 43.1 194.6
SQL*Net roundtrips to/from dblink 6 0.0 0.0
active txn count during cleanout 63 0.1 0.3
background checkpoints completed 0 0.0 0.0
background checkpoints started 0 0.0 0.0
background timeouts 1,045 1.2 5.2
branch node splits 0 0.0 0.0
buffer is not pinned count 1,131,876 1,253.5 5,659.4
buffer is pinned count 1,843,124 2,041.1 9,215.6
bytes received via SQL*Net from c 2,206,371 2,443.4 11,031.9
bytes received via SQL*Net from d 105 0.1 0.5
bytes sent via SQL*Net to client 5,406,567,453 5,987,339.4 ############
bytes sent via SQL*Net to dblink 2,335 2.6 11.7
calls to get snapshot scn: kcmgss 39,525 43.8 197.6
calls to kcmgas 2,768 3.1 13.8
calls to kcmgcs 42 0.1 0.2
change write time 46 0.1 0.2
cleanout - number of ktugct calls 72 0.1 0.4
cleanouts and rollbacks - consist 17 0.0 0.1
cleanouts only - consistent read 2 0.0 0.0
cluster key scan block gets 99,904 110.6 499.5
cluster key scans 72,293 80.1 361.5
commit cleanout failures: block l 0 0.0 0.0
commit cleanout failures: buffer 0 0.0 0.0
commit cleanout failures: callbac 0 0.0 0.0
commit cleanout failures: cannot 0 0.0 0.0
commit cleanouts 3,411 3.8 17.1
commit cleanouts successfully com 3,411 3.8 17.1
commit txn count during cleanout 184 0.2 0.9
consistent changes 785 0.9 3.9
consistent gets 1,354,081 1,499.5 6,770.4
consistent gets - examination 316,250 350.2 1,581.3
current blocks converted for CR 82 0.1 0.4
cursor authentications 198 0.2 1.0
data blocks consistent reads - un 784 0.9 3.9
db block changes 16,595 18.4 83.0
db block gets 14,530 16.1 72.7
deferred (CURRENT) block cleanout 1,733 1.9 8.7
dirty buffers inspected 181 0.2 0.9
enqueue conversions 81 0.1 0.4
enqueue releases 6,997 7.8 35.0
enqueue requests 6,997 7.8 35.0
enqueue timeouts 0 0.0 0.0
enqueue waits 0 0.0 0.0
Tablespace IO Stats for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253
->ordered by IOs (Reads + Writes) desc

Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
PROD_DAT05
80,544 89 32.0 1.8 14 0 12 10.8
PROD_DAT03
25,519 28 37.4 4.3 33 0 6 43.3
PROD_DAT01
23,874 26 46.1 2.2 32 0 3 20.0
PROD_DAT06
11,948 13 27.9 1.3 6 0 0 0.0
PROD_DAT02
9,648 11 42.2 10.0 7 0 0 0.0
PROD_IDX07
6,584 7 31.8 1.0 33 0 0 0.0
PROD_IDX05
5,072 6 35.6 1.8 40 0 0 0.0
PROD_DAT07
3,930 4 40.0 1.1 6 0 0 0.0
SYSTEM
3,250 4 41.7 3.1 59 0 0 0.0
PROD_IDX04
3,171 4 43.8 1.0 22 0 0 0.0
TOOLS
784 1 49.9 1.4 195 0 0 0.0
PROD_IDX03
859 1 47.6 1.0 103 0 0 0.0
PROD_IDX01
863 1 46.0 1.0 56 0 0 0.0
PROD_IDX02
603 1 52.0 2.4 7 0 0 0.0
UNDOTBS1
136 0 33.3 1.0 219 0 0 0.0
PROD_IDX06
143 0 72.9 1.0 43 0 0 0.0
USERS
25 0 49.2 1.0 61 0 0 0.0
WEB_DATA01
27 0 94.8 18.6 3 0 0 0.0
PROD_DAT04
3 0 56.7 1.0 0 0 0 0.0
CWMLITE
1 0 20.0 1.0 0 0 0 0.0
DRSYS
1 0 20.0 1.0 0 0 0 0.0
EXAMPLE
1 0 0.0 1.0 0 0 0 0.0
INDX
1 0 30.0 1.0 0 0 0 0.0
ODM
1 0 0.0 1.0 0 0 0 0.0
PROD_LOB_DAT1
1 0 20.0 1.0 0 0 0 0.0
PROD_LOB_INDX1
1 0 0.0 1.0 0 0 0 0.0

init.ora Parameters for DB: ORA9I Instance: ORA9I Snaps: 3252 -3253

End value
Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
processes 200
timed_statistics TRUE
shared_pool_size 159383552
sga_max_size 1368467944
shared_pool_reserved_size 15728640
large_pool_size 629145600
java_pool_size 83886080
job_queue_processes 10
hash_join_enabled TRUE
background_dump_dest C:\oracle\admin\ORA9I\bdump
user_dump_dest C:\oracle\admin\ORA9I\udump
core_dump_dest C:\oracle\admin\ORA9I\cdump
sort_area_size 52428800
db_name ORA9I
open_cursors 300
sql_trace FALSE
star_transformation_enabled FALSE
query_rewrite_enabled FALSE
pga_aggregate_target 52428800
workarea_size_policy AUTO
aq_tm_processes 1
control_files C:\oracle\oradata\ORA9I\CONTROL
db_block_size 8192
db_cache_size 318767104
compatible 9.2.0.0.0
log_archive_start TRUE
log_archive_dest_1 LOCATION=D:\oracle\ARCHIVES\
log_archive_dest_2 LOCATION=C:\oraprd\ARCHIVES\
log_archive_dest_3 LOCATION=\\srvdev\oraprd\ARCHIVE
log_archive_format ORA9I%t_%s.dbf
db_file_multiblock_read_count 32
fast_start_mttr_target 300
control_file_record_keep_time 5
undo_management AUTO
undo_tablespace UNDOTBS1
undo_retention 7200
max_enabled_roles 60
remote_login_passwordfile EXCLUSIVE
db_domain
instance_name ORA9I
dispatchers (PROTOCOL=TCP) (SERVICE=ORA9IXD
-------------------------------------------------------------

End of Report



After looking at the statpack report,

1. "Rollback per transaction %" is too High.
2. Archive should not be multiplexed on network

I compare the statpack report when Database was runing fine, the major difference is in column "AV Rd(ms)" under section "Tablespace IO Stats". As in present report its almost 10 times higher.
Is this somthing related to OS I/O? (OS is Windows)




Regards
Abhishek



and Tom said...

the thing that jumps out to me is your soft parse % is way low.

Yes, the rollback % is very high.

archive can be multiplexed and archiving should not affect your runtime performance (sort of happens elsewhere, in the background, your users should not be waiting for it)


However, your IO seems to be

a) high, you do a lot of physical IO

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 148,603 0 4,782 32 743.0
db file scattered read 23,161 0 1,359 59 115.8


b) possibly slow, you are doing so much, you are likely saturating the ability of your system to respond to anything in a timely fashion.

0.032 (avg single block IO) and 0.059 (avg multi block IO)


You spent almost no time doing work (85 cpu seconds) and a ton of time waiting for work to be done (IO waits).

Have you always done this much physical IO. I hope you have statspack from when things were "ok" to compare to - or you likely will not be table to answer that question.

Rating

  (18 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Physical I/O

Herod, May 23, 2006 - 9:31 am UTC

May not be worth much.
But I have seen this more than once in the past where IO is suddenly slow. Has most of the time(but not 100%) been a hardware problem.

A card has gone bad, or part of the mirror has bad disks.

Even had bad cabling on 1/2 the fibre channels.

A quick note to the Systems Administrator and sometimes they already knew about it and were in the process of fixing, or arranging things to be fixed. Sometimes I "found" the problem and they just had to fix it.

Just a thought.

Performance Degards

abhishek, May 23, 2006 - 12:04 pm UTC

Hi Tom,
As always Thanks a TON,

Yes i do have statpack reports when things were runing fine. Here is a cut and paste from Statpack when thinks were runing fine.

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
ORA9I 1505135597 ORA9I 1 9.2.0.5.0 NO TOMAHAWK

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 2490 13-Dec-05 10:00:06 125 11.3
End Snap: 2491 13-Dec-05 10:30:08 141 10.6
Elapsed: 30.03 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 304M Std Block Size: 8K
Shared Pool Size: 152M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 2,480.69 6,048.98
Logical reads: 4,373.13 10,663.58
Block changes: 16.66 40.63
Physical reads: 374.23 912.53
Physical writes: 0.73 1.78
User calls: 28.15 68.65
Parses: 15.82 38.57
Hard parses: 0.35 0.86
Sorts: 5.71 13.91
Logons: 0.09 0.23
Executes: 29.66 72.33
Transactions: 0.41

% Blocks changed per Read: 0.38 Recursive Call %: 79.13
Rollback per transaction %: 25.03 Rows per Sort: 43.26

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 91.44 In-memory Sort %: 100.00
Library Hit %: 99.06 Soft Parse %: 97.77
Execute to Parse %: 46.67 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 84.75 % Non-Parse CPU: 93.01

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 87.05 91.37
% SQL with executions>1: 54.27 64.14
% Memory for SQL w/exec>1: 47.39 51.74

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 328,904 503 60.43
CPU time 163 19.59
db file scattered read 17,756 111 13.40
control file parallel write 581 16 1.88
db file parallel write 238 12 1.45
-------------------------------------------------------------
Wait Events for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 328,904 0 503 2 445.1
db file scattered read 17,756 0 111 6 24.0
control file parallel write 581 0 16 27 0.8
db file parallel write 238 0 12 51 0.3
SQL*Net more data to client 7,916 0 7 1 10.7
log file parallel write 706 579 6 9 1.0
log file sync 195 1 5 24 0.3
db file parallel read 310 0 4 12 0.4
control file sequential read 538 0 2 5 0.7
direct path write 16 0 0 16 0.0
SQL*Net break/reset to clien 136 0 0 1 0.2
buffer busy waits 22 0 0 0 0.0
LGWR wait for redo copy 21 0 0 0 0.0
undo segment extension 399 399 0 0 0.5
latch free 1 0 0 0 0.0
virtual circuit status 48,871 42 3,221 66 66.1
wakeup time manager 59 59 1,746 29597 0.1
jobq slave wait 258 249 790 3063 0.3
SQL*Net message from client 49,131 0 37 1 66.5
SQL*Net message to client 49,156 0 0 0 66.5
SQL*Net more data from clien 44 0 0 0 0.1
-------------------------------------------------------------
Background Wait Events for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
control file parallel write 581 0 16 27 0.8
db file parallel write 238 0 12 51 0.3
log file parallel write 706 579 6 9 1.0
control file sequential read 406 0 2 5 0.5
db file sequential read 53 0 0 6 0.1
db file scattered read 7 0 0 6 0.0
LGWR wait for redo copy 21 0 0 0 0.0
rdbms ipc reply 8 0 0 0 0.0
buffer busy waits 8 0 0 0 0.0
latch free 1 0 0 0 0.0
rdbms ipc message 3,758 2,868 10,842 2885 5.1
smon timer 21 1 1,818 86561 0.0
pmon timer 639 619 1,788 2798 0.9
-------------------------------------------------------------
SQL ordered by Gets for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
6,814,071 1 6,814,071.0 86.5 70.58 418.10 29903059
SELECT /*+ rule */ NVL(buut.name,'None') buut_nam
e, DECODE(prre.rev_type, 'PROD', prod.rerg_code,p
rre.rerg_code) rerg_code, DECODE(prre.rev_type, '
PROD', prre.src_product_code, 'PST', prre.src_prst_province_code
||' '||prre.rev_type, 'GST', prre

147,481 529 278.8 1.9 5.73 11.14 2117145654
Module: aspnet_wp.exe
begin PKG_CCH_ESHOP.PROC_CALCULATE_CHARGES(pAccountNumber=>:pAcc
ountNumber, pPrdsProductCode=>:pPrdsProductCode, pItemNumber=>:p
ItemNumber, pQuantity=>:pQuantity, pLicenseQty=>:pLicenseQty, pS
hippingProvinceCode=>:pShippingProvinceCode, pCircularCode=>:pCi
rcularCode, pProductCharge=>:pProductCharge, pShippingHandlingCh

125,671 10 12,567.1 1.6 6.69 42.65 3539150948
Module: aspnet_wp.exe
begin PKG_CCH_ESHOP.MOVE_PRE_ORDERS_TO_ORDERS(psequence=>:pseque
nce, pcontrol_order_line_item=>:pcontrol_order_line_item); end;

108,080 1 108,080.0 1.4 1.75 4.25 3310443653
select s.synonym_name object_name, o.object_type from sys.all_sy
nonyms s, sys.all_objects o where s.owner in ('PUBLIC', use
r) and o.owner = s.table_owner and o.object_name = s.table_name
and o.object_type in ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCED
URE', 'FUNCTION', 'SEQUENCE')

105,918 6 17,653.0 1.3 6.13 34.70 3223479914
Module: aspnet_wp.exe
SELECT MAX(JOB_ID) JOB_ID FROM JOB_LOGS WHERE MODULE_ID = 'SALE0
920'

93,272 1 93,272.0 1.2 10.33 34.81 526519504
Module: dllhost.exe
SELECT /*+ FIRST_ROWS(1) */ /* Backorders. Params. Territory :A
LL MonthFrom : 08 DayFrom : 31 YearFrom : 2005 MonthTo : 12 DayT
o : 12 YearTo : 2005 */ DISTINCT terr.code territory_code, SUB
STR(FCT_TERR_ACCOUNT_MANAGER(terr.code),1,40) manager_name, buu
t.name AS buut_name, a.no AS accno, a.cusi_no AS cusi_no, a.f

73,067 314 232.7 0.9 0.86 5.15 3944859978
Module: aspnet_wp.exe
SELECT COUNT(*) FROM SERVICE_PROFILES SEPR WHERE SEPR.ACCO_NO =
:B3 AND SEPR.STATUS IN ('A','F') AND SEPR.SPECIAL_PRICE_SECOND_C
OPY_FLAG = 'N' AND SEPR.PROD_PRDS_PRODUCT_CODE = :B2 AND SEPR.PR
OD_ITEM_NUMBER = :B1

SQL ordered by Reads for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
297,226 1 297,226.0 44.1 70.58 418.10 29903059
SELECT /*+ rule */ NVL(buut.name,'None') buut_nam
e, DECODE(prre.rev_type, 'PROD', prod.rerg_code,p
rre.rerg_code) rerg_code, DECODE(prre.rev_type, '
PROD', prre.src_product_code, 'PST', prre.src_prst_province_code
||' '||prre.rev_type, 'GST', prre

108,895 10 10,889.5 16.1 6.69 42.65 3539150948
Module: aspnet_wp.exe
begin PKG_CCH_ESHOP.MOVE_PRE_ORDERS_TO_ORDERS(psequence=>:pseque
nce, pcontrol_order_line_item=>:pcontrol_order_line_item); end;

105,840 6 17,640.0 15.7 6.13 34.70 3223479914
Module: aspnet_wp.exe
SELECT MAX(JOB_ID) JOB_ID FROM JOB_LOGS WHERE MODULE_ID = 'SALE0
920'

78,731 1 78,731.0 11.7 10.33 34.81 526519504
Module: dllhost.exe
SELECT /*+ FIRST_ROWS(1) */ /* Backorders. Params. Territory :A
LL MonthFrom : 08 DayFrom : 31 YearFrom : 2005 MonthTo : 12 DayT
o : 12 YearTo : 2005 */ DISTINCT terr.code territory_code, SUB
STR(FCT_TERR_ACCOUNT_MANAGER(terr.code),1,40) manager_name, buu
t.name AS buut_name, a.no AS accno, a.cusi_no AS cusi_no, a.f

57,501 1 57,501.0 8.5 7.38 28.79 1730062000
SELECT ROWID,CR_COLL_ACTION,NO,COMPANY_CODE,CUSTOMER_PO_NUMBER,O
RDER_PLACED_BY,ACCO_NO,CREATED_BY,CREATED_DATE,MODIFIED_DATE,MOD
IFIED_BY,APPROVED_DATE,APPROVED_BY,SHIN_CODE,INVOICE_COPIES,NATI
ONAL_CONTRACT_FLAG,ORDER_TYPE,STATUS,PAYMENT_METHOD,CRV_NO,ORRE_
NO FROM ORDERS WHERE ACCO_NO IN ( SELECT D.NO from collector_ter

22,076 1 22,076.0 3.3 3.05 9.45 1411394328
SELECT ROWID,CR_COLL_ACTION,NO,COMPANY_CODE,CUSTOMER_PO_NUMBER,O
RDER_PLACED_BY,ACCO_NO,CREATED_BY,CREATED_DATE,MODIFIED_DATE,MOD
IFIED_BY,APPROVED_DATE,APPROVED_BY,SHIN_CODE,INVOICE_COPIES,NATI
ONAL_CONTRACT_FLAG,ORDER_TYPE,STATUS,PAYMENT_METHOD,CRV_NO,ORRE_
NO FROM ORDERS WHERE STATUS = 'H' order by NO

Instance Activity Stats for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session 16,298 9.0 22.1
CPU used when call started 16,410 9.1 22.2
CR blocks created 260 0.1 0.4
DBWR buffers scanned 92,779 51.5 125.6
DBWR checkpoint buffers written 305 0.2 0.4
DBWR checkpoints 0 0.0 0.0
DBWR free buffers found 92,253 51.2 124.8
DBWR lru scans 116 0.1 0.2
DBWR make free requests 134 0.1 0.2
DBWR summed scan depth 92,779 51.5 125.6
DBWR transaction table writes 10 0.0 0.0
DBWR undo block writes 321 0.2 0.4
SQL*Net roundtrips to/from client 97,545 54.1 132.0
SQL*Net roundtrips to/from dblink 0 0.0 0.0
active txn count during cleanout 50 0.0 0.1
background checkpoints completed 0 0.0 0.0
background checkpoints started 0 0.0 0.0
background timeouts 2,141 1.2 2.9
branch node splits 0 0.0 0.0
buffer is not pinned count 5,695,404 3,160.6 7,706.9
buffer is pinned count 6,967,754 3,866.7 9,428.6
bytes received via SQL*Net from c 5,413,883 3,004.4 7,326.0
bytes received via SQL*Net from d 0 0.0 0.0
bytes sent via SQL*Net to client 5,615,677,226 3,116,358.1 7,599,022.0
bytes sent via SQL*Net to dblink 0 0.0 0.0
calls to get snapshot scn: kcmgss 75,305 41.8 101.9
calls to kcmgas 5,189 2.9 7.0
calls to kcmgcs 65 0.0 0.1
change write time 130 0.1 0.2
cleanout - number of ktugct calls 317 0.2 0.4
cleanouts and rollbacks - consist 7 0.0 0.0
cleanouts only - consistent read 261 0.1 0.4
cluster key scan block gets 3,240 1.8 4.4
cluster key scans 1,296 0.7 1.8
commit cleanout failures: block l 0 0.0 0.0
commit cleanout failures: buffer 0 0.0 0.0
commit cleanout failures: callbac 0 0.0 0.0
commit cleanout failures: cannot 0 0.0 0.0
commit cleanouts 6,471 3.6 8.8
commit cleanouts successfully com 6,471 3.6 8.8
commit txn count during cleanout 297 0.2 0.4
consistent changes 265 0.2 0.4
consistent gets 7,854,110 4,358.6 10,628.0
consistent gets - examination 6,835,292 3,793.2 9,249.4
current blocks converted for CR 0 0.0 0.0
cursor authentications 398 0.2 0.5
data blocks consistent reads - un 265 0.2 0.4
db block changes 30,022 16.7 40.6
db block gets 26,276 14.6 35.6
deferred (CURRENT) block cleanout 3,485 1.9 4.7
dirty buffers inspected 438 0.2 0.6
enqueue conversions 77 0.0 0.1
enqueue releases 13,254 7.4 17.9
enqueue requests 13,252 7.4 17.9
enqueue timeouts 0 0.0 0.0
enqueue waits 0 0.0 0.0
Instance Activity Stats for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491


Tablespace IO Stats for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491
->ordered by IOs (Reads + Writes) desc

Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
PROD_DAT07
198,618 110 1.1 1.0 5 0 0 0.0
PROD_DAT06
81,779 45 1.4 1.0 8 0 0 0.0
PROD_DAT03
17,701 10 6.9 12.5 33 0 0 0.0
PROD_DAT02
9,855 5 4.7 3.2 1 0 0 0.0
PROD_IDX04
9,508 5 2.7 1.0 13 0 0 0.0
PROD_DAT05
8,872 5 3.1 5.3 4 0 0 0.0
PROD_IDX06
7,818 4 1.9 1.0 27 0 0 0.0
PROD_DAT01
7,635 4 4.8 8.1 35 0 0 0.0
SYSTEM
1,504 1 4.6 1.1 94 0 1 0.0

init.ora Parameters for DB: ORA9I Instance: ORA9I Snaps: 2490 -2491

End value
Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
processes 200
timed_statistics TRUE
shared_pool_size 159383552
sga_max_size 1368467944
shared_pool_reserved_size 15728640
large_pool_size 629145600
java_pool_size 83886080
control_files C:\oracle\oradata\ORA9I\CONTROL
db_block_size 8192
db_cache_size 318767104
compatible 9.2.0.0.0
log_archive_start TRUE
log_archive_dest_1 LOCATION=D:\oracle\ARCHIVES\
log_archive_dest_2 LOCATION=C:\oraprd\ARCHIVES\
log_archive_dest_3 LOCATION=\\srvdev\oraprd\ARCHIVES
log_archive_format ORA9I%t_%s.dbf
db_file_multiblock_read_count 32
fast_start_mttr_target 300
control_file_record_keep_time 5
undo_management AUTO
undo_tablespace UNDOTBS1
undo_retention 7200
max_enabled_roles 60
remote_login_passwordfile EXCLUSIVE
db_domain
instance_name ORA9I
dispatchers (PROTOCOL=TCP) (SERVICE=ORA9IXD
job_queue_processes 10
hash_join_enabled TRUE
background_dump_dest C:\oracle\admin\ORA9I\bdump
user_dump_dest C:\oracle\admin\ORA9I\udump
core_dump_dest C:\oracle\admin\ORA9I\cdump
sort_area_size 52428800
db_name ORA9I
open_cursors 300
sql_trace FALSE
star_transformation_enabled FALSE
query_rewrite_enabled FALSE
pga_aggregate_target 52428800
workarea_size_policy AUTO
aq_tm_processes 1
-------------------------------------------------------------

End of Report



Tom Kyte
May 23, 2006 - 3:49 pm UTC

so, why didn't you compare them?

you are doing much more physical IO now, why is that.

We had the same symptom

Bauer Wolfgang, May 23, 2006 - 4:04 pm UTC

Hi,

I can remember we had something similar. Sometimes things where all right - then again everything went bad. It was because of some bad plans the CBO caculated. The application didn't use binds at that time and we had a lot of dynamic generated SQL (Java...).
To solve it we did:
- Changed the app to use binds as much as it was possible.
- Using Outlines for some "critical" SQLs.
- SQL tuning using Subqueryfactoring, ROWNUM and OPTIMZER_INDEX_COST_ADJ and of course eliminating some useless Statements.
- Calculating better stats, histograms and also used Stats to tune some Statements.
- Lot's of 10046 traces and a database logon trigger to enable it whenever we needed to.

Now we have a better control about the plans Oracle calculates. The performance ist very good since 5 Month now.

We didn't use statspak to tune but a mixture of Method R from Carry Milsap (read his book Optimizing Oracle Performance) and the knowledge we learned from Toms books (especially Expert One on One)

Regards
Wolfgang

ALexander the ok, May 23, 2006 - 4:22 pm UTC

Tom,

Curious why you are not flipping over his execute to parse? Shouldn't that be 99% or better on a production system?

Tom Kyte
May 24, 2006 - 7:02 am UTC

No, not really - depends on what the middle tier can do.

Mine is about 50-60% on asktom right now. I use mod_plsql. It is hard to get it much higher for me since a cursor will not remain open across web pages.

They have miles to go before we start looking at the java code and asking them to allow for cursor reuse here.

symptoms

Alex, May 24, 2006 - 3:49 am UTC

Hi Tom
thanks for the support.
Hi Abhishek

It seems to me, that it's StatspackMancy
(Guessing on a coffee-grounds by russian)
and offer one more variant.

Let suppose that we have:
1. Win2000 SE (2Gb per process, w/o /3GB option)
2. Peak of used memory in case of dedicated servers
1368467944(sga_max_size)+
177(process) * 52428800(sort_area_size) ~9Gb

3. For 15 minutes 8 sessions have probably died
(users have not waited the terminations of inquiries
because of possible swapping and have restarted computers - exempli gratia).
Then it is clear why such high rollback %

4. Less intense days are when we have 120-144 sessions.

IMHO only OTN's ace can reveal a problem having looked on one statspack report, other DBA it is necessary to start some own selects and to look performance of OS.

good luck


Tom Kyte
May 24, 2006 - 7:08 am UTC

... IMHO only OTN's ace can reveal a problem having looked on one statspack report, ...

no, not even then.

Alexander the ok, May 24, 2006 - 8:56 am UTC

Tom I think was confusing execute to parse with soft parse % from Effective Oracle by Design, my bad.

A reader

Sreenivasa Rao, May 24, 2006 - 4:23 pm UTC

Abishek,

As our expert TOM suggested, look for the bind variable usage.
Apart from this,there are two major wait events(already TOM pinpointed) affecting performance of your database. i.e

db file sequential read 148,603 4,782 74.51
db file scattered read 23,161 1,359 21.18

These 2 events constitutes 92 % of responce time.
So look at the following quries
------------------------------------------------
58,926 1 58,926.0 12.9 8.00 180.75 1404675027
SELECT ROWID,CR_COLL_ACTION,NO,COMPANY_CODE,CUSTOMER_PO_NUMBER,O
RDER_PLACED_BY,ACCO_NO,CREATED_BY,CREATED_DATE,MODIFIED_DATE,MOD
IFIED_BY,APPROVED_DATE,APPROVED_BY,SHIN_CODE,INVOICE_COPIES,NATI
ONAL_CONTRACT_FLAG,ORDER_TYPE,STATUS,PAYMENT_METHOD,CRV_NO,ORRE_
NO FROM ORDERS WHERE ACCO_NO IN ( SELECT D.NO from collector_ter

58,479 1 58,479.0 12.8 15.64 227.89 1502691368
select wcta . ta_terr_code , coll . user_id collector , a . acco
_no , nvl ( c . organization_name , b . first_name || ' ' || b
. last_name ) , a . invo_no , a . artc_code , b . crco_code_havi
ng_new , a . company_code , a . transaction_date , a . amount +
a . pst_charge + a . gst_charge + a . shipping_handling_charge +

54,002 2 27,001.0 11.8 8.47 222.53 571400938
select distinct orli.prod_prds_product_code prod_prds_product_co
de, orli.prod_item_number prod_item_number, prod.product_type pr
oduct_type, prod.full_title full_title from order_line_items orl
i, orders orde, products prod where orli.orde_no = orde.no and o
rde.status not in ('H','V','C') and orli.prod_prds_product_code

25,247 1 25,247.0 5.5 6.64 1126.69 2706485961
Module: dllhost.exe
SELECT /*+ FIRST_ROWS(1) */ /* Sales By Product. Params. Territ
ory :ALL MonthFrom : 5 DayFrom : 01 YearFrom : 2005 MonthTo : 2
DayTo : 28 YearTo : 2006 */ DISTINCT terr.code territory_code,
SUBSTR(FCT_TERR_ACCOUNT_MANAGER(terr.code),1,40) manager_name,
buut.name AS buut_name, a.no AS accno, a.cusi_no AS cusi_no,
-----------------------------------------------------

Study asktom book "Effective Oracle by Design" and try to tune these quries ,probably you quries are not using indexes and trying to do full table scans which is not always bad.

Regards,
Sreenivas.

Abhishek ? Why different hostnames

Irfan Khan, May 24, 2006 - 4:25 pm UTC

Abhishek

Why are we seeing 2 different hostnames here in statspack reports, which makes me feel that these are not same databases.

Please comment or am I missing something here

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
ORA9I 1505135597 ORA9I 1 9.2.0.5.0 NO TOMAHAWK


DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
ORA9I 1505135597 ORA9I 1 9.2.0.5.0 NO SRVPRD


soft parse % too low?

A reader, May 24, 2006 - 10:16 pm UTC

You mentioned in your first response that soft parse % jumped out at you as too low. I see in that report it is: Soft Parse %: 97.24
Is that alarmingly low?


Tom Kyte
May 25, 2006 - 1:31 pm UTC

yes, to me - the guy who cannot go 5 minutes without saying "bind variables"

99% and above is good.

Alexey, May 25, 2006 - 10:58 am UTC

Totally agree with Alex from SPb

Abhishek has about 10GB SGA+PGA and if there are 2-4GB physical RAM on the server - then the OS must be swapping like mad.

Tom Kyte
May 25, 2006 - 1:49 pm UTC

where do you see 10gb sga+pga???

Tons of tables

Citrus, January 09, 2007 - 3:54 am UTC

We are running on Oracle 10g R2. We have a third party application from whom we have purchased few modules but not the complete suite.

The application has more than 60,000 tables of which we hardly use 5,000 (our purchased module). Will it give us a database performance benefit if we remove the tables which are not used by us?
Tom Kyte
January 11, 2007 - 9:18 am UTC

only if you query the dictionary a lot and are having performance issues around the dictionary itself

How to deal with Unused Data

Shailesh, January 12, 2007 - 3:37 am UTC

Hi Tom,

With the passage of time the database starts getting heavier and heavier and If there is no provision in the code to handle such problem, Can something be done by DBA so that a percentage(or the records before a certain date) of the database could be kept in such a way that it is not accessessed until required.



or simply ask..



What steps are taken by the Oracle DBA when the database becomes too heavy and contains some records in tables which are rarely used but cant be deleted.


Thanks in Advance!!!!!

Try Partitioning

Tim, January 22, 2007 - 9:14 pm UTC

You could always make use of the partitioning option (although you will have to pay for it)

dictionary SQL

Igor, February 20, 2007 - 1:34 pm UTC

Hi Tom,

I am getting into situation (likely similar to Citrus, also on 10.2) with more and more schemas (currently around 250, they are "async" deleted) and dictionary queries are taking much more time than is usual (for example some of them does FTS on ts$, tab$, cdef$ etc as on some other instances). Each schema has 8000-10000 objects.
It's a QA environment with a lot of create/test/drop and some verifications that involves dictionary tables go much slower comparing on other instances we have. One example, for small schemas we need sometimes ~40 minutes to drop a schema objects. (Also, unfortunately, tablespaces are not reused, so ts$ continues to grow. )
In this situation, we are close to switch to share this "bottleneck" with more instances and instead of transportable tablespace we are using now, we started to think about to switch to to rman restore.
(Of course it will take much more resources)
Have you seen similar situation and what is point of view ?

Thank you.
Tom Kyte
February 20, 2007 - 3:15 pm UTC

how are you dropping things. what is your "process"

Drop process

Igor, February 21, 2007 - 5:53 am UTC

Droping goes by:
drop table ... purge
drop user ... cascade
drop tablespace ...
(tried also instance level recyclebin=OFF)

In some part in the load side (import metadata using transportable tablespace) do you know what this query is for:
SELECT COUNT(BAD)
FROM
SYS.IMP8CDT


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 0
Fetch 2 36.98 67.04 4950 10267411 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 36.99 67.05 4950 10267411 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=10267411 pr=4950 pw=0 time=67045364 us)
0 NESTED LOOPS (cr=10267411 pr=4950 pw=0 time=67045348 us)
3405815 INDEX FULL SCAN I_CON2 (cr=33683 pr=4558 pw=0 time=47681424 us)(object id 49)
0 TABLE ACCESS BY INDEX ROWID CDEF$ (cr=10233728 pr=392 pw=0 time=35758364 us)
3405814 INDEX UNIQUE SCAN I_CDEF1 (cr=6819648 pr=63 pw=0 time=17348369 us)(object id
50)

Thank you


Tom Kyte
February 21, 2007 - 11:06 am UTC

so, Ok, well - dropping 8k-10k of objects is going to ... well ... take a bit of time. You have 2,400 seconds (40 minutes), that is 3 or 4 objects dropped per second (free space, clean up, lots of work to do).

It is going to take a while.

perhaps for your QA, you just use a database/schema and "erase the database, restore datafiles" approach.

Igor, February 21, 2007 - 6:03 am UTC

Sorry, last one looks like that can be fixed with different execution plan. But anyway, do you know what bitand in view is for ?

Thank you

Thank you

Igor, February 22, 2007 - 4:59 am UTC

>> perhaps for your QA, you just use a database/schema and "erase the database, restore datafiles" approach.

Yes, that's inline with what we were thought about.
Unfortunately, that is one of aspects that I would agree with Sybase guys that Oracle needs more resources for same task (In Sybase drop database takes ~1 minute and all share same server memory).

Thank you
Tom Kyte
February 22, 2007 - 8:52 am UTC

In Oracle 'drop database' happens in 0 seconds.

well, as long as it takes to erase a set of files anyway.

Igor, February 22, 2007 - 1:04 pm UTC

>> In Oracle 'drop database' happens in 0 seconds.
>> well, as long as it takes to erase a set of files anyway.

Yes, right. Difference is that we have to do compromise between fast drop and resource sharing (can't share SGA with multiple instances).


More to Explore

Performance

Get all the information about database performance in the Database Performance guide.