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@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@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
***** The Database ***************
***********************************
11:34:58 system@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
------------------------------
MLOGPROD.ENRON.NET
STARTUP
--------------------
02/04/2001 15:17:03
***** The Query *****************
***********************************
11:16:05 system@mlogprod SQL> /
USERNAME SORTS PARSE CALLS BUFFER GETS ROWS_PROCESSED EXECUTIONS SQL
---------- ------- ----------- ------------ -------------- -----------
----------------------------------------
MLOG_ADMIN 0 23,428 52,859,035 8862581 44,340 select
log_record, raw_log_data_id from
raw_log_data where status = 'U' and log_
filename
= :1
1 row selected.
11:16:23 system@mlogprod SQL>
***** Session Waits **************
***********************************
11:16:23 system@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@mlogprod SQL>
***** The IO ********************
***********************************
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
---------- ---------- ----------- --------
-----------
sum 1195183 83 9,877.55 .69
9,878.23
8 rows selected.
10:38:57 system@mlogprod SQL>
***** truss output ***************
***********************************
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
23898: pread64(407, "0602\0\0\bC3DE\nC5E2 X93".., 8192, 0x7BC14000) = 8192
...
***** latch sleeps ***************
***********************************
11:17:10 system@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@mlogprod SQL>
--
Please see the official ORACLE-L FAQ: http://www.orafaq.com
--
Author:
INET: [EMAIL PROTECTED]
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: [EMAIL PROTECTED] (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).
