Hello,
10 2 0 4 0 on hpux B.11 here :)
I have one procedure which normaly finishes in about 30-60 seconds, and now is active for the last 6 hours while showing extra big wait times on
db file parallel read and db file sequential read.
This is happening only while reading 2 specific tables.
Parallel DML is not used and parallel query also.
Tables that are being extremly slowly read are nethier created or altered with parallel option.
One table is >600gb range partitioned table and other is heap.
I traced that session for few minutes :
exec dbms_system.set_ev(241,44611,10046,12,'');
and then formatet generated trace file with
tkprof fas_ora_24643.trc fas_ora_24643.out sys=no sort=prsela exeela fchela
5 minuted tracing wrote this :
TKPROF: Release 10.2.0.4.0 - Production on Wed Apr 15 12:13:53 2009
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: fas_ora_24643.trc
Sort options: prsela exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SELECT NVL(SUM(DURATION),0)
FROM
LEAP_CUSTOMERS S, RTX R WHERE S.MSISDN=:B3 AND R.IMSI=S.IMSI AND
R.CALLDATETIME>:B2 AND R.CALLDATETIME<:B1 AND RTX_TYPE=1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 29 0.02 0.00 0 0 0 0
Fetch 29 1.41 159.77 29533 57624 0 29
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 58 1.43 159.77 29533 57624 0 29
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 12938 0.06 57.96
db file parallel read 439 0.32 98.90
********************************************************************************
SELECT TOTAL_AMOUNT
FROM
LEAP_INVOICES WHERE SUBSCRIBER_ID=:B1 ORDER BY DUE_DATE DESC
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 19 0.00 0.02 0 0 0 0
Fetch 19 0.00 4.10 0 0 0 154
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 38 0.00 4.13 0 0 0 154
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 38 0.00 0.00
SQL*Net message from dblink 38 0.37 3.71
********************************************************************************
SELECT COUNT(*)
FROM
AUTO_RULES_ELEMENTS WHERE MSISDN=:B1 AND CREATE_DATE>TRUNC(SYSDATE) AND
RULE_ID IN (-1,-2)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 12 0.01 0.00 0 0 0 0
Fetch 12 0.01 0.42 0 0 0 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 24 0.02 0.43 0 0 0 12
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 24 0.00 0.00
SQL*Net message from dblink 24 0.07 0.42
********************************************************************************
SELECT COUNT(*)
FROM
AUTO_RULES_ELEMENTS WHERE MSISDN=:B2 AND CREATE_DATE>TO_DATE(:B1 ,
'yyyymmddhh24miss') AND RULE_ID=-1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 6 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.19 0 0 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.00 0.19 0 0 0 6
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 12 0.00 0.00
SQL*Net message from dblink 12 0.03 0.19
********************************************************************************
SELECT SUBSCRIBER_ID,IMSI, CUSTOMER_ID
FROM
LEAP_CUSTOMERS S WHERE S.IMSI=:B1 ORDER BY SUBSCRIBER_ACT_DATE DESC
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 29 0.00 0.00 0 0 0 0
Fetch 29 0.00 0.13 35 95 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 58 0.00 0.13 35 95 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 35 0.04 0.13
********************************************************************************
SELECT SUBSCRIBER_ID,MSISDN, CUSTOMER_ID
FROM
LEAP_CUSTOMERS S WHERE S.IMSI=:B1 ORDER BY SUBSCRIBER_ACT_DATE DESC
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 29 0.00 0.00 0 0 0 0
Fetch 29 0.00 0.02 13 121 0 29
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 58 0.00 0.02 13 121 0 29
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 13 0.00 0.01
********************************************************************************
INSERT INTO AUTO_RULES_ELEMENTS ( ID, RULE_ID, CREATE_DATE, FM_ID, BAN, IMSI,
MSISDN, AMOUNT, STATE, CUSTOMER_ID)
VALUES
( AUTO_RULES_ELEMENTS_SEQ.NEXTVAL, :B7 , SYSDATE, :B6 , :B5 , :B4 , :B3 ,
:B2 /60, 1,:B1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 10
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.00 0.00 0 0 0 10
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 49 (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 10 0.00 0.00
SQL*Net message from dblink 10 0.00 0.00
********************************************************************************
SELECT /*+ ordered */ L.FM_ID, F.IMSI,SUBSTR(F.MSISDN,3) MSISDN, SUM(DURATION)
DURATION
FROM
FM_IMSI_LIST L, LEAP_FRIENDS F,RTX R WHERE L.GROUP_ID=6 AND
L.CUSTOMER_IDENT_VAL=F.IMSI AND CUSTOMER_IDENT_ID=202 AND R.O_P_MSISDN=
F.MSISDN AND RTX_TYPE=1 AND R.IMSI=F.IMSI AND CALLDATETIME>:B3 AND
R.CALLDATETIME<:B2 GROUP BY L.FM_ID, F.IMSI,F.MSISDN HAVING SUM(DURATION)
>:B1 /2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 100
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 100
Misses in library cache during parse: 0
Parsing user id: 49 (recursive depth: 2)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 6 0.00 0.00
SQL*Net message from dblink 6 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 134 0.03 0.04 0 0 0 10
Fetch 125 1.42 164.66 29581 57840 0 331
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 259 1.45 164.71 29581 57840 0 341
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 12986 0.06 58.11
db file parallel read 439 0.32 98.90
SQL*Net message to dblink 78 0.00 0.00
SQL*Net message from dblink 78 0.37 4.34
10 user SQL statements in session.
0 internal SQL statements in session.
10 SQL statements in session.
********************************************************************************
Trace file: fas_ora_24643.trc
Trace file compatibility: 10.01.00
Sort options: prsela exeela fchela
31 sessions in tracefile.
10 user SQL statements in trace file.
0 internal SQL statements in trace file.
10 SQL statements in trace file.
8 unique SQL statements in trace file.
15096 lines in trace file.
164 elapsed seconds in trace file.
It's pretty obvious that
SELECT NVL(SUM(DURATION),0)
FROM
LEAP_CUSTOMERS S, RTX R WHERE S.MSISDN=:B3 AND R.IMSI=S.IMSI AND
R.CALLDATETIME>:B2 AND R.CALLDATETIME<:B1 AND RTX_TYPE=1
pops out with those stats.
It seems that this session is now doing select operation on those 2 tables zilion times slower that usual
Why ?
I executed only select from new session with the same user , with different CALLDATETIME values and it finishes in sec or two.
Note that rtx table is range partitioned by CALLDATETIME column.
Last date that rtx and leap_customers have been last analyzed is 11.3.2009 with default configured GATHER_STATS_JOB .
This would be one autotrace of that strange select from another session wth the same user:
SQL> SELECT NVL (SUM (DURATION), 0)
FROM leap_customers s, rtx r
WHERE s.msisdn = 375296569321
AND r.imsi = s.imsi
AND r.calldatetime > 20090301000246
AND r.calldatetime < 20090319000246
AND rtx_type = 1 2 3 4 5 6 7 ;
NVL(SUM(DURATION),0)
--------------------
3604
Elapsed: 00:00:01.85
Execution Plan
----------------------------------------------------------
Plan hash value: 247540042
--------------------------------------------------------------------------------
------------------------------------------
| Id | Operation | Name | Rows | Bytes
| Cost (%CPU)| Time | Pstart| Pstop |
--------------------------------------------------------------------------------
------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 68
| 6805 (2)| 00:01:22 | | |
| 1 | SORT AGGREGATE | | 1 | 68
| | | | |
|* 2 | TABLE ACCESS BY LOCAL INDEX ROWID| RTX | 2 | 76
| 4623 (1)| 00:00:56 | | |
| 3 | NESTED LOOPS | | 2 | 136
| 6805 (2)| 00:01:22 | | |
|* 4 | INDEX FAST FULL SCAN | LEAP_CUSTOMERS_IDX5 | 1 | 30
| 2182 (5)| 00:00:27 | | |
| 5 | PARTITION RANGE ALL | | 2095 |
| 2787 (1)| 00:00:34 | 1 | 1392 |
|* 6 | INDEX RANGE SCAN | RTX_IDX__IMSI | 2095 |
| 2787 (1)| 00:00:34 | 1 | 1392 |
--------------------------------------------------------------------------------
------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("RTX_TYPE"=1 AND TO_NUMBER("R"."CALLDATETIME")>20090301000246 AND
TO_NUMBER("R"."CALLDATETIME")<20090319000246)
4 - filter(TO_NUMBER("S"."MSISDN")=375296569321)
6 - access("R"."IMSI"="S"."IMSI")
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
22447 consistent gets
21553 physical reads
0 redo size
528 bytes sent via SQL*Net to client
492 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
There were no altering any init ora parameters for any session,
these are values that are valid for session that is hanging on those 2 wait events and also that were valid for session that i used to test this select.
SQL> sho parameter optimizer
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
optimizer_dynamic_sampling integer 2
optimizer_features_enable string 10.2.0.4
optimizer_index_caching integer 0
optimizer_index_cost_adj integer 100
optimizer_mode string CHOOSE
optimizer_secure_view_merging boolean TRUE
SQL> sho parameter bloc
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_block_buffers integer 0
db_block_checking string FALSE
db_block_checksum string TRUE
db_block_size integer 8192
db_file_multiblock_read_count integer 32
SQL> sho parameter index
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
optimizer_index_caching integer 0
optimizer_index_cost_adj integer 100
skip_unusable_indexes boolean TRUE
What are your observations on this ?
How could this be interpreted ?