请教：创建表空间非常慢

Yong Huang

Now I see why it's related to the jobs. In 11gR2, the background process SMCO (space management coordinator) and its slave W00n coordinate space management. See
https://supporthtml.oracle.com/e ... id=743773.1&h=Y
Since your W00n keeps dying and restarting (it's not a fatal background process so its death won't crash instance), the datafile creation constantly gets interrupted. Instead of looking at alert.log, you can (1) check the job-related traces and the W00n traces. Let us know anything interesting in there.

Ignore "kewastUnPackStats(): bad magic 1".

Again, (2) let us know interesting messages in /var/log/messages, if any.

(3) Do you have TrendMicro running (ps -ef | grep vsapiapp)? We had serious issues with it during file creation or copying.

I list 3 action items for you shown above. Hope you don't miss any one.

FYI, for all new background processes in 11gR2, refer to
https://supporthtml.oracle.com/e ... id=444149.1&h=Y

Yong Huang

xchui702

Very appreciate your help.
1. About the W00n traces:
oracle@CNDCDLORA02:/u01/app/oracle/diag/rdbms/cdiamp01/cdiamp01/trace> ls -ltr cdiamp01_w000_*
-rw-r----- 1 oracle oinstall  64 2010-11-16 16:21 cdiamp01_w000_13117.trm
-rw-r----- 1 oracle oinstall 798 2010-11-16 16:21 cdiamp01_w000_13117.trc
-rw-r----- 1 oracle oinstall  64 2010-11-16 20:05 cdiamp01_w000_32727.trm
-rw-r----- 1 oracle oinstall 798 2010-11-16 20:05 cdiamp01_w000_32727.trc

The two traces files for W00 process have the similar message as following.
oracle@CNDCDLORA02:/u01/app/oracle/diag/rdbms/cdiamp01/cdiamp01/trace> view cdiamp01_w000_13117.trc
Trace file /u01/app/oracle/diag/rdbms/cdiamp01/cdiamp01/trace/cdiamp01_w000_13117.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
System name:    Linux
Node name:      CNDCDLORA02
Release:        2.6.16.60-0.21-smp
Version:        #1 SMP Tue May 6 12:41:02 UTC 2008
Machine:        x86_64
Instance name: cdiamp01
Redo thread mounted by this instance: 1
Oracle process number: 24
Unix process pid: 13117, image: oracle@CNDCDLORA02 (W000)


*** 2010-11-16 16:21:17.229
*** CLIENT ID) 2010-11-16 16:21:17.229
*** SERVICE NAME) 2010-11-16 16:21:17.229
*** MODULE NAME) 2010-11-16 16:21:17.229
*** ACTION NAME) 2010-11-16 16:21:17.229

New process timed out

2. about /var/log/messages, when the tablesapces are created, the message is as below:

Nov 16 16:57:59 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 17:15:03 CNDCDLORA02 su: (to beagleindex) root on none
Nov 16 17:15:17 CNDCDLORA02 su: (to beagleindex) root on none
Nov 16 17:57:59 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81003e712240)
Nov 16 18:21:56 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:21:56 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 c2 47 00 01 d0 00
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81003e712240)
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff810139c6e500)
Nov 16 18:21:56 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:21:56 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 d8 17 00 04 00 00
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff810139c6e500)
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81013a7e23c0)
Nov 16 18:21:56 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:21:56 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 e4 17 00 04 00 00
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81013a7e23c0)
Nov 16 18:21:56 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81003e712e40)
Nov 16 18:22:20 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:46 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 ec 17 00 01 d0 00
Nov 16 18:22:46 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81003e712e40)
Nov 16 18:22:46 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff810139c6ec80)
Nov 16 18:22:46 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:48 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 ed e7 00 04 00 00
Nov 16 18:22:48 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff810139c6ec80)
Nov 16 18:22:48 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81013913b9c0)
Nov 16 18:22:48 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:49 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 f1 e7 00 04 00 00
Nov 16 18:22:49 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81013913b9c0)
Nov 16 18:22:49 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81000da7ce00)
Nov 16 18:22:49 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:49 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 f5 e7 00 01 20 00
Nov 16 18:22:49 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81000da7ce00)
Nov 16 18:22:49 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff81003e712540)
Nov 16 18:22:49 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:51 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 fc 0f 00 00 b8 00
Nov 16 18:22:51 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff81003e712540)
Nov 16 18:22:51 CNDCDLORA02 kernel: mptscsih: ioc0: attempting task abort! (sc=ffff810139c6eb00)
Nov 16 18:22:51 CNDCDLORA02 kernel: sd 0:0:0:0:
Nov 16 18:22:52 CNDCDLORA02 kernel:         command: Write(10): 2a 00 00 21 fc f7 00 00 10 00
Nov 16 18:22:52 CNDCDLORA02 kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff810139c6eb00)
Nov 16 18:57:59 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 19:57:59 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 20:58:00 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 21:58:00 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 22:58:00 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 16 23:58:00 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0

3. about TrendMicro: There's no process about vsapiapp.
CNDCDLORA02:~ # ps -ef | grep -i vsapiapp
root      9297  8535  0 11:13 pts/3    00:00:00 grep -i vsapiapp

xchui702

我又做了一下试验，发现创建的时间少了，但是还是出现m000 not start，所以问题不能重现。
Tue Nov 23 17:35:50 2010
create tablespace work1 datafile size 20G
Tue Nov 23 17:40:40 2010

***********************************************************************

Fatal NI connect error 12537, connecting to:
(LOCAL=NO)

  VERSION INFORMATION:
        TNS for Linux: Version 11.2.0.1.0 - Production
        Oracle Bequeath NT Protocol Adapter for Linux: Version 11.2.0.1.0 - Production
        TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.1.0 - Production
  Time: 23-NOV-2010 17:40:40
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12537

TNS-12537: TNS:connection closed
Tue Nov 23 17:40:51 2010
    ns secondary err code: 12560
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
opiodr aborting process unknown ospid (31452) as a result of ORA-609
Tue Nov 23 17:41:58 2010
AUD: Audit Commit Delay exceeded, written a copy to OS Audit Trail
Tue Nov 23 17:43:24 2010
Errors in file /u01/app/oracle/diag/rdbms/cdiamp01/cdiamp01/trace/cdiamp01_mmon_16350.trc  (incident=9721):
ORA-00445: background process "m000" did not start after 120 secondsTue Nov 23 17:43:44 2010
Incident details in: /u01/app/oracle/diag/rdbms/cdiamp01/cdiamp01/incident/incdir_9721/cdiamp01_mmon_16350_i9721.trc
Tue Nov 23 17:49:36 2010
Trace dumping is performing id=[cdmp_20101123174936]
Tue Nov 23 17:50:05 2010
Sweep [inc][9721]: completed
Sweep [inc2][9721]: completed
Tue Nov 23 17:54:10 2010
Completed: create tablespace work1 datafile size 20G   --创建时间为15分钟
Tue Nov 23 18:00:57 2010
kewastUnPackStats(): bad magic 1 (0x2b672922fbd8, 0)
kewastUnPackStats(): bad magic 1 (0x2b672922fbd8, 0)
kewastUnPackStats(): bad magic 1 (0x2b672922fcf0, 0)
kewastUnPackStats(): bad magic 1 (0x2b672922fcf0, 0)
kewastUnPackStats(): bad magic 1 (0x2b672922fbe0, 0)

我打了补丁5601428, 做了几次试验，就没有再出现了这个问题了，当然也不能确定是否是这个原因。

oracle@CNDCDLORA02:/u01/app/oracle/product/11.2.0/dbhome_1/OPatch> ./opatch lsinventory
Invoking OPatch 11.1.0.6.6

Oracle Interim Patch Installer version 11.1.0.6.6
Copyright (c) 2009, Oracle Corporation.  All rights reserved.


Oracle Home       : /u01/app/oracle/product/11.2.0/dbhome_1
Central Inventory : /u01/app/oraInventory
   from           : /etc/oraInst.loc
OPatch version    : 11.1.0.6.6
OUI version       : 11.2.0.1.0
OUI location      : /u01/app/oracle/product/11.2.0/dbhome_1/oui
Log file location : /u01/app/oracle/product/11.2.0/dbhome_1/cfgtoollogs/opatch/opatch2010-11-25_09-07-20AM.log

Patch history file: /u01/app/oracle/product/11.2.0/dbhome_1/cfgtoollogs/opatch/opatch_history.txt

Lsinventory Output file location : /u01/app/oracle/product/11.2.0/dbhome_1/cfgtoollogs/opatch/lsinv/lsinventory2010-11-25_09-07-20AM.txt

--------------------------------------------------------------------------------
Installed Top-level Products (1):

Oracle Database 11g                                                  11.2.0.1.0
There are 1 products installed in this Oracle Home.


Interim patches (1) :

Patch  8730312      : applied on Wed Nov 24 11:56:19 CST 2010
Unique Patch ID:  12177426
   Created on 7 Feb 2010, 06:41:26 hrs PST8PDT
   Bugs fixed:
     8730312



--------------------------------------------------------------------------------

OPatch succeeded.

创建表空间的log 信息如下：

Wed Nov 24 12:57:54 2010
create tablespace work1 datafile size 20G
Wed Nov 24 13:16:11 2010
Completed: create tablespace work1 datafile size 20G
Wed Nov 24 13:18:29 2010
drop tablespace work1
Deleted Oracle managed file /u01/oradata/CDIAMP01/datafile/o1_mf_work1_6gs6tlpw_.dbf
Completed: drop tablespace work1
Wed Nov 24 17:50:12 2010
create tablespace work1 datafile size 20G
Wed Nov 24 18:08:33 2010
Completed: create tablespace work1 datafile size 20G
Wed Nov 24 18:15:35 2010

Yong Huang

I have fairly good confidence to say your hard drives or controllers (hardware) or drivers (software) have problems. Can you check /var/log/messages and older files (messages.?) to see if every time the slow tablespace creation corresponded to scsi errors in time, and fast creation to lack of the errors?

Yong Huang

xchui702

谢谢！ 这个错误只是最近才碰到。我对比了err message 如上边帖子所示，看不出关于磁盘的问题。昨天创建正常时：/var/log/message 的信息如下。
Nov 24 11:58:36 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 24 12:58:37 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0
Nov 24 13:58:37 CNDCDLORA02 syslog-ng[4090]: STATS: dropped 0

如再出现此类情况，我会按你的方法留意一下。谢谢！

伊思

顶下

woaini1987120

聽君一席話，勝讀十年書。
Tring to be better，Thank you of all

zhangheli1985

谢谢分享

LHDZ_BJ

嗯，根据你的信息，估计和数据库没什么关系，还是硬盘的性能问题，vmstat的io信息很差了，这个状态，你用这么久一点都不奇怪；
另外，你的数据库服务器上，是否还有其他IO相关的负载？导致性能时好时坏？下次性能差时，建议用iostat -dx 3收集些信息，然后贴在这里大家一起看看，谢谢。