| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> Excessive IO problem after index partition split/rebuild
Dear List,
Here's a problem that a fellow DBA is experiencing, and for which I have not been much help. :(
This is the situation:
A session is started and the following query is issued:
select log_record, raw_log_data_id
from raw_log_data
where status = 'U' and log_filename = :1
Here's the table:
11:56:43 system_at_mlogprod SQL> desc mlog_mstr.raw_log_data
Name Null? Type ----------------------------- -------- -------------------- RAW_LOG_DATA_ID NOT NULL NUMBER(38) LOG_FILENAME NOT NULL VARCHAR2(200) PROCESS_TMSTMP DATE PARTNER_ACCT_ID NUMBER PROVIDER_ACCT_ID NUMBER RECORD_START_TIME DATE RECORD_END_TIME DATE LOG_RECORD CLOB MEDSVRTYP_CD VARCHAR2(10) STATUS NOT NULL CHAR(2) STATUS_CMT VARCHAR2(2000)
11:56:46 system_at_mlogprod SQL>
Here's the index being used by the query:
TABLE INDEXNAME COLUMNNAME POS
------------- --------------------- ----------------------------------- ----
RAW_LOG_DATA RAW_LOG_DATA_IX01 LOG_FILENAME 1
STATUS 2
( This is a local partitioned index. )
This query began this morning at 00:59:59
At the time the query started, there were 65 partitions in the index.
At 01:00:00 an operation began to split the overflow partition on the index, and then do an ALTER INDEX REBUILD partition on the new partition created by the split.
Here's where the fun starts. The partition split/rebuild was successful.
But the query that began 1 second earlier begins to behave very strangely.
This query normally runs in < 3 seconds. But under these circumstances it begins to read the same database block over and over from the empty partition that was just added.
Querying v$session_wait reveals the file and block:
USERNAME EVENT SID P1TEXT P1 P2TEXT
P2 TIME WAIT STATE
---------- ------------------------------ ------ ---------- ------------ ----------
------------ ------- ------- --------------------
MLOG_ADMIN db file sequential read 16 file# 35 block#
253450 0 423 WAITING
Querying dba_extents reveals the object and partition:
select segment_name, segment_type, partition_name
from dba_extents
where file_id = 35 and 253450 between block_id and
block_id + blocks - 1
/
SEGMENT_NAME SEGMENT_TYPE PARTITION_NAME
-------------------- ------------------ ------------------------------RAW_LOG_DATA_IX01 INDEX PARTITION P66 We have seen the wait on the read take well over an hour. After it completes, the next wait will be for the same file and block.
The stats that appear by querying the latch sleeps etc are misleading IMO, and merely a symptom of some other problem.
By doing a truss on the shadow process, it can be seen that a call to pread64() is being made millions of times in succession with the same parameters. ( see below )
This is a reproducable problem, as we have had several occurrences.
OWS is so far baffled.
If anyone has had a similar experience, and/or has some thoughts on the matter, it would be appreciated.
( See below for DB version, IO stats, latch sleeps, truss output, etc )
Thanks
Jared
The session of interest is SID 16 for MLOG_ADMIN
11:34:58 system_at_mlogprod SQL> @showdb
PRODUCT VERSION STATUS ------------------------------ -------------------- -------------------- NLSRTL 3.4.0.0.0 Production Oracle8i Enterprise Edition 8.1.6.1.0 Production PL/SQL 8.1.6.1.0 Production TNS for Solaris: 8.1.6.0.0 Production
Data Base
11:16:05 system_at_mlogprod SQL> /
USERNAME SORTS PARSE CALLS BUFFER GETS ROWS_PROCESSED EXECUTIONS SQL ---------- ------- ----------- ------------ -------------- -----------
raw_log_data where status = 'U' and log_
filename
= :1
11:16:23 system_at_mlogprod SQL>
11:16:23 system_at_mlogprod SQL> @sesswait
WAIT IN
USERNAME EVENT SID P1TEXT P1 P2TEXT
P2 TIME WAIT STATE
---------- ------------------------------ ------ ---------- ------------
---------- ------------ ------- ------- --------------------
DBAKEVIN SQL*Net message from client 21 driver id 1413697536 #bytes
1 0 2655 WAITING
43 driver id 1413697536 #bytes
1 0 2907 WAITING
72 driver id 1413697536 #bytes
1 0 2325 WAITING
56 driver id 1413697536 #bytes
1 0 0 WAITING
FOGLIGHT SQL*Net message from client 12 driver id 1413697536 #bytes
1 0 79 WAITING
MLOG_ADMIN db file sequential read 16 file# 35 block#
253450 0 579 WAITING
SYS SQL*Net message from client 8 driver id 1650815232 #bytes
1 0 2547 WAITING
SYSTEM SQL*Net message to client 10 driver id 1413697536 #bytes
1 -2 0 WAITED UNKNOWN TIME
8 rows selected.
11:17:10 system_at_mlogprod SQL>
File I/O report for Database: MLOGPROD
Start Time: 02/15/2001 10:36:55
End Time : 02/15/2001 10:38:56
Seconds: 121
RDS WRT
IOS
PER PER
PER R/W
DRIVE NAME RDTOT WRTOT SEC SEC
SEC RATIO
------------ -------------------- ---------- ---------- ----------- --------
----------- --------
/or0001h raw_log_data_m26.dbf 0 15 .00 .12
.12 .0
raw_log_index_m04.dbf 1195163 0 9,877.38 .00
9,877.38 ########
raw_log_index_m05.dbf 0 6 .00 .05
.05 .0
raw_log_index_s02.dbf 0 6 .00 .05
.05 .0
rbs01.dbf 3 43 .02 .36
.38 .1
rbs02.dbf 2 6 .02 .05
.07 .3
system01.dbf 15 1 .12 .01
.13 15.0
tools01.dbf 0 6 .00 .05
.05 .0
************ ---------- ---------- ----------- --------
-----------
sum 1195183 83 9,877.55 .69
9,878.23
8 rows selected.
10:38:57 system_at_mlogprod SQL>
11:17:10 system_at_mlogprod SQL> @$J/../apt/latch_sleeps
LATCH TYPE IMPACT SLEEP RATE WAITS HOLDING LEVEL ------------------------------------- ----------- ---------- ------------- ----- cache buffers chains 5931249 0.04% 2093541 1 library cache 289813 0.01% 11859691 5 undo global data 10141 0.00% 35422 5 row cache objects 8862 0.00% 909384 4 cache buffers lru chain 8347 0.00% 309822 3 redo allocation 7011 0.00% 700420 6 session idle bit 6749 0.00% 0 1 enqueue hash chains 3623 0.00% 36621 4 session allocation 3329 0.01% 63736 5 redo writing 3093 0.01% 221882 5 transaction allocation 1807 0.00% 60228 8 enqueues 1766 0.00% 39404 5...
11:19:14 system_at_mlogprod SQL>
-- Please see the official ORACLE-L FAQ: http://www.orafaq.com -- Author: INET: jkstill_at_cybcon.com Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051 San Diego, California -- Public Internet access / Mailing Lists -------------------------------------------------------------------- To REMOVE yourself from this mailing list, send an E-Mail message to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).Received on Thu Feb 15 2001 - 14:39:15 CST
 |
 |