| 实例2上语句长时间等待某个块

实例2上语句长时间等待某个块

作者：OoNiceDream【转载时请务必以超链接形式标明文章原始出处和作者信息】
链接：http://www.dbaroad.me/archives/2009/04/buffer_busy_waits_block.html

故障现象：相同的语句，在实例1上运行正常，实例二上长时间的“buffer busy waits”在等待某个块。

实例二：

SYS@ZJDB2> @login_ZJDB2
 
INSTANCE_NUMBER INSTANCE_NAME   NAME       OPEN_MODE  LOG_MODE        CHECKPOINT_CHANGE#
--------------- --------------- ---------- ---------- --------------- ------------------
              2 ZJDB2           ZJDB       READ WRITE ARCHIVELOG          10739870502834
 
SPID                SID    SERIAL# OSUSER          PROCESS      MACHINE
------------ ---------- ---------- --------------- ------------ --------------------
632660              107      10429 NiceDream       2220:2224    WORKGROUP\OONICEDREA
                                                                M
 
SYS@ZJDB2> select count(*) from uname.tab_test_all ;
 
  COUNT(*)
----------
     25207
SYS@ZJDB2> SELECT DISTINCT COLU_ID
  2    FROM (SELECT TTA.BILL_COLU_ID,
  3                 TTA.COLU_ID,
  4                 TTA.SRV_CODE,
  5                 TTA.COLUMN_T,
  6                 TTA.COLUMN_OR
  7            FROM UNAME.TAB_TEST_ALL TTA
  8           WHERE TTA.ST = '201'
  9              AND TBL_ID = 71
10           ORDER BY TTA.SRV_CODE,
11                    TTA.COLUMN_OR DESC,
12                    TTA.COLUMN_T DESC)
13   where ROWNUM < = 1;

接着就是长时间的等待。
另开一个会话做10046 trace，发现就是长时间的等待343\290850这个块

SQL> oradebug setospid 632660
Oracle pid: 596, Unix process pid: 632660, image: oracle@pg_db_2 (TNS V1-V3)
SQL> oradebug event 10046 trace name context forever,level 12;
Statement processed.
SQL> oradebug tracefile_name
/app/oracle/admin/ZJDB/udump/zjdb2_ora_632660.trc
SQL> 
SQL> !
[/home/oracle]$ tail -f /app/oracle/admin/ZJDB/udump/zjdb2_ora_632660.trc
WAIT #1: nam='buffer busy waits' ela= 976577 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 378257 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976577 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976579 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976578 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976579 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976579 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976580 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976577 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976577 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976581 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976578 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976577 p1=343 p2=290850 p3=130
WAIT #1: nam='buffer busy waits' ela= 976592 p1=343 p2=290850 p3=130

而实例1上能很快的返回结果：

SYS@ZJDB1> set timi on
SYS@ZJDB1> SELECT DISTINCT COLU_ID
  2    FROM (SELECT TTA.BILL_COLU_ID,
  3                 TTA.COLU_ID,
  4                 TTA.SRV_CODE,
  5                 TTA.COLUMN_T,
  6                 TTA.COLUMN_OR
  7            FROM UNAME.TAB_TEST_ALL TTA
  8           WHERE TTA.ST = '201'
  9              AND TBL_ID = 71
 10           ORDER BY TTA.SRV_CODE,
 11                    TTA.COLUMN_OR DESC,
 12                    TTA.COLUMN_T DESC)
 13   where ROWNUM < = 1;
 
COLU_ID
--------------------------------------------------
71370828703
已用时间:  00: 00: 01.05
SYS@ZJDB1>

尝试Flash buffer cache，还是不行。

DUMP这个块的相关信息：

SQL> select count(*) from uname.tab_test_all where
  2  dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=290850 and dbms_rowid.ROWID_RELATIVE_FNO(rowid)=343;
 
  COUNT(*)
----------
         0
 
SQL> show parameter inst
 
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
active_instance_count                integer
cluster_database_instances           integer     2
instance_groups                      string
instance_name                        string      ZJDB2
instance_number                      integer     2
open_links_per_instance              integer     4
parallel_instance_group              string
parallel_server_instances            integer     2
SQL> 
 
 
SQL> alter system dump datafile 343 block 290850;
 
System altered.
 
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug tracefile_name
/app/oracle/admin/ZJDB/udump/zjdb1_ora_922898.trc
 
*** 2009-04-01 20:29:31.555
*** SESSION ID:(1775.6698) 2009-04-01 20:29:31.547
Start dump data blocks tsn: 7 file#: 343 minblk 290850 maxblk 290850
buffer tsn: 7 rdba: 0x55c47022 (343/290850)
scn: 0x09c4.9147c39f seq: 0x01 flg: 0x06 tail: 0xc39f0601
frmt: 0x02 chkval: 0x4500 type: 0x06=trans data
Block header dump:  0x55c47022
 Object id on Block? Y
 seg/obj: 0x53dcd  csc: 0x9c4.9147b171  itc: 36  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x55c47009 ver: 0x01
     inc: 0  exflg: 0
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0053.02d.00097c98  0xce436c7e.44d2.04  C---    0  scn 0x09c4.8fa42462
0x02   0x0009.02c.001222ea  0xce00feaa.f56c.25  C---    0  scn 0x09c4.8f622a98
0x03   0x0052.00d.000de212  0x00c5e254.51b3.0c  C---    0  scn 0x09c4.8f626839
0x04   0x0009.014.00123429  0xce00feaa.f56c.1f  C---    0  scn 0x09c4.8f622a69
0x05   0x002f.02d.000d8703  0xce048db2.7b89.44  C---    0  scn 0x09c4.9143a1f2
0x06   0x0009.016.001233e9  0xce00feaa.f56c.0a  C---    0  scn 0x09c4.8f622a19
0x07   0x0009.028.00123429  0xce00feaa.f56c.13  C---    0  scn 0x09c4.8f622a37
0x08   0x0009.01c.001221b2  0xce00feaa.f56c.22  C---    0  scn 0x09c4.8f622a73
0x09   0x0033.00a.0003ca0a  0x0081473c.4757.1d  C---    0  scn 0x09c4.8f62490e
0x0a   0x0053.012.00097d6f  0xce43a868.44d1.20  C---    0  scn 0x09c4.8f9c1ed9
0x0b   0x0052.02b.000dd353  0x00c5e25b.51b3.04  C---    0  scn 0x09c4.8f62693a
0x0c   0x0009.02b.0012325c  0xce00fea7.f56c.1c  C---    0  scn 0x09c4.8f622a00
0x0d   0x0009.009.001232a2  0xce00feaa.f56c.0d  C---    0  scn 0x09c4.8f622a1d
0x0e   0x0034.00d.00072013  0x00c12591.64ce.01  C---    0  scn 0x09c4.8f624d98
0x0f   0x001f.007.000f152c  0xce43dbea.aea1.3b  C---    0  scn 0x09c4.8fbe1182
0x10   0x0009.02e.0012292f  0xce00fea7.f56c.19  C---    0  scn 0x09c4.8f6229e8
0x11   0x0052.011.000deb20  0x00c5e254.51b3.08  C---    0  scn 0x09c4.8f62680c
0x12   0x0052.009.000dd4ee  0x00c5e259.51b3.1e  C---    0  scn 0x09c4.8f62692f
0x13   0x0009.00a.001231b1  0xce00feaa.f56c.07  C---    0  scn 0x09c4.8f622a08
0x14   0x0009.013.00123306  0xce00feaa.f56c.04  C---    0  scn 0x09c4.8f622a06
0x15   0x0009.018.0012041a  0xce00feaa.f56c.16  C---    0  scn 0x09c4.8f622a48
0x16   0x003f.017.0010c240  0xce844ff3.80f9.0a  C---    0  scn 0x09c4.903a9199
0x17   0x0009.006.0012335b  0xce00feaa.f56c.2b  C---    0  scn 0x09c4.8f622ab2
0x18   0x0009.00f.0012299a  0xce00feaa.f56c.2e  C---    0  scn 0x09c4.8f622acd
0x19   0x0009.007.0012338e  0xce00feaa.f56c.19  C---    0  scn 0x09c4.8f622a4f
0x1a   0x0009.004.001233a9  0xce00feaa.f56c.28  C---    0  scn 0x09c4.8f622a9e
0x1b   0x0009.024.00121fbd  0xce00feaa.f56c.31  C---    0  scn 0x09c4.8f622ad1
0x1c   0x0033.023.0003ca25  0x0081473c.4757.25  C---    0  scn 0x09c4.8f624926
0x1d   0x0052.012.000dc47b  0x00c5e257.51b3.04  C---    0  scn 0x09c4.8f626863
0x1e   0x002f.014.000d737c  0xce44a870.7b8a.29  --U-    1  fsc 0x00ab.9147c39f
0x1f   0x0045.006.000c66bb  0xce83117c.69f6.02  C---    0  scn 0x09c4.90728799
0x20   0x004a.01c.0005726c  0x0083aa7c.4c20.14  C---    0  scn 0x09c4.90ba9413
0x21   0x0052.016.000de155  0x00c5e254.51b3.04  C---    0  scn 0x09c4.8f6267f7
0x22   0x0053.008.00097ec5  0x0083df31.44de.01  C---    0  scn 0x09c4.903afa9d
0x23   0x0009.021.00123350  0xce00feaa.f56c.10  C---    0  scn 0x09c4.8f622a32
0x24   0x0009.026.00123383  0xce00feaa.f56c.1c  C---    0  scn 0x09c4.8f622a62
 
data_block_dump,data header at 0x1102a1394
===============
tsiz: 0x1c68
hsiz: 0x70
pbl: 0x1102a1394
bdba: 0x55c47022
     76543210
flag=--------
ntab=1
nrow=47
frre=0
fsbo=0x70
fseo=0x73
avsp=0x1b4b
tosp=0x1bf8
0xe:pti[0]      nrow=47 offs=0
0x12:pri[0]     sfll=1
0x14:pri[1]     sfll=2
0x16:pri[2]     sfll=3
0x18:pri[3]     sfll=4
0x1a:pri[4]     sfll=5
0x1c:pri[5]     sfll=6
0x1e:pri[6]     sfll=7
0x20:pri[7]     sfll=8
0x22:pri[8]     sfll=9
0x24:pri[9]     sfll=10
0x26:pri[10]    sfll=11
0x28:pri[11]    sfll=12
0x2a:pri[12]    sfll=13
0x2c:pri[13]    sfll=14
0x2e:pri[14]    sfll=15
0x30:pri[15]    sfll=16
0x32:pri[16]    sfll=17
0x34:pri[17]    sfll=18
0x36:pri[18]    sfll=19
0x38:pri[19]    sfll=20
0x3a:pri[20]    sfll=21
0x3c:pri[21]    sfll=22
0x3e:pri[22]    sfll=23
0x40:pri[23]    sfll=24
0x42:pri[24]    sfll=25
0x44:pri[25]    sfll=26
0x46:pri[26]    sfll=27
0x48:pri[27]    sfll=28
0x4a:pri[28]    sfll=29
0x4c:pri[29]    sfll=30
0x4e:pri[30]    sfll=31
0x50:pri[31]    sfll=32
0x52:pri[32]    sfll=33
0x54:pri[33]    sfll=34
0x56:pri[34]    sfll=35
0x58:pri[35]    sfll=36
0x5a:pri[36]    sfll=37
0x5c:pri[37]    sfll=38
0x5e:pri[38]    sfll=39
0x60:pri[39]    sfll=41
0x62:pri[40]    offs=0x73
0x64:pri[41]    sfll=42
0x66:pri[42]    sfll=43
0x68:pri[43]    sfll=44
0x6a:pri[44]    sfll=45
0x6c:pri[45]    sfll=46
0x6e:pri[46]    sfll=-1
block_row_dump:
tab 0, row 40, @0x73
tl: 2 fb: --HDFL-- lb: 0x1e 
end_of_block_dump
End dump data blocks tsn: 7 file#: 343 minblk 290850 maxblk 290850

临时的解决办法是，停应用，原表RENAME成“_BAK”表，新建一张表，将数据导进去。
晚上重启后，发现实例2上已能正常的查询该表，再DUMP该块，前后的DUMP信息相同

SYS@ZJDB1> set timi on
SYS@ZJDB1> SELECT DISTINCT COLU_ID
  2    FROM (SELECT TTA.BILL_COLU_ID,
  3                 TTA.COLU_ID,
  4                 TTA.SRV_CODE,
  5                 TTA.COLUMN_T,
  6                 TTA.COLUMN_OR
  7            FROM UNAME.TAB_TEST_ALL TTA
  8           WHERE TTA.ST = '201'
  9              AND TBL_ID = 71
10           ORDER BY TTA.SRV_CODE,
11                    TTA.COLUMN_OR DESC,
12                    TTA.COLUMN_T DESC)
13   where ROWNUM < = 1;
 
COLU_ID
--------------------------------------------------
71370828703
 
Elapsed: 00:00:00.05
SQL> show parameter inst
 
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
active_instance_count                integer
cluster_database_instances           integer     2
instance_groups                      string
instance_name                        string      ZJDB2
instance_number                      integer     2
open_links_per_instance              integer     4
parallel_instance_group              string
parallel_server_instances            integer     2
 
SQL> select count(*) from uname.tab_test_all where
  2  dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=290850 and dbms_rowid.ROWID_RELATIVE_FNO(rowid)=343;
 
  COUNT(*)
----------
         0
 
SQL> alter system dump datafile 343 block 290850;
 
System altered.
 
SQL> oradebug setmypid
Statement processed.
SQL> oradebug tracefile_name
/app/oracle/admin/ZJDB/udump/zjdb2_ora_26054.trc
 
*** 2009-04-02 00:37:51.764
*** SESSION ID:(32.3) 2009-04-02 00:37:51.760
Start dump data blocks tsn: 7 file#: 343 minblk 290850 maxblk 290850
buffer tsn: 7 rdba: 0x55c47022 (343/290850)
scn: 0x09c4.9147c39f seq: 0x01 flg: 0x06 tail: 0xc39f0601
frmt: 0x02 chkval: 0x4500 type: 0x06=trans data
Block header dump:  0x55c47022
 Object id on Block? Y
 seg/obj: 0x53dcd  csc: 0x9c4.9147b171  itc: 36  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x55c47009 ver: 0x01
     inc: 0  exflg: 0
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0053.02d.00097c98  0xce436c7e.44d2.04  C---    0  scn 0x09c4.8fa42462
0x02   0x0009.02c.001222ea  0xce00feaa.f56c.25  C---    0  scn 0x09c4.8f622a98
0x03   0x0052.00d.000de212  0x00c5e254.51b3.0c  C---    0  scn 0x09c4.8f626839
0x04   0x0009.014.00123429  0xce00feaa.f56c.1f  C---    0  scn 0x09c4.8f622a69
0x05   0x002f.02d.000d8703  0xce048db2.7b89.44  C---    0  scn 0x09c4.9143a1f2
0x06   0x0009.016.001233e9  0xce00feaa.f56c.0a  C---    0  scn 0x09c4.8f622a19
0x07   0x0009.028.00123429  0xce00feaa.f56c.13  C---    0  scn 0x09c4.8f622a37
0x08   0x0009.01c.001221b2  0xce00feaa.f56c.22  C---    0  scn 0x09c4.8f622a73
0x09   0x0033.00a.0003ca0a  0x0081473c.4757.1d  C---    0  scn 0x09c4.8f62490e
0x0a   0x0053.012.00097d6f  0xce43a868.44d1.20  C---    0  scn 0x09c4.8f9c1ed9
0x0b   0x0052.02b.000dd353  0x00c5e25b.51b3.04  C---    0  scn 0x09c4.8f62693a
0x0c   0x0009.02b.0012325c  0xce00fea7.f56c.1c  C---    0  scn 0x09c4.8f622a00
0x0d   0x0009.009.001232a2  0xce00feaa.f56c.0d  C---    0  scn 0x09c4.8f622a1d
0x0e   0x0034.00d.00072013  0x00c12591.64ce.01  C---    0  scn 0x09c4.8f624d98
0x0f   0x001f.007.000f152c  0xce43dbea.aea1.3b  C---    0  scn 0x09c4.8fbe1182
0x10   0x0009.02e.0012292f  0xce00fea7.f56c.19  C---    0  scn 0x09c4.8f6229e8
0x11   0x0052.011.000deb20  0x00c5e254.51b3.08  C---    0  scn 0x09c4.8f62680c
0x12   0x0052.009.000dd4ee  0x00c5e259.51b3.1e  C---    0  scn 0x09c4.8f62692f
0x13   0x0009.00a.001231b1  0xce00feaa.f56c.07  C---    0  scn 0x09c4.8f622a08
0x14   0x0009.013.00123306  0xce00feaa.f56c.04  C---    0  scn 0x09c4.8f622a06
0x15   0x0009.018.0012041a  0xce00feaa.f56c.16  C---    0  scn 0x09c4.8f622a48
0x16   0x003f.017.0010c240  0xce844ff3.80f9.0a  C---    0  scn 0x09c4.903a9199
0x17   0x0009.006.0012335b  0xce00feaa.f56c.2b  C---    0  scn 0x09c4.8f622ab2
0x18   0x0009.00f.0012299a  0xce00feaa.f56c.2e  C---    0  scn 0x09c4.8f622acd
0x19   0x0009.007.0012338e  0xce00feaa.f56c.19  C---    0  scn 0x09c4.8f622a4f
0x1a   0x0009.004.001233a9  0xce00feaa.f56c.28  C---    0  scn 0x09c4.8f622a9e
0x1b   0x0009.024.00121fbd  0xce00feaa.f56c.31  C---    0  scn 0x09c4.8f622ad1
0x1c   0x0033.023.0003ca25  0x0081473c.4757.25  C---    0  scn 0x09c4.8f624926
0x1d   0x0052.012.000dc47b  0x00c5e257.51b3.04  C---    0  scn 0x09c4.8f626863
0x1e   0x002f.014.000d737c  0xce44a870.7b8a.29  --U-    1  fsc 0x00ab.9147c39f
0x1f   0x0045.006.000c66bb  0xce83117c.69f6.02  C---    0  scn 0x09c4.90728799
0x20   0x004a.01c.0005726c  0x0083aa7c.4c20.14  C---    0  scn 0x09c4.90ba9413
0x21   0x0052.016.000de155  0x00c5e254.51b3.04  C---    0  scn 0x09c4.8f6267f7
0x22   0x0053.008.00097ec5  0x0083df31.44de.01  C---    0  scn 0x09c4.903afa9d
0x23   0x0009.021.00123350  0xce00feaa.f56c.10  C---    0  scn 0x09c4.8f622a32
0x24   0x0009.026.00123383  0xce00feaa.f56c.1c  C---    0  scn 0x09c4.8f622a62
 
data_block_dump,data header at 0x1102a1394
===============
tsiz: 0x1c68
hsiz: 0x70
pbl: 0x1102a1394
bdba: 0x55c47022
     76543210
flag=--------
ntab=1
nrow=47
frre=0
fsbo=0x70
fseo=0x73
avsp=0x1b4b
tosp=0x1bf8
0xe:pti[0]      nrow=47 offs=0
0x12:pri[0]     sfll=1
0x14:pri[1]     sfll=2
0x16:pri[2]     sfll=3
0x18:pri[3]     sfll=4
0x1a:pri[4]     sfll=5
0x1c:pri[5]     sfll=6
0x1e:pri[6]     sfll=7
0x20:pri[7]     sfll=8
0x22:pri[8]     sfll=9
0x24:pri[9]     sfll=10
0x26:pri[10]    sfll=11
0x28:pri[11]    sfll=12
0x2a:pri[12]    sfll=13
0x2c:pri[13]    sfll=14
0x2e:pri[14]    sfll=15
0x30:pri[15]    sfll=16
0x32:pri[16]    sfll=17
0x34:pri[17]    sfll=18
0x36:pri[18]    sfll=19
0x38:pri[19]    sfll=20
0x3a:pri[20]    sfll=21
0x3c:pri[21]    sfll=22
0x3e:pri[22]    sfll=23
0x40:pri[23]    sfll=24
0x42:pri[24]    sfll=25
0x44:pri[25]    sfll=26
0x46:pri[26]    sfll=27
0x48:pri[27]    sfll=28
0x4a:pri[28]    sfll=29
0x4c:pri[29]    sfll=30
0x4e:pri[30]    sfll=31
0x50:pri[31]    sfll=32
0x52:pri[32]    sfll=33
0x54:pri[33]    sfll=34
0x56:pri[34]    sfll=35
0x58:pri[35]    sfll=36
0x5a:pri[36]    sfll=37
0x5c:pri[37]    sfll=38
0x5e:pri[38]    sfll=39
0x60:pri[39]    sfll=41
0x62:pri[40]    offs=0x73
0x64:pri[41]    sfll=42
0x66:pri[42]    sfll=43
0x68:pri[43]    sfll=44
0x6a:pri[44]    sfll=45
0x6c:pri[45]    sfll=46
0x6e:pri[46]    sfll=-1
block_row_dump:
tab 0, row 40, @0x73
tl: 2 fb: --HDFL-- lb: 0x1e 
end_of_block_dump
End dump data blocks tsn: 7 file#: 343 minblk 290850 maxblk 290850

挺怪的问题，不知道大家有没有发现什么异常之处，类似的问题，有什么好的解决办法？

— The End —

关键字: 故障案例

上一篇限制用户只能KILL本用户的会话

无法查询v$session_wait 下一篇

喜欢DBARoad的文章，那就通过 RSS Feed 功能订阅阅读吧！

随机文章

已经有4 个评论

1楼
04月 7th, 2009 at 10:00 jlttt 说:
有没有检查下这个块是否坏掉？

Reply
OoNiceDream Reply:
04月 7th, 2009 at 16:49
应该不是块掉了，要是块掉，访问时应该就会报出来了，重启完，查询该语句速度就很快了。

Reply
2楼
06月 5th, 2009 at 12:02 AndrewBoldman 说:
The article on antibiotics are very good.

Reply
3楼
07月 20th, 2009 at 21:42 Freedba 说:
SQL> select count(*) from uname.tab_test_all where
2 dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=290850 and dbms_rowid.ROWID_RELATIVE_FNO(rowid)=343;

COUNT(*)
———-
0

结果为0,buffer busy wait等的不是data block?
可能是undo block?dba_extents看看

Reply

公告牌:

当前位置: DBARoad > 故障案例, 本站推荐 > 文章正文

实例2上语句长时间等待某个块

相关文章

随机文章

已经有4 个评论

我要评论

相关文章

最新文章

订阅

站内搜索