WebLogic 12C自定义Access.log日志

不管是Nginx,还是WebLogic,在运行的过程中都会产生Access.log,Access.log可以帮助我们做一些统计(记录某个时间点访问的数量),也可以帮助我们做一些安全性的审计(防范攻击)等等。默认的Access.log 在日常的使用中,已经提供了一些基础的信息。那么Access.log如何扩展,如何自定义是我们这篇文章需要探讨的?

首先,我们来看一下修改之前,我的Access.log的日志格式,如下所示:

211.67.64.23 - - [14/Sep/2016:11:06:49 +0800] "POST /wcm/center.do HTTP/1.0" 200 2646 
211.67.64.23 - - [14/Sep/2016:11:06:51 +0800] "POST /wcm/app/website/website_addedit_dowith.jsp HTTP/1.0" 200 1 
211.67.64.23 - - [14/Sep/2016:11:06:51 +0800] "POST /wcm/app/nav_tree/tree_html_creator.jsp HTTP/1.0" 200 511 
211.67.64.23 - - [14/Sep/2016:11:06:51 +0800] "GET /wcm/app/include/cmsobject_locked.jsp?ObjId=5&ObjType=103&ActionFlag=false HTTP/1.0" 200 83 

这里面包含了IP、时间、请求的URL和HTTP协议,HTTP请求状态,发送给客户端文件内容大小等信息。而我们还能够对默认的日志进行扩展。首先进入下列界面(主页 >服务器概要 >AdminServer):

将这里的公用修改成扩展,并将扩展日志记录格式字段设置成:c-ip cs-username date time cs-uri sc-status bytes cs(Referer) cs(User-Agent),如下所示:

修改这个之后,需要重新启动weblogic,然后得到的日志格式,就会变成如下:

#Version: 1.0 
#Fields: c-ip cs-username date time cs-uri sc-status bytes cs(Referer) cs(User-Agent) 
#Software: WebLogic 
#Start-Date: 2016-09-14 17:32:37 

211.67.64.23 - 2016-09-14 09:32:37 /wcm/app/main/refresh.jsp?r=1473845558269 302 299 "http://static-news.e21.cn 
/wcm/app/main.jsp" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36" 
211.67.64.23 - 2016-09-14 09:32:37 /wcm/include/not_login.htm 200 571 "http://static-news.e21.cn/wcm/app/main.js 
p" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36" 
211.67.64.163 - 2016-09-14 09:32:49 /wcm/app/login.jsp 200 3572 "http://211.67.64.24:7001/wcm/" "Mozilla/5.0 (Wind 
ows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36" 
211.67.64.163 - 2016-09-14 09:32:49 /wcm/app/js/easyversion/extrender.js 304 0 "http://211.67.64.24:7001/wcm/app/ 
login.jsp" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36" 

可以看到日志的格式发生了变化,多了url跳转来源,用户终端浏览器等信息。那么具体的这个地方要怎么设置呢?可以参考下列表格:

Field Description Example value from above
x-GWXFF actual client IP using custom jar file 11.22.33.44
c-ip IP of client, in this case, IP of the load balancer 22.33.44.55
s-ip IP or hostname of managed
server:port
managed-serve-rhost:port
cs-username Username passed during http authorization “-” implies it was not passed
date date of request in YYYY-MM-DD format 2013-11-20
time time of request in HH:MM:SS format 16:10:19
cs-method Method for this request, can be GET, POST, etc POST
cs-uri URI called /HelloWorld/index.jsp
sc-status HTTP status code, e.g. 200, 301, 403, 500, etc 200
bytes bytes sent 5245
cs(Referer) Referer URL “-” implies direct visit
cs(User-Agent) User-Agent of the client’s browser making the request Axis/1.3

这里需要说明一下x-GWXFF这个参数,如果要使用这个参数,需要创建一个GWXFF.java文件,详情可以参考文档:How to Configure WebLogic Server to Capture Client IP Addresses Behind a Load Balancer Using Extended Log Format (文档 ID 1602379.1)

Fedora 24源码安装MySQL 5.7.14遇到的问题

自从上一篇安装MySQL文章写了之后:CentOS 5下源码安装Mysql 5.5,好几年没碰MySQL了,现在因为新项目的需要,又要重新开始学习MySQL了。不过在这一次源码安装的过程中遇到一些小问题,写个笔记方便自己学习。这一次我安装的环境是Fedora 24,MySQL源码5.7.14。这一次安装和以前写的文章类似,这里不在重复,只是将遇到的几个问题记录一下。

[root@oracle mysql-5.7.14]# cmake -DCMAKE_INSTALL_PREFIX=/data/mysql/ \
> -DDEFAULT_CHARSET=utf8 \
> -DDEFAULT_COLLATION=utf8_genral_ci \
> -DENABLED_LOCAL_INFILE=ON \
> -DWITH_INNOBASE_STORAGE_ENGINE=1 \
> -DWITHOUT_FEDERATED_STORAGE_ENGINE=1\
> -DWITH_BLACKHOLE_STORAGE_ENGINE=1 \
> -DWITHOUT_EXAMPLE_STORAGE_ENGINE=1 \
> -DWITH_PARTITION_STORAGE_ENGINE=1 \
> -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 \
> -DCOMPILATION_COMMENT='Buddy MySQL' \
> -DSYSCONFDIR=/data/mysql  \
> -DMYSQL_UNIX_ADDR=/data/mysql/mysql.sock

首先这是我编译的一些参数,很有必要先了解一下这些参数的含义。有兴趣的可以参考官方文档:CMAKE,官方有一个表格,详细的列出了这些选项的含义。以下我就我这次编译的这些参数做解释,因为这些比较常用。

-DCMAKE_INSTALL_PREFIX         这个参数方便指向安装的路径,默认MySQL你不指定他就会给你安装到/usr/local/mysql目录下去。所以预先还是规划好,程序文件安装在那个目录.
-DDEFAULT_CHARSET     指定MySQL服务器的默认字符集,默认字符集是拉丁(latin1),这里我选择的是UTF-8,但是其实拉丁也不会乱码.
-DDEFAULT_COLLATION            指定MySQL服务器的默认校对规则,默认是(latin1_swedish_ci),这里我选择的是utf8_genral_ci.
-DENABLED_LOCAL_INFILE  是否允许从客户端本地加载数据到MySQL服务器端。这个主要用于LOAD DATA INFILE.
-DWITH_INNOBASE_STORAGE_ENGINE  编译InnoDB存储引擎.
-DWITHOUT_FEDERATED_STORAGE_ENGINE 编译FEDERATED存储引擎.
-DWITH_BLACKHOLE_STORAGE_ENGINE    编译BLACKHOLE存储引擎.
-DWITHOUT_EXAMPLE_STORAGE_ENGINE   不编译EXAMPLE存储引擎.
-DWITH_PARTITION_STORAGE_ENGINE    是否允许支持分区功能.
-DWITH_PERFSCHEMA_STORAGE_ENGINE   是否包含Performance Schema.
-DCOMPILATION_COMMENT  指定编译信息
-DSYSCONFDIR    指定MySQL参数文件的默认路径.
-DMYSQL_UNIX_ADDR   指定MySQL Socket文件的存放路径.
-DMYSQL_TCP_PORT       指定MySQL数据库提供的TCP/IP端口,默认为3306.
-DMYSQL_DATADIR        指定MySQL数据库文件的存储路径.

在编译过程中遇到的第一个错误如下:

-- Performing Test HAVE_LLVM_LIBCPP
-- Performing Test HAVE_LLVM_LIBCPP - Failed

-- Could NOT find Curses (missing: CURSES_LIBRARY CURSES_INCLUDE_PATH)
CMake Error at cmake/readline.cmake:64 (MESSAGE):
Curses library not found. Please install appropriate package,

remove CMakeCache.txt and rerun cmake.On Debian/Ubuntu, package name is libncurses5-dev, on Redhat and derivates it is ncurses-devel.
Call Stack (most recent call first):
cmake/readline.cmake:107 (FIND_CURSES)
cmake/readline.cmake:197 (MYSQL_USE_BUNDLED_EDITLINE)
CMakeLists.txt:483 (MYSQL_CHECK_EDITLINE)
-- Configuring incomplete, errors occurred!
See also "/home/oracle/下载/mysql-5.7.14/CMakeFiles/CMakeOutput.log".
See also "/home/oracle/下载/mysql-5.7.14/CMakeFiles/CMakeError.log"

这个错误是由于没有安装ncurses-devel包导致的。

[root@oracle mysql-5.7.14]# yum install ncurses-devel

接下来遇到的问题如下:

-- Found ZLIB: zlib (found version "1.2.3")
-- Googlemock was not found. gtest-based unit tests will be disabled. You can run cmake . -DENABLE_DOWNLOADS=1 
to automatically download and build required components from source.
-- If you are inside a firewall, you may need to use an http proxy: export http_proxy=http://example.com:80
-- Performing Test HAVE_UNUSED_TYPEDEFS
-- Performing Test HAVE_UNUSED_TYPEDEFS - Success
CMake Warning at cmake/bison.cmake:20 (MESSAGE):
Bison executable not found in PATH
Call Stack (most recent call first):
sql/CMakeLists.txt:528 (INCLUDE)
CMake Warning at cmake/bison.cmake:20 (MESSAGE):
Bison executable not found in PATH
Call Stack (most recent call first):
libmysqld/CMakeLists.txt:160 (INCLUDE)
-- Library mysqlserver depends on OSLIBS -lpthread;m;rt;crypt;dl
-- INSTALL mysqlclient.pc lib/pkgconfig
-- Skipping deb packaging on unsupported platform .
-- CMAKE_BUILD_TYPE: RelWithDebInfo
-- COMPILE_DEFINITIONS: _GNU_SOURCE;_FILE_OFFSET_BITS=64;HAVE_CONFIG_H;HAVE_LIBEVENT1
-- CMAKE_C_FLAGS: -Wall -Wextra -Wformat-security -Wvla -Wwrite-strings -Wdeclaration-after-statement
-- CMAKE_CXX_FLAGS: -Wall -Wextra -Wformat-security -Wvla -Woverloaded-virtual -Wno-unused-parameter
-- CMAKE_C_FLAGS_RELWITHDEBINFO: -O3 -g -fabi-version=2 -fno-omit-frame-pointer -fno-strict-aliasing -DDBUG_OFF
-- CMAKE_CXX_FLAGS_RELWITHDEBINFO: -O3 -g -fabi-version=2 -fno-omit-frame-pointer -fno-strict-aliasing -std=gnu++03 -DDBUG_OFF
-- Configuring done
-- Generating done
-- Build files have been written to: /home/oracle/下载/mysql-5.7.14

这个时候虽然编译成功了,但是上面有一个小错误,Googlemock was not found. gtest-based unit tests will be disabled. You can run cmake . -DENABLE_DOWNLOADS=1 to automatically download and build required components from source.这个意思是需要在编译的参数上加上DENABLE_DOWNLOADS=1,这样就会自动的下载Googlemock这个工具。下载完对这个工具做个编辑就行了。这是个做C++单元测试的工具。不过国内封杀了Google,在编译这个时候根本下载不下来,不过问题不大,可以使用Yum来安装。

[root@oracle source_downloads]# yum install gmock
[root@oracle source_downloads]# make
[root@oracle source_downloads]# make install

安装好了就可以开始初始化数据库了。在初始化数据库的时候需要下列问题:

[mysql@oracle mysqldata]$ mysqld --initialize --user=mysql --datadir=/data/mysqldata --basedir=/data/mysql
2016-09-08T12:48:17.691302Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use 
--explicit_defaults_for_timestamp server option (see documentation for more details).
2016-09-08T12:48:17.693168Z 0 [ERROR] Unknown collation: 'utf8_genral_ci'
2016-09-08T12:48:17.693245Z 0 [ERROR] Aborting

这个问题需要在参数文件中设置字符集为UTF-8,阿西吧,我们不是编译的选项设置了UTF-8吗?为什么还要在参数文件中在设置一遍呢。

[mysql@oracle mysqldata]$ more /data/my.cnf
[mysqld]
basedir=/data/mysql
datadir=/data/mysqldata
character_set_server=utf8
[mysql@oracle mysqldata]$ mysqld --defaults-file=/data/my.cnf --initialize --user=mysql
2016-09-08T12:52:10.616392Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option 
(see documentation for more details).
2016-09-08T12:52:12.332400Z 0 [Warning] InnoDB: New log files created, LSN=45790
2016-09-08T12:52:12.778097Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-09-08T12:52:13.041590Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. 
Generating a new UUID: 101751eb-75c3-11e6-8891-1c6f65aafdbd.
2016-09-08T12:52:13.107937Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2016-09-08T12:52:13.109834Z 1 [Note] A temporary password is generated for root@localhost: Ie:e&lnZp3yd

这里初始化完成之后默认会给你一个root密码。接下来启动数据库修改默认root密码就好。

mysqld_safe --defaults-file=/data/my.cnf &
[mysql@oracle ~]$ mysql -u root -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.14

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> ALTER USER 'root'@'localhost' IDENTIFIED BY 'root';
Query OK, 0 rows affected (0.00 sec)

Latch Free、Library cache伪游标(pseudo cursor)之间的乱七八糟的事情

1. Latch Free很头疼
“57.8这套系统CPU又100%啦,同事赶紧帮忙看一下。”远处传来了客户的声音。
我不慌不忙的打开终端,轻叹口气道:“唉,又是这套库,自从我来这边,已经查了2遍了,而且其他人也查过好几遍了,问题很难定位啊!“
前面我查了几次都觉得是SQL硬解析的问题,可是把这个事情反馈过去之后。他们给我们发了以前的statspack报告,发现硬解析过去是300次/秒,现在下降到了60次/秒,Latch free却增加了不少,着实摸不着头脑。”通过前期的排查基本上定位出了Latch Free的争用是由于library cache引起的。当系统出现大量的Library cache争用的时候,CPU就会达到100%。但是原因?最重要的原因一直未找到。我认为是硬解析导致的,也有同事认为是shared pool太小导致的。还有同事认为是几条逻辑读较高的语句导致的。众说纷纭,也没有一个准。基本上这些方法客户都尝试过了,仍然未能解决这个问题。

2. 从Library cache入手走下去
前期的排查让我们确信的一点是CPU的消耗是在Library cache争用上面,那么Library cache里面情况又是如何的呢?为了一探究竟,我决定在出问题期间直接查询v$libarycache视图,找寻根源。

SQL> select NAMESPACE,GETS,GETHITS,GETHITRATIO,PINS,PINHITS,PINHITRATIO from v$librarycache;
NAMESPACE GETS GETHITS GETHITRATIO PINS PINHITS PINHITRATIO RELOADS
--------------- ---------- ---------- ----------- ---------- ---------- ----------- ---------
SQL AREA 2681757300 2466988687 .91991497 2526130229 636861692 .252109604 145268976
TABLE/PROCEDURE 1425869375 1426215639 1.00024284 400135986 395962811 .989570608 4011372
BODY 149608221 149606649 .999989493 149608385 149605739 .999982314 747
TRIGGER 201588390 201584681 .999981601 201588426 201582160 .999968917 2513
INDEX 147927 144354 .975846194 147833 144231 .975634669 7
CLUSTER 1913453 1905342 .995761067 1116345 1100128 .985473129 1
OBJECT 0 0 1 0 0 1 0
PIPE 0 0 1 0 0 1 0
JAVA SOURCE 2995 1199 .40033389 2995 1199 .40033389 0
JAVA RESOURCE 2995 1202 .401335559 2995 1202 .401335559 0
JAVA DATA 0 0 1 0 0 1 0

从v$librarycache视图中我们发现了一个问题,在对SQL AREA这种对象在pin的时候发生了丢失,可以看到pin hint这项命中率只有区区的25%。而在其他上面都接近100%。那我们来具体的看一下library cache的结构。

123edc

在我们寻找hash bucket,定位cursor的handle,还有寻找具体的child cursor,或者是其依赖的对象,都需要将其pin住。然后做完操作在unpin。
发现pin的问题后,我根据文档的提示检查了v$latch_misses视图,通过这个视图我们可以看到在函数kglpnc:child和kglupc:child上面sleep_count和wtr_slp_count两个值是很高的。sleep_count字段记录进程在此位置hold对应latch而处于sleep状态的次数,而wtr_slp_count记录此内核位置request对应latch的次数。通过文档我们发现kglpnc:child和kglupc:child正好对应了pin和unpin的函数操作。

SQL> select * from v$latch_misses where PARENT_NAME = 'library cache' order by SLEEP_COUNT desc;

PARENT_NAME WHERE SLEEP_COUNT WTR_SLP_COUNT
-------------- ------------------------------------ ----------- -------------
library cache kglpndl: child: before processing 176450042 56119602
library cache kglpnc: child 175151792 205921071
library cache kglupc: child 157330567 135873756
library cache kgllkdl: child: cleanup 103775154 93107365

在网上和Mos上胡乱搜索一通,还真找到了一个解决办法,可以将参数” cursor_space_for_time”改为true,能有效的将部分cursor给pin在内存中,这样就可以减少pin和unpin产生的次数,不过修改这个参数又是有风险的。长期把这些cursor pin在shared pool内存当中,内存一定要足够大才行,不然容易报ORA-04031的错误,毕竟这可是9i的数据库呀。另外一个风险就是你的应用有cursor泄漏,那么泄漏的cursor会浪费大量内存并在一段时间的运行之后对性能产生负面影响。
所以当我们提出修改这个参数的时候,客户也说了:”年关将至,我们最好保守一些,等过完年之后在大动干戈,现在是要想办法让他把这段时间撑过去。“
3. 保守,促使需要寻找根本原因
既然要求我们保守一点,那就需要寻找问题的根源。这就需要找到引起Library cache争用的具体的对象。通过对系统的监控,我们发现了下列可疑的信息。
123rfv
可以从图中看到。我们的Library cache争用主要集中在table_这一类的东西上面,那”table_”代表着什么呢?
通过一系列的文档和资料发现叫做伪游标(pseudo cursor)。首先我们在执行一条SQL语句的时候会在内存里面申请一块区域存放我们的游标,这个内存区域就是我们的Library cache。我们可以通过v$open_cursor查询我们打开的游标,同时我们也可以通过我们的v$sql、v$sqlarea查询执行过的游标,但是会有一个奇怪的现象,一部分v$open_cursor中打开的游标在v$sql或者v$sqlarea中是查不到的。那么这一类不存在的游标有一些就是我们的伪游标了。伪游标的具体表现形式就类似”table_4_9_d6c6_0_0_0“。

SQL> select NAME,TYPE from v$db_object_cache where name like '%table_%';
NAME                                                      TYPE
------------------------------------------------------------ 
table_4_9_d6c6_0_0_0                                      CURSOR

伪游标是怎么产生的呢?在Oracle访问数据字典表、Lob字段或者Nchar、Nvarchar2的时候,Oracle内部都会提供伪游标这个结构去直接访问数据库对象,这么做的好处是省去了写一个显示的Select语句的开销。
还有一些时候,我们的AWR报告会显示下面的一系列的内容。显示**SQL Text Not Avaliable **,这类的SQL有SQL ID,可是没有SQL Text,这类的SQL也可能是伪游标。
123yhn
前面介绍了伪游标是怎么产生的,那么如何查询伪游标是在那个对象产生的呢?我们可以通过v$open_cursor查询到打开的伪游标,可以看到它的展现形式是“table_4_9_d6c6_0_0_0”,那么这个中间有一个d6c6,我们需要将这个十六进制的字符串转换成十进制,转换成十进制后就是54982,这个值对应我们的object_id。然后我们就能把object_name找出来。
还有一个办法就是在文档1298471.1提供了一个脚本可以直接帮我们查到相关的对象。脚本内容如下:

create or replace view h$pseudo_cursor as
select Pseudo_cursor, sql_id,obj_id hex_obj_id
     ,obj# object_id, u.name owner, o.name object_name
from (select distinct 
             KGLNAOBJ Pseudo_cursor,kglobt03 sql_id
        ,substr(KGLNAOBJ
               ,instr(KGLNAOBJ,'_',1,3)+1
               ,instr(KGLNAOBJ,'_',1,4)-instr(KGLNAOBJ,'_',1,3)-1) obj_id 
       ,(case when 
         replace(translate(substr(upper(KGLNAOBJ)
                                 ,instr(KGLNAOBJ,'_',1,3)+1
                                 ,instr(KGLNAOBJ,'_',1,4)
                                  -instr(KGLNAOBJ,'_',1,3)-1)
                          ,'0123456789ABCDEF','................')
                ,'.') is null then 'Y' else 'N' end) is_safe_to_compare
            from x$kglob) k
   , obj$ o, user$ u
where obj#=decode(is_safe_to_compare,'Y',to_number(obj_id,'xxxxxxxxxx'),0)
   and o.owner#=u.user#;

找到了这些伪游标,我们又找到了其相关的对象,接下来就是找到和这些对象相关的SQL语句,最保守的做法就是把能想办法把一部分LOB类的SQL进行改造。或者是高峰期错开运行。

AUL恢复Truncate数据

需要说吗一下,这里为什么要选择AUL工具,那是因为其他工具都没有办法执行大数据量的抽取,在性能上AUL也比其他工具要速度快,所以这里选用了AUL作为恢复工具。

1.进入AUL,需要设置LICENCE 

SET LICENCE XXXXX
SET BYTE_ORDER BIG

才能认到文件。第一列显示Y

AUL> open db11.cfg
*  ts#  rfn ver bsize     blocks   sizemb filename
- ---- ---- --- ----- ---------- -------- -----------------------------------
Y    0    1 a2   8192    1048576        0 /oradata10/pboss_sys/system01.dbf
Y   62  876 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_01.dbf
Y   62  894 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_04.dbf
Y   62  903 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_05.dbf
Y   62  904 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_06.dbf
Y   62  905 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_07.dbf
Y   62  872 a2   8192    1048576        0 /oradata10/pboss_tmp1/linkage_std_data72.dbf

2.LOAD数据字典

AUL> UNLOAD TABLE USER$;
AUL> UNLOAD TABLE OBJ$;
AUL> UNLOAD TABLE TAB$;
AUL> UNLOAD TABLE COL$;

3.设置LOB字段参数

SET LOB_STORAGE 1
SET MAXLOBDIR 2000

4.查看用户表信息

AUL> desc pboss.TIP_NGCRMRECEIVE_LOG
Storage(OBJ#=0 OBJD=0 TS=0 FILE=0 BLOCK=0 CLUSTER=0)
No. SEQ INT Column Name                   Type
--- --- --- ----------------------------- ----------------
1   1   1 LOG_ID                        VARCHAR2(32) NOT NULL
2   2   2 SEQ                           NUMBER NOT NULL
3   3   3 SERVCODE                      VARCHAR2(5)
4   4   4 FINDCODE                      VARCHAR2(64)
5   5   5 SYSID                         VARCHAR2(5)
6   6   6 REQCODE                       VARCHAR2(4)
7   7   7 SERERRORCODE                  VARCHAR2(500)
8   8   8 REQDESC                       VARCHAR2(2000)
9   9   9 RECEIVECONTENT                CLOB  (SYS_IL0000393293C00009$$)
10  10  10 RETURNCONTENT                CLOB  (SYS_IL0000393293C00010$$)
11  11  11 LOG_FLAG                     CHAR(1)
12  12  12 LOG_DATE                     DATE NOT NULL

5.获取DATA_OBJECT_ID
去原来的生产库上执行

SQL> select SEGMENT_NAME,PARTITION_NAME,HEADER_FILE,HEADER_BLOCK from dba_segments where SEGMENT_NAME='TIP_NGCRMRECEIVE_LOG' order by PARTITION_NAME;
SEGMENT_NAME                   PARTITION_NAME     HEADER_FILE HEADER_BLOCK
------------------------------ ------------------------------ ------------
TIP_NGCRMRECEIVE_LOG           P1209                      713       113962
TIP_NGCRMRECEIVE_LOG           P1210                      713       113970
TIP_NGCRMRECEIVE_LOG           P1211                      713       113978
TIP_NGCRMRECEIVE_LOG           P1212                      713       113986
TIP_NGCRMRECEIVE_LOG           P1301                      713       113994
TIP_NGCRMRECEIVE_LOG           P1302                      713       114002
TIP_NGCRMRECEIVE_LOG           P1303                      713       114010
TIP_NGCRMRECEIVE_LOG           P1304                      713       114018
TIP_NGCRMRECEIVE_LOG           P1305                      713       114026
TIP_NGCRMRECEIVE_LOG           P1306                      713       114034
TIP_NGCRMRECEIVE_LOG           P1307                      713       114042
TIP_NGCRMRECEIVE_LOG           P1308                      672       137466
TIP_NGCRMRECEIVE_LOG           P1309                      679       105914
TIP_NGCRMRECEIVE_LOG           P1310                      679       105922
TIP_NGCRMRECEIVE_LOG           P1311                      679       105930
TIP_NGCRMRECEIVE_LOG           P1312                      679       105938
TIP_NGCRMRECEIVE_LOG           P1401                      695       648170
TIP_NGCRMRECEIVE_LOG           P1402                      695       648210
TIP_NGCRMRECEIVE_LOG           P1403                      695       648250
TIP_NGCRMRECEIVE_LOG           P1404                      695       648314
TIP_NGCRMRECEIVE_LOG           P1405                      695       648330
TIP_NGCRMRECEIVE_LOG           P1406                      695       648378
TIP_NGCRMRECEIVE_LOG           P1407                      695       648426
TIP_NGCRMRECEIVE_LOG           P1408                      695       648450
TIP_NGCRMRECEIVE_LOG           P1409                      695       648490
TIP_NGCRMRECEIVE_LOG           P1410                      695       648538
TIP_NGCRMRECEIVE_LOG           P1411                      710       118098    =>118103
TIP_NGCRMRECEIVE_LOG           P1412                      695       648610    =>648615
TIP_NGCRMRECEIVE_LOG           P1501                      695       648650    =>648655
TIP_NGCRMRECEIVE_LOG           P1502                      695       648690    =>648695
TIP_NGCRMRECEIVE_LOG           P1503                      695       648730    =>648735
TIP_NGCRMRECEIVE_LOG           P1504                      695       648770    =>648775
TIP_NGCRMRECEIVE_LOG           P1505                      695       648810    =>648815
TIP_NGCRMRECEIVE_LOG           P1506                      695       648850
TIP_NGCRMRECEIVE_LOG           P1507                      695       648890
TIP_NGCRMRECEIVE_LOG           P1508                      695       648930
TIP_NGCRMRECEIVE_LOG           P1509                      695       648970
TIP_NGCRMRECEIVE_LOG           P1510                      695       649010
TIP_NGCRMRECEIVE_LOG           P1511                      695       649050
TIP_NGCRMRECEIVE_LOG           P1512                      695       649090
TIP_NGCRMRECEIVE_LOG           P1601                      695       649098

select SEGMENT_NAME,PARTITION_NAME,HEADER_FILE,HEADER_BLOCK from dba_segments where SEGMENT_NAME='TOM_BO_INSTANCE_HIS' order by PARTITION_NAME;

SEGMENT_NAME                             PARTITION_NAME                 HEADER_FILE HEADER_BLOCK
---------------------------------------- ------------------------------ ----------- ------------
TOM_BO_INSTANCE_HIS                      P1212                                  763       110738
TOM_BO_INSTANCE_HIS                      P1301                                  763       110746
TOM_BO_INSTANCE_HIS                      P1302                                  763       110754
TOM_BO_INSTANCE_HIS                      P1303                                  763       110762
TOM_BO_INSTANCE_HIS                      P1304                                  763       110770
TOM_BO_INSTANCE_HIS                      P1305                                  763       110778
TOM_BO_INSTANCE_HIS                      P1306                                  763       110786
TOM_BO_INSTANCE_HIS                      P1307                                  763       110794
TOM_BO_INSTANCE_HIS                      P1308                                  763       110802
TOM_BO_INSTANCE_HIS                      P1309                                  763       110810
TOM_BO_INSTANCE_HIS                      P1310                                  763       110818
TOM_BO_INSTANCE_HIS                      P1311                                  763       110826
TOM_BO_INSTANCE_HIS                      P1312                                  763       110834
TOM_BO_INSTANCE_HIS                      P1401                                  695       652162
TOM_BO_INSTANCE_HIS                      P1402                                  695       654354
TOM_BO_INSTANCE_HIS                      P1403                                  696       588266
TOM_BO_INSTANCE_HIS                      P1404                                  696       588370
TOM_BO_INSTANCE_HIS                      P1405                                  695       657586   => 657591
TOM_BO_INSTANCE_HIS                      P1406                                  695       658706   => 658711
TOM_BO_INSTANCE_HIS                      P1407                                  695       658802   => 658807
TOM_BO_INSTANCE_HIS                      P1408                                  696       588498   => 588503
TOM_BO_INSTANCE_HIS                      P1409                                  695       661938   => 661943
TOM_BO_INSTANCE_HIS                      P1410                                  695       663058   => 663063
TOM_BO_INSTANCE_HIS                      P1411                                  695       663154   => 663159
TOM_BO_INSTANCE_HIS                      P1412                                  696       588626   => 588631
TOM_BO_INSTANCE_HIS                      P1501                                  695       666290   => 666295
TOM_BO_INSTANCE_HIS                      P1502                                  695       667410
TOM_BO_INSTANCE_HIS                      P1503                                  695       667506
TOM_BO_INSTANCE_HIS                      P1504                                  696       588754   =>588759
TOM_BO_INSTANCE_HIS                      P1505                                  695       670642   =>670647
TOM_BO_INSTANCE_HIS                      P1506                                  695       671762
TOM_BO_INSTANCE_HIS                      P1507                                  695       671858
TOM_BO_INSTANCE_HIS                      P1508                                  696       641234
TOM_BO_INSTANCE_HIS                      P1509                                  695       674994
TOM_BO_INSTANCE_HIS                      P1510                                  695       676114
TOM_BO_INSTANCE_HIS                      P1511                                  695       676210
TOM_BO_INSTANCE_HIS                      P1512                                  696       641362
TOM_BO_INSTANCE_HIS                      P1601                                  696       641370

然后执行dump命令dump出数据块,注意不是段头块,一般将块号增加几个,我这里增加的是5

SQL> oradebug setmypid
Statement processed.
SQL> oradebug tracefile_name
/oracle/database/diag/rdbms/integ/integ3/trace/integ3_ora_26183.trc
SQL> alter system dump datafile 695 block 661943

通过trace文件搜索obj查到相关的obj号码,然后转换成10进制

seg/obj: 0x70f31 =>462641

6.然后再AUL中用LIST命令获取执行代码

AUL> list table pboss
UNLOAD TABLE pboss.ZH0914 TO ZH0914.txt;
UNLOAD TABLE pboss.TOM_WORK_ORDER_HANG_UP TO TOM_WORK_ORDER_HANG_UP.txt;
UNLOAD TABLE pboss.TIP_ZXTV_INFO TO TIP_ZXTV_INFO.txt;
UNLOAD TABLE pboss.TIP_BESTTV_LOG_HIS TO TIP_BESTTV_LOG_HIS.txt;
UNLOAD TABLE pboss.TRMAP_EXEC_ORDER_HIS TO TRMAP_EXEC_ORDER_HIS.txt;
UNLOAD TABLE pboss.TMID_POWER_ALLDEVICE TO TMID_POWER_ALLDEVICE.txt;

7.执行获取代码,中间要加上object编号

UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1411 object 462641 TO TIP_NGCRMRECEIVE_LOG_P1411.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1412 object 462655 TO TIP_NGCRMRECEIVE_LOG_P1412.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1501 object 462669 TO TIP_NGCRMRECEIVE_LOG_P1501.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1502 object 462683 TO TIP_NGCRMRECEIVE_LOG_P1502.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1503 object 462697 TO TIP_NGCRMRECEIVE_LOG_P1503.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1504 object 462711 TO TIP_NGCRMRECEIVE_LOG_P1504.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1505 object 3019673 TO TIP_NGCRMRECEIVE_LOG_P1505.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1505 object 462725 TO TIP_NGCRMRECEIVE_LOG_P15052.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1405 object 463223 TO TOM_BO_INSTANCE_HIS_P1405.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1406 object 463239 TO TOM_BO_INSTANCE_HIS_P1406.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1407 object 463255 TO TOM_BO_INSTANCE_HIS_P1407.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1408 object  TO TOM_BO_INSTANCE_HIS_P1408.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1409 object 463287 TO TOM_BO_INSTANCE_HIS_P1409.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1410 object 463303 TO TOM_BO_INSTANCE_HIS_P1410.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1411 object 463319 TO TOM_BO_INSTANCE_HIS_P1411.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1412 object 463335 TO TOM_BO_INSTANCE_HIS_P1412.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1501 object 463351 TO TOM_BO_INSTANCE_HIS_P1501.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1502 TO TOM_BO_INSTANCE_HIS_P1502.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1503 TO TOM_BO_INSTANCE_HIS_P1503.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1504 object 463399 TO TOM_BO_INSTANCE_HIS_P1504.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1505 object 3019551 TO TOM_BO_INSTANCE_HIS_P1505.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1505 object 463415 TO TOM_BO_INSTANCE_HIS_P15052.txt;

8.到AUL目录下执行导入数据,注意修改表空间和表名

sqlplus dbmon/dbmon123 @TIP_NGCRMRECEIVE_LOG_syntax.sql
sqlldr dbmon/dbmon123 control=TIP_NGCRMRECEIVE_LOG_P1411_sqlldr.ctl
TIP_NGCRMRECEIVE_LOGp1412
TIP_NGCRMRECEIVE_LOGP1412

ORA-00494: enqueue [CF] held for too long (more than 900 seconds)问题分析

数据库在下午13点05分左右爆发了ORA-00494: enqueue [CF] held for too long (more than 900 seconds)问题,最终导致数据库异常宕机,通过对日志的分析发现下列信息:

Errors in file /u01/oracle/admin/cppicids/bdump/cppicids_lgwr_168278.trc: ORA-00494: enqueue [CF] held for too long (more than 900 seconds) (more than 900 seconds) by inst 1, osid 270814')
Thu Jun 11 13:05:21 2015System State dumped to trace file /u01/oracle/admin/cppicids/bdump/cppicids_lgwr_168278.trcKilling enqueue blocker (pid=270814) on resource CF-00000000-00000000 by killing session 882.1Killing enqueue blocker (pid=270814) on resource CF-00000000-00000000 by terminating the processLGWR: terminating instance due to error 2103

从中我们可以看到进程270814持有cf锁达到900秒,最终引发lgwr终止了实例,并抛出了错误代码2103。我们进一步分析lgwr的trace,发现下列信息。

SO: 700000e74329590, type: 2, owner: 0, flag: INIT/-/-/0x00
  (process) Oracle pid=5, calls cur/top: 700000e754de920/700000e754de920, flag: (6) SYSTEM
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 24
              last post received-location: ksasnd
              last process to post me: 700000e74329d70 1 6
              last post sent: 0 0 24
              last post sent-location: ksasnd
              last process posted by me: 700000e74329d70 1 6
  (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 700000e76341580
    O/S info: user: oracle, term: UNKNOWN, ospid: 270814 
    OSD pid info: Unix process pid: 270814, image: oracle@CXIDSDBBAK (DBW0)
Dump of memory from 0x0700000E7430F978 to 0x0700000E7430FB80
SO: 700000e75474ba0, type: 4, owner: 700000e74329590, flag: INIT/-/-/0x00
  (session) sid: 882 trans: 0, creator: 700000e74329590, flag: (51) USR/- BSY/-/-/-/-/-
            DID: 0001-0005-00000005, short-term DID: 0000-0000-00000000
            txn branch: 0
            oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
  waiting for 'kcbzps' blocking sess=0x0 seq=64993 wait_time=0 seconds since wait started=60
          =0, =0, =0
  Dumping Session Wait History
   for 'kcbzps' count=1 wait_time=1102055
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97670
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97671
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666

我们可以看到270814进程是dbw0进程,也就是数据写入进程。它的历史和现在的等待事件都是’kcbzps’,等待的时间非常之长,也就是说dbw0进程一直在等待。
我们在看一下dbw0持有的队列信息。

    SO: 700000e7350ce88, type: 5, owner: 700000e754de920, flag: INIT/-/-/0x00
      (enqueue) CF-00000000-00000000    DID: 0001-0005-00000005
      lv: 02 0f dd 46 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x2
      res: 0x700000e764b2458, mode: S, lock_flag: 0x0
      own: 0x700000e75474ba0, sess: 0x700000e75474ba0, proc: 0x700000e74329590, prv: 0x700000e764b2468

  SO: 700000e735123b0, type: 5, owner: 700000e000040d8, flag: INIT/-/-/0x00
      (enqueue) CF-00000000-00000000    DID: 0001-00B9-0000C7C5
      lv: 02 0f dd 46 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x2
      res: 0x700000e764b2458, req: SSX, lock_flag: 0x0
      own: 0x700000e74468560, sess: 0x700000e74468560, proc: 0x700000e7433f7f0, prv: 0x700000e764b2478

我们可以看到我们的dbw0进程以s模式持有了CF-00000000-00000000锁,而另外一个进程想以X模式来持有它。我们来看看是什么进程。

 (session) sid: 659 trans: 0, creator: 700000e7433f7f0, flag: (c0000041) USR/- BSY/-/-/-/-/-
              DID: 0001-00B9-0000C7C5, short-term DID: 0000-0000-00000000
              txn branch: 0
              oct: 47, prv: 0, sql: 700000e47f92088, psql: 700000e47f92088, user: 0/SYS
    service name: SYS$USERS
    O/S info: user: oracle, term: , ospid: 1798860, machine: CXIDSDBBAK
              program: rman@CXIDSDBBAK (TNS V1-V3)
    application name: rman@CXIDSDBBAK (TNS V1-V3), hash value=3432807229
    action name: 0000001 FINISHED70, hash value=706507012
    waiting for 'enq: CF - contention' blocking sess=0x700000e75474ba0 seq=131 wait_time=0 seconds since wait started=0
                name|mode=43460005, 0=0, operation=0
    Dumping Session Wait History
     for 'enq: CF - contention' count=1 wait_time=2929718
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929703
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929699
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929699
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929709
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929702
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929701
                name|mode=43460005, 0=0, operation=0

通过trace我们发现是用户发起的rman进程需要以x模式获取cf锁,而此时我们的cf锁是被dbw0以s模式持有着,正常情况是能释放的,而dbw0进程因为等待’kcbzps’导致无法正常释放的。此时我们前台的rman进程的等待事件是enq: CF – contention。
一、 解决办法
根据错误号和相关的等待事件’kcbzps’我们可以发现文档ORA-00494: enqueue [CF] held for too long (more than 900 seconds); LGWR:Terminating Instance Due to Error 2103 (Doc ID 1089733.1)是比较符合我们的情况的
该问题提到了4中情况:
1) Starts with space error and file offline
2) Sessions are waiting for CF enqueue
3) Arguments ksliwat   kslwaitns_timed  kskthbwt  kslwait… match that in the call stack of bug
4) There is a wait on kcbzps and occurs with DBWR
我们和第四种情况匹配,为了进一步证实这个问题,我们在通过文档提到的堆栈来进行对比。
如下图所示,文档中提到的堆栈如下:
123qaz
我们trace中相关堆栈如下图:
123wsx
通过对比,堆栈是一致的。也就是印证了这个问题。
那么解决办法是安装Apply Patch 7411568。而这个数据库的PSU较高,最好先检查PSU中是否包含该补丁,如果包含此补丁,需要确认补丁相关的文件是否损坏,损坏了可以重新单独对这个补丁安装,如果没有可以立即安装这个补丁。

Enq: RO – fast object reuse问题处理

应用会话在ybtdb2数据库执行Truncate操作无法成功,数据库出现异常等待事件“enq: RO – fast object reuse”。出现异常等待期间数据库主机资源使用正常。为了进一步分析问题,对该进程做了errorstack,errorstack trace文件如下:

SO: 70000050fc93af8, type: 4, owner: 70000050f8d63d8, flag: INIT/-/-/0x00
    (session) sid: 1103 trans: 7000004f99b71a8, creator: 70000050f8d63d8, flag: (100041) USR/- BSY/-/-/-/-/-
              DID: 0002-0227-00001ECA, short-term DID: 0002-0227-00001ECB
              txn branch: 0
              oct: 170, prv: 0, sql: 7000004cd3ff508, psql: 7000004cd3ff508, user: 35/YBT
    service name: ybtdb
    O/S info: user: ybtcenter, term: , ospid: 15266, machine: ybtapp2
              program: loadidsdata@ybtapp2 (TNS V1-V3)
    client info: 10.190.115.2
    application name: loadidsdata@ybtapp2 (TNS V1-V3), hash value=227635376
    waiting for 'enq: RO - fast object reuse' blocking sess=0x0 seq=15114 wait_time=0 seconds since wait started=278032
                name|mode=524f0006, 2=20227, 0=1
    Dumping Session Wait History
     for 'enq: RO - fast object reuse' count=1 wait_time=488301
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488295
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488299
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488293
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488292
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488290
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488291
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488292
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488296
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488299
                name|mode=524f0006, 2=20227, 0=1
    temporary object counter: 0

可以看到该会话一直在等待enq: RO – fast object reuse,且等待时间较长。

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
7000004cde152e0       909  package body SYS.DBMS_SYS_SQL
7000004cde15990        39  package body SYS.DBMS_SQL
70000050e323ca8         7  procedure YBT.TRUNCATE_TABLE
----- Call Stack Trace -----
ksliwat+06c0         bl       skgpwwait            FFFFFFFFFFEB1F0 ? 000000000 ?
                                                   103AC4EF8 ? 000000000 ?
                                                   FFFFFFFFFFEB1F0 ?
kslwaitns_timed+002  bl       ksliwat              000000000 ? 000000000 ?
4                                                  000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
kskthbwt+022c        bl       kslwaitns_timed      000000004 ? 000000000 ?
                                                   FFFFFFFFFFEBE20 ? 000000000 ?
                                                   3784759F126D58 ? 000000061 ?
                                                   FFFFFFFFFFEB530 ? 000000000 ?
kslwait+00f4         bl       kskthbwt             3200000032 ? 4900000049 ?
                                                   000000000 ? 0524F0006 ?
                                                   000020227 ? 000000001 ?
                                                   E00000000000E ?
                                                   6955278669552786 ?
kjuscv+0ad0          bl       kslwait              FFFFFFFFFFEB704 ? 200000003 ?
                                                   5000001101960E8 ? 700000000 ?
                                                   000000020 ? 000000000 ?
ksipcon+041c         bl       kjuscv               700000509346A00 ?
                                                   50000010564B0D0 ?
                                                   61FFFFFFBF ? 0FFFFFEFF ?
                                                   FFFFFFFFFFEBE20 ? 000000000 ?
                                                   000000000 ? FFFFFFFFFFEBD4C ?
ksqcmi+0e14          bl       ksipcon              10564B8E4 ? 10564B8F0 ?
                                                   10564B928 ? 10564B914 ?
                                                   10564B908 ? 080000004 ?
                                                   10564B940 ? 10564B934 ?
ksqcnv+030c          bl       ksqcmi               70000050B0D3DF8 ? 600000000 ?
                                                   FFFF0011BD18 ?
                                                   147AE140B4A3EC8 ?
                                                   FFFFFFFFFFED260 ?
                                                   FFFFFFFFFFED4B0 ? 000000004 ?
                                                   110001248 ?
ksqcov+0034          bl       ksqcnv               FFFFFFFFFFED84C ? 000000000 ?
                                                   FFFFFFFFFFED844 ? 000000001 ?
                                                   000000001 ? 000020227 ?
                                                   00147AE14 ?
kcbo_reuse_obj+0880  bl       01F94504             
kcbrbo+00bc          bl       01F93AE0             
ktsstrn_segment+0f6  bl       kcbrbo               FFFFFFFFFFEE0C0 ? 000000000 ?
c                                                  7000004BD28E470 ?
kkbtts_trunc_tbl_se  bl       ktsstrn_segment      FFFFFFFFFFEE0C0 ? 02CC03F1D ?
g+04b8                                             000000000 ? 0FFFEE268 ?
                                                   064232020 ? 064232020 ?
kkbtrn+13f8          bl       kkbtts_trunc_tbl_se  047548A48 ? 7000004BD28E318 ?
                              g                    000000000 ? 1FFFEE7A0 ?
                                                   7000004D42A5D88 ?
                                                   700000443A513F0 ?
                                                   3000000000003 ?
opiexe+317c          bl       kkbtrn

通过观察堆栈发现是在执行Truncate语句,执行过程中采取了下列调用。

kslwaitns_timed -> kskthbwt -> kslwait -> kjuscv -> ksipcon -> ksqcmi -> ksipcon -> ksqcnv -> ksqcov -> kcbo_reuse_obj -> kcbrbo -> ktsstrn_segment -> kkbtts_trunc_tbl_se

通过metalink note进行搜索,找到了文档Process waits too long for ‘enq: RO – fast object reuse’. Cause: CKPT Process Bug 7385253 (文档 ID 785232.1)里面的文档中的Call Stack和我们的类似。文档中指出的Call Stack如下所示:

kslwaitns_timed kskthbwt kslwait ksqcmi ksqcnv ksqcov kcbo_reuse_obj kcbrbo ..etc

同时可以观察队列资源的情况。

----------resource 0x7000004c3fb9410----------------------
resname       : [0x20227][0x1],[RO]
GRANTED_Q :
lp 70000050bce5f40 gl KJUSERCR rp 7000004c3fb9410 [0x20227][0x1],[RO]
  master 1 gl owner 70000050cd9d4d0 possible pid 2064446 xid 2001-0013-00000005 bast 0 rseq 15 mseq 0 history 0x95514955
  open opt KJUSERDEADLOCK  KJUSERIDLK 
CONVERT_Q: 
lp 700000509346a00 gl KJUSERPW rl KJUSEREX rp 7000004c3fb9410 [0x20227][0x1],[RO]
  master 1 gl owner 70000050fc93af8 possible pid 1159360 xid 2022-0227-00001ECA bast 0 rseq 15 mseq 0 history 0x5514955a
  convert opt KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK

可以看到该队列和pid 2064446和pid 1159360有关。

SO: 70000050b0d3dd8, type: 5, owner: 700000481adb5a0, flag: INIT/-/-/0x00
        (enqueue) RO-00020227-00000001  DID: 0002-0227-00001ECA
        lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x3
        res: 0x70000050a15e320, mode: SSX, req: X, lock_flag: 0x0
        own: 0x70000050fc93af8, sess: 0x70000050fc93af8, proc: 0x70000050f8d63d8, prv: 0x70000050a15e350
        slk: 0x700000509346a00

possible owner[19.2064446] on resource RO-00020227-00000001

继续分析可以发现pid 1159360以X模式在请求持有队列RO-00020227-00000001。pid 1159360正是发起truncate的会话进程。而队列RO-00020227-00000001是被pid 2064446所持有的。而通过查询2064446发现是ckpt进程。

[jtdba@sxybtdb2 ~]$ps -ef | grep ckpt
   jtdba 1581064 2146438   0 14:30:52  pts/0  0:00 grep ckpt 
  oracle 2064446       1   0   Dec 21      - 28:02 ora_ckpt_ybtdb2

问题解决
建议安装单独的patch 7385253来规避这个问题.
建议将数据库升级到11.2来规避此问题.11.2以上的版本才修复了该问题.

ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53]问题分析

数据库突然异常宕机。查看后台alert日志,PMON进程出现致命错误,报ORA-00600[4442]错误。

Thu Jan 22 11:04:46 2015 
Thread 1 advanced to log sequence 442095 
Current log# 8 seq# 442095 mem# 0: /p09bp_mm/mm_u01/mm/redo08_a.log 
Current log# 8 seq# 442095 mem# 1: /p09bp_mm/mm_u02/mm/redo08_b.log 
Thu Jan 22 11:07:27 2015 
Errors in file /u01/oracle/admin/mm/bdump/mm_pmon_1757288.trc: 
ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53], [], [], [], [], [] 
Thu Jan 22 11:07:30 2015 
Errors in file /u01/oracle/admin/mm/bdump/mm_pmon_1757288.trc: 
ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53], [], [], [], [], [] 
Thu Jan 22 11:07:30 2015 
PMON: terminating instance due to error 472 
Termination issued to instance processes. Waiting for the processes to exit 
Thu Jan 22 11:07:40 2015 
Instance termination failed to kill one or more processes 
Instance terminated by PMON, pid = 1757288 
Thu Jan 22 11:23:06 2015 
Starting ORACLE instance (normal) 
LICENSE_MAX_SESSION = 0 
LICENSE_SESSIONS_WARNING = 0 
Picked latch-free SCN scheme 3 
Autotune of undo retention is turned on.

为了进一步研究PMON进程为何突发异常,我们需要研究PMON的Trace文件。

PROCESS STATE 
------------- 
Process global information: 
process: 7000008ca28f5b8, call: 7000008cb3d54e8, xact: 0, curses: 7000008c93d0c10, usrses: 7000008c93d0c10 
---------------------------------------- 
SO: 7000008ca28f5b8, type: 2, owner: 0, flag: INIT/-/-/0x00 
(process) Oracle pid=2, calls cur/top: 7000008cb3d54e8/7000008cb3d54e8, flag: (e) SYSTEM 
int error: 0, call error: 0, sess error: 0, txn error 0 
(post info) last post received: 0 0 15 
last post received-location: ksupsc 
last process to post me: 7000008ca28fd98 1 6 
last post sent: 0 0 147 
last post sent-location: ktmpsm 
last process posted by me: 7000008cf28ba40 1 22 
(latch info) wait_event=0 bits=40 
holding (efd=4) 70000001001c670 transaction branch allocation level=6 
Location from where latch is held: ktcxdp: 
Context saved from call: 0 
state=busy, wlstate=free 
waiters [orapid (seconds since: put on list, posted, alive check)]: 
213 (0, 1421896047, 0) 
190 (0, 1421896047, 0) 
134 (0, 1421896047, 0) 
41 (0, 1421896047, 0) 
113 (0, 1421896047, 0) 
146 (0, 1421896047, 0) 
131 (0, 1421896047, 0) 
137 (0, 1421896047, 0) 
32 (0, 1421896047, 0) 
waiter count=9 
Process Group: DEFAULT, pseudo proc: 7000008ce30e4d0 
O/S info: user: oracle, term: UNKNOWN, ospid: 1757288 
OSD pid info: Unix process pid: 1757288, image: oracle@CXSFDB1 (PMON) 

可以看到PMON进程的trace显示Location from where latch is held: ktcxdp。也就是在执行函数ktcxdp的时候出现了latch的阻塞。导致pmon进程被堵塞。而pmon的进一步堵塞导致了9个会话被堵。

而Trace里面的函数堆栈显示:

----- Call Stack Trace ----- 
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              0FFFFFFFF ? 000000020 ?
ksedmp+0290          bl       ksedst               104811CB8 ?
ksfdmp+0018          bl       03F40AE0             
kgeriv+0108          bl       _ptrgl               
kgesiv+0080          bl       kgeriv               1048E451C ? 1048E451C ?
                                                   1048E451C ? 1048E451C ?
                                                   1048E451C ?
ksesic2+0060         bl       kgesiv               000000002 ? 054C0696F ?
                                                   000000001 ? 70000001001C670 ?
                                                   1104D3E80 ?
ktcxdp+0344          bl       ksesic2              115A0000115A ? 000000002 ?
                                                   7000008A7C22EF8 ? 000000000 ?
                                                   000000035 ? 00011D1D3 ?
                                                   000000000 ? 000000000 ?
ksucln+0938          bl       ktcxdp               
ksbrdp+03e0          bl       _ptrgl               
opirip+03fc          bl       01FAFCBC             
opidrv+0448          bl       opirip               11029E590 ? 41029FED0 ?
                                                   FFFFFFFFFFFF6D0 ?
sou2o+0090           bl       opidrv               32031840FC ? 4A0170928 ?
                                                   FFFFFFFFFFFF6D0 ?
opimai_real+0150     bl       01FAB1B4             
main+0098            bl       opimai_real          000000000 ? 000000000 ?
__start+0098         bl       main                 000000000 ? 000000000 ?

ksedst <- ksedmp <- ksfdmp <- kgeriv <- kgesiv 
<- ksesic2 <- ktcxdp <- ksucln <- ksbrdp <- opirip 
<- opidrv <- sou2o <- opimai_real <- main <- start 

通过metalink note进行搜索,找到了文档Database Crashed After ORA-600 [4442] (文档 ID 368877.1)里面的文档中的Call Stack和我们的类似。而文档中指出的Call Stack如下所示:

ORA-600 [4442] is signalled by PMON, with the stack trace:
ktcxdp <- ksucln <- ksbrdp <- opirip <- opidrv <- sou2o

因此我们可以确定命中了Bug 4891103 'INSTANCE DOWN OWING TO ORA-600 [4442]'. This is due to PMON cleaning up a distributed transaction incorrectly.那么这个问题就出在我们的PMON去清理分布式事务的时候触发的。为了进一步确认分布式事务引起的问题,我们还在PMON的trace中看到下列信息。

B0BB3C91:3BDB1F4E    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[1] comment=[KSB action for X-instance calls]
B0BB3C9D:3BDB1F4F    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[63] comment=[Scumnt mount lock]
B0BB3C9E:3BDB1F50    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[64] comment=[Poll system events broadcast channel]
B0BB3CA1:3BDB1F51    12  1315 10254  73 KSBCTI: (RECO) : (timeout action)   : acnum=[0] comment=[Monitor Cleanup]
B0BB3CD9:3BDB1F52    12  1315 10254  73 KSBCTI: (RECO) : (timeout action)   : acnum=[119] comment=[distributed recovery wakeup]
B0BB3E0F:3BDB1F53    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[1] comment=[KSB action for X-instance calls]

这里可以看到我们的reco的进程也是被唤醒过的,恢复进程recoverer process (RECO)用于分布式数据库结构,自动解决分布式事务的错误。但是因为数据库异常宕机,通过trace文件无法定位到具体的分布式SQL语句。
问题解决

  1. 建议安装单独的patch 4891103来规避这个问题.
  2. 目前版本是10.2.0.2,在10.2.0.3上已经修复该问题,建议升级到10.2.0.5以上的版本.
  3. 通过dba_2pc_pengding视图监控相关的分布式事务,找出引发异常2pc事务的源头。
  4. 文档126069.1给出了一个手动解决有问题的分布式事务的方法。NOTE:126069.1 - Manually Resolving In-Doubt Transactions: Different Scenarios