ORA-07445: [__lwp_kill()+8] [SIGIOT]错误一例

这是一套SunOS 5.10上的10.2.0.3的RAC系统,8月初告警日志中陆续出现以下记录:

Tue Aug  3 15:17:04 2010
Errors in file /u01/app/oracle/admin/prsi061/udump/prsi061a_ora_27774.trc:
ORA-07445: exception encountered: core dump [__lwp_kill()+8] [SIGIOT] [unknown code] [0x6C7E00000000] [] []

SIGIOT信号伴随7445错误出现并不多见,因为该信号一般是用来实现相关的硬件异常的。
我们可以欣赏一下这个trace文件
trace文件中的堆栈信息如下:

ksedmp()+744         CALL     ksedst()             000000840 ? 1066C60CC ?
000000000 ? 1066C2BC0 ?
1066C1928 ? 1066C2328 ?
ssexhd()+1240        CALL     ksedmp()             000106400 ? 106530764 ?
106530000 ? 000106530 ?
000106400 ? 106530764 ?
__sighndlr()+12      PTR_CALL 0000000000000000     10652D000 ? 1066C9EF0 ?
10652A72C ? 00010652D ?
000000006 ? 000000067 ?
call_user_handler()  CALL     __sighndlr()         000000006 ? 1066C9EF0 ?
+992                                               1066C9C10 ? 10033B1C0 ?
000000000 ? 000000005 ?
sigacthandler()+84   CALL     call_user_handler()  FFFFFFFF7D500200 ?
FFFFFFFF7D500200 ?
1066C9C10 ? 000000009 ?
000000000 ? 000000000 ?
__lwp_kill()+8       PTR_CALL 0000000000000000     000000000 ? 1066C9EF0 ?
1066C9C10 ?
FFFFFFFF7D500200 ?
000000000 ?
FFFFFFFF7C73C000 ?
raise()+16           FRM_LESS _pthread_kill()      000000000 ? 000000006 ?
FFFFFFFF7F60AC48 ?
FFFFFFFF7C54B048 ?
000000005 ?
FFFFFFFF7C74CB50 ?
abort()+208          CALL     raise()              000000006 ? 000000006 ?
000000005 ?
FFFFFFFF7C748500 ?
FFFFFFFF7D500200 ?
000000005 ?
vcsipc_poll()+1724   CALL     FFFFFFFF7F5477E0     000001DA0 ?
FFFFFFFF7F550D00 ?
FFFFFFFF7F4205A8 ?
0001F107C ? 000000001 ?
000000000 ?
skgxpwait()+5604     CALL     vcsipc_poll()        FFFFFFFF7FFECE90 ?
106747378 ? 000001FD0 ?
FFFFFFFF7FFE78C8 ?
000001C00 ? 000200000 ?
ksxpwait()+1804      CALL     0000000106524980     FFFFFFFF7F54FC28 ?
106747378 ? 000000000 ?
FFFFFFFF7FFECF68 ?
0000004E2 ?
FFFFFFFF7FFECE90 ?
ksliwat()+2952       CALL     ksxpwait()           000000000 ? 000101000 ?
000000000 ? 10652DB98 ?
000001000 ? 106533FC8 ?
kslwaitns_timed()+4  CALL     ksliwat()            000000000 ? 000000002 ?
8                                                  00000007D ? 5798B6C18 ?
5798B6BA0 ? 000032033 ?
kskthbwt()+232       CALL     kslwaitns_timed()    00000007D ? 000000001 ?
00000007C ? 000000000 ?
FFFFFFFF7FFED3B8 ?
000000001 ?
kslwait()+116        CALL     kskthbwt()           00000007D ? 00000007C ?
000000000 ? 000000007 ?
000032033 ? 000000001 ?
ksxprcv()+916        CALL     kslwait()            0925A2B0A ? 000000000 ?
00000000A ? 00000000A ?
000032033 ? 000000001 ?
kclwcrs()+960        CALL     ksxprcv()            0001056DE ? 10652B118 ?
00000007D ? 1056DE598 ?
00010652A ? 1056DE000 ?
kclgclk()+10052      CALL     kclwcrs()            3800143A8 ? 000000000 ?
000000000 ? 519F716A0 ?
000000007 ? 000106535 ?
kcbzib()+19288       CALL     kclgclk()            000106400 ? 00000000C ?
FFFFFFFF7FFF5EB8 ?
000000000 ? 000000000 ?
000105400 ?
kcbgtcr()+10528      CALL     kcbzib()             5665FB520 ?
FFFFFFFF7C058170 ?
000105C00 ? 000000000 ?
000000006 ?
FFFFFFFF7FFF44A0 ?
ktrget()+260         CALL     kcbgtcr()            FFFFFFFF7FFF5028 ?
FFFFFFFF7FFF502C ?
5665FB520 ? 000000000 ?
000000000 ? 57FF6DA18 ?
kdst_fetch()+872     CALL     ktrget()             FFFFFFFF7C058160 ?
FFFFFFFF7C0580E0 ?
00000023F ? 000000000 ?
FFFFFFFF7C058170 ?
3800172B8 ?
kdstf0100101km()+50  CALL     kdst_fetch()         FFFFFFFF7C058158 ?
4                                                  000000000 ?
FFFFFFFF7FFF5688 ?
000106528 ? 00000023F ?
00000FC00 ?
kdsttgr()+27872      CALL     kdstf0100101km()     FFFFFFFF7C058158 ?
4E6AB809E ? 000000001 ?
000000000 ? 54C540BB8 ?
FFFFFFFF7C058038 ?
qertbFetch()+720     CALL     kdsttgr()            000000000 ? 000000000 ?
FFFFFFFF7C054EA8 ?
FFFFFFFF7C058158 ?
000000004 ? 1032109C0 ?
qerflFetch()+172     PTR_CALL 0000000000000000     000000001 ? 000000001 ?
1056DE068 ?
FFFFFFFF7FFF6348 ?
10652B298 ? 000000002 ?
opifch2()+8204       PTR_CALL 0000000000000000     FFFFFFFF7C058898 ?
102527EE0 ?
FFFFFFFF7FFF69D0 ?
000000001 ? 103210000 ?
10320CA00 ?
opifch()+52          CALL     opifch2()            FFFFFFFF7FFF6878 ?
000000090 ? 000000000 ?
000000001 ? 000000000 ?
105A2C000 ?
opipls()+3532        CALL     opifch()             000000005 ? 000000002 ?
FFFFFFFF7FFF6F20 ?
000000002 ? 000000000 ?
000000001 ?
opiodr()+1548        PTR_CALL 0000000000000000     000106400 ? 10653A000 ?
000105800 ? 000000010 ?
00010653A ?
FFFFFFFF7B6392D8 ?
rpidrus()+196        CALL     opiodr()             10576DC08 ? 000000066 ?
10652B000 ? 000000001 ?
FFFFFFFF7C03A830 ?
00010652D ?
skgmstack()+168      PTR_CALL 0000000000000000     FFFFFFFF7FFF8350 ?
000000006 ?
FFFFFFFF7FFF8100 ?
10652A000 ? 000000066 ?
1056DE000 ?
rpidru()+172         CALL     skgmstack()          10034D1E0 ?
FFFFFFFF7FFF8350 ?
00000F618 ? 10034D1E0 ?
FFFFFFFF7FFF8350 ?
FFFFFFFF7FFF8328 ?
rpiswu2()+500        PTR_CALL 0000000000000000     FFFFFFFF7FFF8B18 ?
1056C3000 ? 1056C2B90 ?
1056C0F50 ? 000000C10 ?
000000182 ?
rpidrv()+1696        CALL     rpiswu2()            000000000 ? 10652B298 ?
000000000 ?
FFFFFFFF7FFF84E8 ?
1056DE000 ? 00010652A ?
psddr0()+516         CALL     rpidrv()             FFFFFFFF7FFF8EC0 ?
000105C00 ?
FFFFFFFF7FFF89C4 ?
000000002 ?
FFFFFFFF7B615F60 ?
00010652D ?
psdnal()+512         CALL     psddr0()             106541CE0 ? 10652B298 ?
000000066 ? 1056DE068 ?
000000008 ? 00000000A ?
pevm_BFTCHC()+308    PTR_CALL 0000000000000000     FFFFFFFF7FFF9CA8 ?
00000000A ? 000000000 ?
FFFFFFFF7B6396F8 ?
106537000 ? 10652B000 ?
pfrinstr_FTCHC()+18  CALL     pevm_BFTCHC()        000000000 ? 105AE7600 ?
0                                                  555E62580 ?
FFFFFFFF7C069EE8 ?
FFFFFFFF7B6396F8 ?
000000000 ?
pfrrun_no_tool()+72  PTR_CALL 0000000000000000     000000000 ? 000000000 ?
FFFFFFFF7C069F50 ?
FFFFFFFF7C069EE8 ?
0000001EE ? 555E62892 ?
pfrrun()+832         CALL     pfrrun_no_tool()     FFFFFFFF7C069EE8 ?
555E6288E ?
FFFFFFFF7C069F50 ?
105B1BF50 ? 000002001 ?
000002001 ?
plsql_run()+696      CALL     pfrrun()             FFFFFFFF7C035420 ?
FFFFFFFF7C069EE8 ?
000002001 ? 000200000 ?
FFFFFFFF7C069EE8 ?
0001056DE ?
peicnt()+260         CALL     plsql_run()          000000006 ? 000000000 ?
FFFFFFFF7B63BBF8 ?
FFFFFFFF7FFF9888 ?
000000180 ? 000000007 ?
kkxexe()+616         CALL     peicnt()             FFFFFFFF7FFFA808 ?
10652B298 ? 106541CE0 ?
106762258 ? 10652B000 ?
10652B000 ?
opiexe()+12736       CALL     kkxexe()             FFFFFFFF7B63F4B8 ?
106537000 ? 000106537 ?
FFFFFFFF7FFF9CA8 ?
000000000 ? 54C0616F0 ?
kpoal8()+1912        CALL     opiexe()             000106400 ?
FFFFFFFF7C056EC0 ?
000000000 ? 000000000 ?
000000000 ? 57FDB9250 ?
opiodr()+1548        PTR_CALL 0000000000000000     0BFFFFC00 ? 000040008 ?
000000000 ? 000000820 ?
000105800 ? 106538260 ?
ttcpip()+1284        PTR_CALL 0000000000000000     10576DC08 ? 00000005E ?
10652B000 ? 000000001 ?
FFFFFFFF7C03A830 ?
00010652D ?
opitsk()+1432        CALL     ttcpip()             000000017 ?
FFFFFFFF7FFFCFB0 ?
1056C3F6C ? 1056C1750 ?
000000000 ? 10652B118 ?
opiino()+1128        CALL     opitsk()             106538268 ? 000000001 ?
000000000 ? 106538260 ?
1058884D0 ? 0FFFFFFFD ?
opiodr()+1548        PTR_CALL 0000000000000000     000106400 ? 10652DB98 ?
000106400 ? 10652D000 ?
000106400 ? 106538260 ?
opidrv()+896         CALL     opiodr()             1065373D8 ? 00000003C ?
000106400 ? 1065381E0 ?
000106538 ? 00010652D ?
sou2o()+80           CALL     opidrv()             10653A960 ? 000000000 ?
00000003C ? 106537698 ?
00000003C ? 000000000 ?
opimai_real()+124    CALL     sou2o()              FFFFFFFF7FFFF708 ?
00000003C ? 000000004 ?
FFFFFFFF7FFFF730 ?
105E12000 ? 000105E12 ?
main()+152           CALL     opimai_real()        000000002 ?
FFFFFFFF7FFFF808 ?
104054D6C ? 1064D3220 ?
00247E3B4 ? 000014800 ?
_start()+380         CALL     main()               000000002 ? 000000008 ?
000000000 ?
FFFFFFFF7FFFF818 ?
FFFFFFFF7FFFF928 ?
FFFFFFFF7D500200 ?

经过和MOS确认,认为是apply了Patch 5165885后引起的新问题:

I have checked our internal bug database and issue seems to be occuring due to fix for Bug.5165885.

Action plan:
=============

Apply patch for 6678154

https://updates.oracle.com/download/6678154.html

Workaround:
————–

Remove the patch for 5165885 .

Yes, Symptoms are pointing finger towards this bug. I would recommend to apply the patch rather than going for workarounds.

这个case目前实施了补丁6678154,仍在观察期。
录以记之!

利用FORCE_MATCHING_SIGNATURE捕获非绑定变量SQL

做为一个DBA,你大概习惯了定期要抓取数据库中的非绑定变量SQL,这些SQL经常扮演着一箱苹果中蛀虫的角色。
看到下列SQL你必定觉得眼熟:

SELECT substr(sql_text, 1, 80), count(1)
FROM v$sql
GROUP BY substr(sql_text, 1, 80)
HAVING count(1) > 10
ORDER BY 2

是的,以上这段抓取literal sql的脚本大约从8i时代就开始流行了,在那时它很popular也很休闲,使用它或许还会给你的雇主留下一丝神秘感。不过今天我要告诉你的是,它彻底过时了,落伍了,已经不是fashion master了。
10g以后v$SQL动态性能视图增加了FORCE_MATCHING_SIGNATURE列,其官方定义为”The signature used when the CURSOR_SHARING parameter is set to FORCE”,也就是Oracle通过将原SQL_TEXT转换为可能的FORCE模式后计算得到的一个SIGNATURE值。这么说可能不太形象,我们来具体看一下:

SQL> create table YOUYUS (t1 int);
Table created.
SQL> alter system flush shared_pool;
System altered.
SQL>select /*test_matching_a*/ * from YOUYUS where t1=1;
no rows selected
SQL>select /*test_matching_a*/ * from YOUYUS where t1=2;
no rows selected
SQL>select /*test_matching_a*/ * from YOUYUS where t1=3;
no rows selected
SQL> col sql_text format a55;
SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
2    FROM V$SQL
3   WHERE sql_text like '%test_matching_a%'
4     and sql_text not like '%like%';
SQL_TEXT                                                FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
------------------------------------------------------- ------------------------ ------------------------
select /*test_matching_a*/ * from YOUYUS where t1=2          4.59124694481197E18      1.00267830752731E19
select /*test_matching_a*/ * from YOUYUS where t1=3          4.59124694481197E18      1.61270448861426E19
select /*test_matching_a*/ * from YOUYUS where t1=1          4.59124694481197E18      1.36782048270058E18
/*以上将变量硬编码至SQL中的游标,FORCE_MATCHING_SIGNATURE值完全相同,而EXACT_MATCHING_SIGNATURE值各有不同。FORCE_MATCHING_SIGNATURE值相同说明在游标共享FORCE模式下,这些游标满足CURSOR SHARING的条件 */
SQL> alter system flush shared_pool;
System altered.
SQL> alter session set cursor_sharing=FORCE;
Session altered.
SQL>select /*test_matching_a*/ * from YOUYUS where t1=1;
no rows selected
SQL>select /*test_matching_a*/ * from YOUYUS where t1=2;
no rows selected
SQL>select /*test_matching_a*/ * from YOUYUS where t1=3;
no rows selected
SQL> col sql_text for a70
SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
2    FROM V$SQL
3   WHERE sql_text like '%test_matching_a%'
4     and sql_text not like '%like%';
SQL_TEXT                                                               FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
---------------------------------------------------------------------- ------------------------ ------------------------
select /*test_matching_a*/ * from YOUYUS where t1=:"SYS_B_0"                4.59124694481197E18      4.59124694481197E18
/*FORCE模式下将SQL文本中的变量值转换成了:SYS_B形式,EXACT_MATCHING_SIGNATURE也随之等同于FORCE_MATCHING_SIGNATURE了*/

以上演示说明了FORCE_MATCHING_SIGNATURE列可以帮助我们找出那些潜在可以共享的游标(也包括了因非绑定问题造成的游标无法共享),现在我们利用它来完善捕获非绑定变量SQL的脚本:

SQL> alter system flush shared_pool;
System altered.
SQL> select  /*test_matching_b*/ * from YOUYUS where t1=1;
no rows selected
SQL> select  /*test_matching_b*/ * from YOUYUS where t1='1';            //我有引号,我与众不同!
no rows selected
SQL> col sql_text for a70
SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
2    FROM V$SQL
3   WHERE sql_text like '%test_matching_b%'
4     and sql_text not like '%like%';
SQL_TEXT                                                               FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
---------------------------------------------------------------------- ------------------------ ------------------------
select  /*test_matching_b*/ * from YOUYUS where t1='1'                      1.43666633406896E19      1.83327833675856E19
select  /*test_matching_b*/ * from YOUYUS where t1=1                       1.43666633406896E19      8.05526057286178E18
/*多余的引号也会导致游标无法共享,此时的FORCE_MATCHING_SIGNATURE 也会是一致的*/
select FORCE_MATCHING_SIGNATURE, count(1)
from v$sql
where FORCE_MATCHING_SIGNATURE > 0
and FORCE_MATCHING_SIGNATURE != EXACT_MATCHING_SIGNATURE
group by FORCE_MATCHING_SIGNATURE
having count(1) > &a
order by 2;
Enter value for a: 10
old   6: having count(1) > &a
new   6: having count(1) > 10
FORCE_MATCHING_SIGNATURE   COUNT(1)
------------------------ ----------
8.81463386552502E18         12
So We find it!

在这里再推荐一种来自MOS,find Literal SQL的方法:

How to Find Literal SQL in Shared Pool


Applies to:

PL/SQL – Version: 8.1.7 to 10.2
Information in this document applies to any platform.

Goal

There is no direct way to query the dictionary for literal SQL only.

However the following example will try to exclude all SQL statements in the
shared pool that do use bind variables.

There still might be situations, with statements using subqueries, where the
example still will show SQL statements using bind variables.

Solution

Create the following PL/SQL block:

[maclean@rh2 bin]$ cat  find_literal.sql
set serveroutput on
set linesize 120
--
-- This anonymous PL/SQL block must be executed as INTERNAL or SYS
-- Execute from : SQL*PLUS
-- CAUTION:
-- This sample program has been tested on Oracle Server - Enterprise Edition
-- However, there is no guarantee of effectiveness because of the possibility
-- of error in transmitting or implementing it. It is meant to be used as a
-- template, and it may require modification.
--
declare
b_myadr VARCHAR2(20);
b_myadr1 VARCHAR2(20);
qstring VARCHAR2(100);
b_anybind NUMBER;
cursor my_statement is
select address from v$sql
group by address;
cursor getsqlcode is
select substr(sql_text,1,60)
from v$sql
where address = b_myadr;
cursor kglcur is
select kglhdadr from x$kglcursor
where kglhdpar = b_myadr
and kglhdpar != kglhdadr
and kglobt09 = 0;
cursor isthisliteral is
select kkscbndt
from x$kksbv
where kglhdadr = b_myadr1;
begin
dbms_output.enable(10000000);
open my_statement;
loop
Fetch my_statement into b_myadr;
open kglcur;
fetch kglcur into b_myadr1;
if kglcur%FOUND Then
open isthisliteral;
fetch isthisliteral into b_anybind;
if isthisliteral%NOTFOUND Then
open getsqlcode;
fetch getsqlcode into qstring;
dbms_output.put_line('Literal:'||qstring||' address: '||b_myadr);
close getsqlcode;
end if;
close isthisliteral;
end if;
close kglcur;
Exit When my_statement%NOTFOUND;
End loop;
close my_statement;
end;
/
/*尝试执行*/
SQL> @find_literal
Literal:select inst_id, java_size, round(java_size / basejava_size,  address: 00000000BC6E94E8
Literal:select reason_id, object_id, subobject_id, internal_instance address: 00000000BC5F1D60
Literal:select  DBID, NAME, CREATED, RESETLOGS_CHANGE#, RESETLOGS_TI address: 00000000BC6000B0
Literal:select di.inst_id,di.didbi,di.didbn,to_date(di.dicts,'MM/DD/ address: 00000000BC530DA8
Literal:      declare          vsn  varchar2(20);             begin  address: 00000000BC85A9F8
Literal:SELECT INCARNATION#, RESETLOGS_CHANGE#, RESETLOGS_TIME, PRIO address: 00000000BC829978
Literal:select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where  address: 00000000BCA84D00
Literal:select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U address: 00000000BC771BF0
Literal: select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_S address: 00000000BC4673A8
Literal:select streams_pool_size_for_estimate s,           streams_p address: 00000000BCA58848
Literal:         select open_mode from v$database address: 00000000BC5DF2D0
Literal:select FORCE_MATCHING_SIGNATURE, count(1)   from v$sql  wher address: 00000000BCA91628
Literal:select inst_id, tablespace_name, segment_file, segment_block address: 00000000BC66EF38
Literal:select sum(used_blocks), ts.ts#   from GV$SORT_SEGMENT gv, t address: 00000000BCAA01B0
Literal:BEGIN DBMS_OUTPUT.ENABLE(NULL); END; address: 00000000BC61D2D8
Literal:select value$ from props$ where name = 'GLOBAL_DB_NAME' address: 00000000BC570500
Literal:select count(*) from sys.job$ where (next_date > sysdate) an address: 00000000BC6C53F8
Literal:select java_pool_size_for_estimate s,           java_pool_si address: 00000000BCA65070
Literal:select local_tran_id, global_tran_fmt, global_oracle_id, glo address: 00000000BC5900B8
Literal:select inst_id,kglnaobj,kglfnobj,kglobt03, kglobhs0+kglobhs1 address: 00000000BC921538
Literal:select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname, address: 00000000BCA83E90
Literal:SELECT * FROM V$SQL address: 00000000BCA58BC0
Literal:SELECT ADDRESS FROM V$SQL GROUP BY ADDRESS address: 00000000BC565BE8
Literal:      begin          dbms_rcvman.resetAll;       end; address: 00000000BC759858
Literal:declare b_myadr VARCHAR2(20); b_myadr1 VARCHAR2(20); qstring address: 00000000BC928FF8
Literal:select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, address: 00000000BC898BF8
Literal:select CONF#, NAME, VALUE from GV$RMAN_CONFIGURATION where i address: 00000000BC8CB7F8
Literal:select f.file#, f.block#, f.ts#, f.length from fet$ f, ts$ t address: 00000000BC8CDFE8
Literal:select u.name, o.name, trigger$.sys_evts, trigger$.type#  fr address: 00000000BCA877B8
Literal:select id, name, block_size, advice_status,                  address: 00000000BC636B38
Literal:select incarnation#, resetlogs_change#, resetlogs_time,      address: 00000000BCA94250
Literal:select  INSTANCE_NUMBER , INSTANCE_NAME , HOST_NAME , VERSIO address: 00000000BC62A678
Literal:select ks.inst_id,ksuxsins,ksuxssid,ksuxshst,ksuxsver,ksuxst address: 00000000BC8E5440
Literal:select timestamp, flags from fixed_obj$ where obj#=:1 address: 00000000BC916C78
Literal:select size_for_estimate,                      size_factor * address: 00000000BCA5F830
Literal:select shared_pool_size_for_estimate s,          shared_pool address: 00000000BCA5A350
Literal:select  SQL_TEXT , SQL_FULLTEXT , SQL_ID,  SHARABLE_MEM , PE address: 00000000BC76B3A0
Literal:lock table sys.col_usage$ in exclusive mode nowait address: 00000000BCA05978
Literal:select 'x' from dual  address: 00000000BC583818
Literal:      select name, resetlogs_time,              resetlogs_ch address: 00000000BCA9D430
Literal:select inst_id, sp_size, round(sp_size / basesp_size, 4),  k address: 00000000BC65A9F0
Literal:select userenv('Instance'),  icrid, to_number(icrls),        address: 00000000BC692260
Literal:select shared_pool_size_for_estimate, shared_pool_size_facto address: 00000000BCAE0750
Literal:select INST_ID, RMRNO, RMNAM, RMVAL from X$KCCRM where RMNAM address: 00000000BC8CD778
Literal:select metadata from kopm$  where name='DB_FDO' address: 00000000BC9EBB98
Literal:select java_pool_size_for_estimate, java_pool_size_factor,   address: 00000000BC5B27D0
Literal:SELECT INCARNATION#, INCARNATION#, RESETLOGS_CHANGE#, RESETL address: 00000000BC829C48
Literal:select file# from file$ where ts#=:1 address: 00000000BC87CF18
Literal:select A.inst_id, A.bpid, B.bp_name, A.blksz,                address: 00000000BC802248
Literal:lock table sys.mon_mods$ in exclusive mode nowait address: 00000000BC5CBE68
Literal:lock table sys.mon_mods$ in exclusive mode nowait address: 00000000BC5CBE68

ddl操作是否会产生undo?

ddl是否会产生undo?
这可能是每一个初学Oracle的人都会有的疑问;ddl操作又不能rollback回滚,要什么undo数据呢?
事实是几乎每个ddl操作都会产生undo,我们来探究一下:

SQL> select vs.name, ms.value
2    from v$mystat ms, v$sysstat vs
3   where ms.statistic# = vs.statistic#
4     and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0
SQL> create table YOUYUS (t1 int);
Table created.
SQL>   select vs.name, ms.value
2      from v$mystat ms, v$sysstat vs
3     where ms.statistic# = vs.statistic#
4       and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                1992
/*create table的ddl语句产生了大约1992 bytes的撤销变化向量*/
SQL> drop table YOUYUS;
Table dropped.
SQL>   select vs.name, ms.value
2      from v$mystat ms, v$sysstat vs
3     where ms.statistic# = vs.statistic#
4       and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                4528
/* drop table语句产生2563 bytes的undo数据,多于create table;我们可以猜测create table时Oracle需要向基表中insert数据,而drop table时则需要delete/update数据,显然后者产生更多的undo*/
/*我们尝试创建一个由254个列组成的表*/
SQL>     select vs.name, ms.value
2        from v$mystat ms, v$sysstat vs
3       where ms.statistic# = vs.statistic#
4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0
create table YOUYUS (
t1 int,
t2 char(4) default 'oooo',
t3 char(4) default 'oooo',
t4 char(4) default 'oooo',
t5 char(4) default 'oooo',
t6 char(4) default 'oooo',
t7 char(4) default 'oooo',
t8 char(4) default 'oooo',
t9 char(4) default 'oooo',
............................
t248 char(4) default 'oooo',
t249 char(4) default 'oooo',
t250 char(4) default 'oooo',
t251 char(4) default 'oooo',
t252 char(4) default 'oooo',
t253 char(4) default 'oooo',
t254 char(4) default 'oooo'
);
SQL>     select vs.name, ms.value
2        from v$mystat ms, v$sysstat vs
3       where ms.statistic# = vs.statistic#
4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                               85832
/*产生了83k的undo,ddl所产生的undo量视乎其所要维护数据字典的操作类型和操作量*/
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.
SQL> drop table YOUYUS;
Table dropped.
SQL>     select vs.name, ms.value
2        from v$mystat ms, v$sysstat vs
3       where ms.statistic# = vs.statistic#
4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                              214020
/*drop 产生了125k的undo*/
SQL> oradebug tracefile_name;
/home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_5433.trc
/* 我们来看看drop table 到底做了哪些递归操作? */
[maclean@rh2 ~]$ cat PROD_ora_5433.trc|egrep "delete|update"
'Need use delete_topo_geometry_layer() to deregister table '
select decode(u.type#, 2, u.ext_username, u.name), o.name,        t.update$, t.insert$, t.delete$, t.enabled,        decode(bitand(t.property, 8192),8192, 1, 0),        decode(bitand(t.property, 65536), 65536, 1, 0),       decode(bitand(t.property, 131072), 131072, 1, 0),       (select o.name from obj$ o          where o.obj# = u.spare2 and o.type# =57)  from sys.obj$ o, sys.user$ u, sys.trigger$ t, sys.obj$ bo where t.baseobject=bo.obj# and bo.name = :1 and bo.spare3 = :2  and bo.namespace = 1  and t.obj#=o.obj# and o.owner#=u.user#  and o.type# = 12 and bitand(property,16)=0 and bitand(property,8)=0  order by o.obj#
delete from object_usage where obj# in  (select a.obj# from object_usage a, ind$ b where  a.obj# = b.obj# and b.bo# = :1)
delete from sys.cache_stats_1$ where dataobj# = :1
delete com$ where obj#=:1
delete from hist_head$ where obj# = :1
delete from dependency$ where d_obj#=:1
delete from source$ where obj#=:1
delete from compression$ where obj#=:1
m_stmt:='delete from sdo_geor_ddl__table$$ where id=2';
m_stmt:='delete from sdo_geor_ddl__table$$';
delete from sdo_geor_ddl__table$$ where id=2
delete from col$ where obj#=:1
delete from icol$ where bo#=:1
delete from icoldep$ where obj# in (select obj# from ind$ where bo#=:1)
delete from jijoin$ where obj# in ( select obj# from jijoin$ where tab1obj# = :1 or tab2obj# = :1)
delete from jirefreshsql$ where iobj# in ( select iobj# from jirefreshsql$ where tobj# = :1)
delete from ccol$ where obj#=:1
delete from ind$ where bo#=:1
delete from cdef$ where obj#=:1
delete ecol$ where tabobj# = :1
delete from tab$ where obj#=:1
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from col$ where obj#=:1
delete coltype$ where obj#=:1
delete from subcoltype$ where obj#=:1
delete ntab$ where obj#=:1
delete lob$ where obj#=:1
delete refcon$ where obj#=:1
delete from opqtype$ where obj#=:1
delete from cdef$ where obj#=:1
delete from objauth$ where obj#=:1
delete from obj$ where obj# = :1
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3
delete from seg$ where ts#=:1 and file#=:2 and block#=:3
/*如果ddl操作执行失败又会如何呢?*/
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.
SQL>     select vs.name, ms.value
2        from v$mystat ms, v$sysstat vs
3       where ms.statistic# = vs.statistic#
4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0
SQL> drop table YOUYUS;
drop table YOUYUS
*
ERROR at line 1:
ORA-00942: table or view does not exist
SQL>     select vs.name, ms.value
2        from v$mystat ms, v$sysstat vs
3       where ms.statistic# = vs.statistic#
4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                 264
/*同样产生了undo,量较少*/
SQL> oradebug tracefile_name;
/home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_5494.trc
[maclean@rh2 trace]$ cat PROD_ora_5494.trc|egrep "update|insert|delete"
'Need use delete_topo_geometry_layer() to deregister table '
m_stmt:='insert into sdo_geor_ddl__table$$ values (1)';
m_stmt:='insert into sdo_geor_ddl__table$$ values (2)';
insert into sdo_geor_ddl__table$$ values (2)
m_stmt:='delete from sdo_geor_ddl__table$$';
delete from sdo_geor_ddl__table$$
/*执行少量递归操作后,Oracle发现所要drop的对象并不存在,将会rollback之前的"部分"递归dml操作*/
其实我们可以把ddl操作分解为以下步骤:
begin
commit;
--编译ddl
begin
--实现ddl,包括一系列递归的数据字典维护操作及其他操作
commit;
exception
when others then
rollback;
end;
end;

ddl操作无需也不允许手动commit或rollback参与,但这并不代表ddl操作不产生undo。

对于OCM考试的几点意见和建议

Oracle Certified Master(OCM) 大师认证资质是Oracle认证的最高级别。此认证是对技术、知识和操作技能的最高级别的认可。Oracle认证大师是解决最困难的技术难题和最复杂的系 统故障的最佳Oracle专家人选。资深专家级Oracle 技能考试,通过后将成为企业内的资深专家和顾问。OCM 不但有能力处理关键业务数据库系统和应用,还能帮助客户解决所有的Oracle 技术困难。要想获得OCM 证书,必须先通过OCA、OCP考试,再学习两门高级技术课程,然后在Oracle 实验室通过场景实验考试。场景实验考试的目的是测试您的实际问题分析和故障解决能力。

作为一个过来人,我十分愿意分享我对备考OCM的几点建议:

这对于你来说既是一次考试,也是一次系统复习的好机会;OCM考试的面非常广,部分环节可能是你从未实践过的。
准备时间最好不要少于半年,但也千万不要超过半年。
准备阶段使用考纲指定的操作系统,DB,OMS,Clusterware版本。这里推荐在Redhat或Oracle Enterprise Linux 4.7平台上练习,切勿使用windows或windows远程登录练习。
2天的考试是对体力的考验,所以要保证充足的睡眠。
试卷分英语和日语两版;题目文字量较多,需认真阅读;如果对题意并不明了,可以让监考老师进一步解释,一般不会推辞。
很多考试中要求建立的对象可以通过OMS获得SQL语句,确认后输入到SQLPLUS中执行。
部分环节需要十分耐心,如果你不想在屏幕前焦急等待,可以去上个厕所或者泡杯咖啡,总之请放轻松。
如果你不熟悉Grid Control(OMS)界面,那么可以尝试读一下《Oracle.Enterprise.Manager.10g.Grid.Control.Implementation.Guide.2009》,并勤加练习。
考试期间可以阅读10g的官方文档,也可以查询metalink(MOS),前提是在你有足够时间的情况下。
安装配置Grid Control(OMS)是考试的一个高危阶段,这往往决定于你的安装配置经验以及人品,但是一旦出现了问题而你毫无troubleshooting Grid Control的能力,那么就显得事倍功半了。
考试后的hand on是一个”复杂的”过程,请致电OU的800电话。

to be continued …………

Does DB Time include wait on cpu queue time?

DB TIME1=DB CPU2+ Foreground NO-Idle wait time

1:Amount of elapsed time (in microseconds) spent performing Database user-level calls. This does not include the elapsed time spent on instance background processes such as PMON.

2:Amount of CPU time (in microseconds) spent on database user-level calls. This does not include the CPU time spent on instance background processes such as PMON.

10g中引入了基于时间统计信息的调优模型,其核心或者说最值得我们关心的大概是DB TIME和AASC 2项指标。DB TIME是Oracle在数据库层对用户级别(不包括后台进程的CPU和非空闲等待时间)各类操作耗时的一个总计,它直接反映了数据库前台的”工时”。DB TIME是否包含了前台进程在CPU队列上的等待时间呢,换而言之我们的命题是”Does DB TIME equal to DB CPU+Foreground NO-Idle wait time + DB CPU ON QUEUE ?”

让我们来看看以下测试:

[maclean@rh2 ~]$ cat /proc/cpuinfo |grep processor|wc -l
2
/*这是一台双核的pc服务器*/
打开session A:
begin
/* first one busy on cpu */
loop
null;
end loop;
end;
/*死循环调用NULL,会尝试独占一个逻辑CPU,没有其他等待事件*/
打开SESSION B:
begin
/* second one busy on cpu */
loop
null;
end loop;
end;
打开SESSION C:
begin
/* third one busy on cpu */
loop
null;
end loop;
end;
打开SESSION D:
SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.
/*手动收集AWR 快照*/
/*等待几分钟,以便收集信息*/
SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.
/*再次手动收集快照*/

我们来看看AWR报告中的Time Model Statistics:

DB TIME为344s,而DB CPU为226s。以上匿名PL/SQL块仅引起CPU争用(不会产生其他前台等待事件),而这里DB TIME要远大于DB CPU,可见DB TIME=DB CPU+Foreground wait time+Cpu on queue;  我们也可以观察以下OEM界面上的AAS图形:

ASH报告也正确反映了这一事实,虽然它把cpu time和wait on cpu queue归并做了Cpu+wait for CPU:

可以看到CPU ON QUEUE有时被计为Wait time部分。当以上3个回话同时执行CPU敏感的匿名块过程时,其瞬时的Average Session Count为3,而该pc服务器上只有2个逻辑CPU,可以认为实例在该短期内存出现严重阻塞,表现到OS层也就是短期内持续队列较高。

[maclean@rh2 ~]$ vmstat 2
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
3  0      0 752180  93912 2127440    0    0   194   168  536  302  6  1 90  3  0
3  0      0 752056  93912 2127508    0    0     0     0 1012  661 100  0  0  0  0
2  0      0 751436  93928 2127548    0    0     0   932 1131  750 99  1  0  0  0
2  0      0 751436  93928 2127596    0    0     0    16 1012  644 99  0  0  0  0
2  0      0 751444  93928 2127596    0    0     0     0 1011  695 100  0  0  0  0

8i查询DBA_FREE_SPACE视图极慢的问题

还是那套古老的8.1.7.4,在该系统上检查表空间使用情况的SQL运行缓慢,其SQL如下:

SELECT D.TABLESPACE_NAME,
SPACE "SUM_SPACE(M)",
SPACE - NVL(FREE_SPACE, 0) "USED_SPACE(M)",
ROUND((1 - NVL(FREE_SPACE, 0) / SPACE) * 100, 2) "USED_RATE(%)",
FREE_SPACE "FREE_SPACE(M)"
FROM (SELECT TABLESPACE_NAME, ROUND(SUM(BYTES) / (1024 * 1024), 2) SPACE
FROM DBA_DATA_FILES
GROUP BY TABLESPACE_NAME) D,
(SELECT TABLESPACE_NAME,
ROUND(SUM(BYTES) / (1024 * 1024), 2) FREE_SPACE
FROM DBA_FREE_SPACE
GROUP BY TABLESPACE_NAME) F
where d.tablespace_name = f.tablespace_name(+)
order by "USED_RATE(%)" desc;
/*很面熟的DBA常用脚本吧?*/

经确认其中对DBA_FREE_SPACE视图的查询耗费了大量时间,8i中该视图的默认定义是:

select ts.name,
fi.file#,
f.block#,
f.length * ts.blocksize,
f.length,
f.file#
from sys.ts$ ts, sys.fet$ f, sys.file$ fi
where ts.ts# = f.ts#
and f.ts# = fi.ts#
and f.file# = fi.relfile#
and ts.bitmapped = 0
/*以上查询DMT表空间上的FREE EXTENT*/
union all
/*以下查询LMT表空间上的FREE EXTENT*/
select /*+ ordered use_nl(f) use_nl(fi) */
ts.name,
fi.file#,
f.ktfbfebno,
f.ktfbfeblks * ts.blocksize,
f.ktfbfeblks,
f.ktfbfefno
from sys.ts$ ts, sys.x$ktfbfe f, sys.file$ fi
where ts.ts# = f.ktfbfetsn
and f.ktfbfetsn = fi.ts#
and f.ktfbfefno = fi.relfile#
and ts.bitmapped <> 0
and ts.online$ in (1, 4)
and ts.contents$ = 0
/*也许你感到奇怪,实际上8i中就有了本地管理模式的表空间了,只是很少有人用。("In Oracle 8i the EXTENT MANAGEMENT clause was introduced into the CREATE TABLESPACE statement allowing extent management to be LOCAL or DICTIONARY. Locally Manages Tablespaces (LMT) have a bitmap of the blocks, or groups of blocks, they contain allowing them to track extent allocation without reference to the data dictionary.")*/
/*因字典管理模式下FET$基表往往较大,导致UNION ALL以上部分在连接操作时会产生大量的逻辑读,最终导致了对DBA_FREE_SPACE视图的查询十分缓慢。*/

Oracle 提供了官方的视图并不意味着我们非它不可用,可以通过修改DBA_FREE_SPACE的定义,或另建一个具有相同功能但查询SQL构造不同的视图来加快查询速度:

explain plan for
select /*+use_hash (tsfi, fet2 ) */
tsfi.tablespace_name,
tsfi.file_id,
fet2.block_id,
tsfi.blocksize * fet2.blocks,
fet2.blocks,
tsfi.relfile#
from (select /*+ use_hash ( ts, fi ) */
ts.name      tablespace_name,
fi.file#     file_id,
ts.BLOCKSIZE,
fi.relfile#,
ts.ts#
from sys.ts$ ts, sys.file$ fi
where ts.ts# = fi.ts#
and ts.online$ in (1, 4)) tsfi,
(select f.block# block_id, f.length blocks, f.file# file_id, f.ts#
from sys.fet$ f
union all
select f.ktfbfebno  block_id,
f.ktfbfeblks blocks,
f.ktfbfefno,
ktfbfetsn
from sys.x$ktfbfe f) fet2
where fet2.file_id = tsfi.relfile#
and fet2.ts# = tsfi.ts# /*此查询需SYSDBA权限*/ ;
Explained
select * from  table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------
Plan hash value: 717737944
---------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |    20 |  1560 |     9  (12)| 00:00:01 |
|*  1 |  HASH JOIN           |          |    20 |  1560 |     9  (12)| 00:00:01 |
|*  2 |   HASH JOIN          |          |     4 |   104 |     6  (17)| 00:00:01 |
|   3 |    TABLE ACCESS FULL | FILE$    |     4 |    36 |     2   (0)| 00:00:01 |
|*  4 |    TABLE ACCESS FULL | TS$      |     5 |    85 |     3   (0)| 00:00:01 |
|   5 |   VIEW               |          |   101 |  5252 |     3   (0)| 00:00:01 |
|   6 |    UNION-ALL         |          |       |       |            |          |
|   7 |     TABLE ACCESS FULL| FET$     |     1 |    52 |     3   (0)| 00:00:01 |
|   8 |     FIXED TABLE FULL | X$KTFBFE |   100 |  5200 |     0   (0)| 00:00:01 |
---------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("FET2"."FILE_ID"="FI"."RELFILE#" AND
"FET2"."TS#"="TS"."TS#")
2 - access("TS"."TS#"="FI"."TS#")
4 - filter("TS"."ONLINE$"=1 OR "TS"."ONLINE$"=4)
/*改写后可以大幅减少逻辑读从而提高性能*/
/*可以建立DBA_FREE_SPACE功能相同的替代品,并代入到表空间使用率的脚本中*/
CREATE OR REPLACE VIEW DBA_FREE_SPACE_NEW (
TABLESPACE_NAME,
FILE_ID,
BLOCK_ID,
BYTES,
BLOCKS,
RELATIVE_FNO
) AS
select /*+use_hash (tsfi, fet2 ) */
tsfi.tablespace_name,
tsfi.file_id,
fet2.block_id,
tsfi.blocksize * fet2.blocks,
fet2.blocks,
tsfi.relfile#
from (select /*+ use_hash ( ts, fi ) */
ts.name      tablespace_name,
fi.file#     file_id,
ts.BLOCKSIZE,
fi.relfile#,
ts.ts#
from sys.ts$ ts, sys.file$ fi
where ts.ts# = fi.ts#
and ts.online$ in (1, 4)) tsfi,
(select f.block# block_id, f.length blocks, f.file# file_id, f.ts#
from sys.fet$ f
union all
select f.ktfbfebno  block_id,
f.ktfbfeblks blocks,
f.ktfbfefno,
ktfbfetsn
from sys.x$ktfbfe f) fet2
where fet2.file_id = tsfi.relfile#
and fet2.ts# = tsfi.ts#  /*建此视图需SYSDBA权限*/ ;

ora-600 [17182]错误一例

这是一套古老的系统,SUNOS 5.8,Oracle 8.1.7.4。最近老革命途遇新问题,告警日志烽烟掠起:

Errors in file /u01/app/oracle/admin/CULPRODB/udump/culprodb_ora_7913.trc:
ORA-00600: internal error code, arguments: [17182], [32438472], [], [], [], [], [], []
Thu Jul 15 16:19:29 2010
Errors in file /u01/app/oracle/admin/CULPRODB/udump/culprodb_ora_7913.trc:
ORA-00600: internal error code, arguments: [17182], [32438472], [], [], [], [], [], []
Thu Jul 15 16:19:30 2010
Errors in file /u01/app/oracle/admin/CULPRODB/udump/culprodb_ora_7913.trc:
ORA-00600: internal error code, arguments: [17182], [32438472], [], [], [], [], [], []

如果你像我一样对600着迷,那么点击这里欣赏一下这个trace文件。报错期间运行的SQL及调用栈信息:

ksedmp: internal or fatal error
ORA-00600: internal error code, arguments: [17182], [32438472], [], [], [], [], [], []
Current SQL statement for this session:
select * from olsuser.cardmaster where cm_card_no between '2336330010201570013' and '2336330010201580004' union
select * from olsuser.cardmaster where cm_card_no between '2336330012402300018' and '2336330012402310009' union
select * from olsuser.cardmaster where cm_card_no between '2336330052400220016' and '2336330052400230007' union
select * from olsuser.cardmaster where cm_card_no between '2336330015103900012' and '2336330015138100032' union
select * from olsuser.cardmaster where cm_card_no between '2336330055100910018' and '2336330055100920009'
----- Call Stack Trace -----
calling                   call     entry
location                  type     point
--------------------      -------- --------------------
ksedmp()+220              CALL     ksedst()+0
kgeriv()+268              PTR_CALL 0000000000000000
kgesiv()+140              CALL     kgeriv()+0
kgesic1()+32              CALL     kgesiv()+0
kghfrf()+204              CALL     kgherror()+0
kkscls()+1592             CALL     kghfrf()+0
opicca()+248              CALL     kkscls()+0
opiclo()+8                CALL     opicca()+0
kpoclsa()+60              CALL     opiclo()+0
opiodr()+2540             PTR_CALL 0000000000000000
ttcpip()+5676             PTR_CALL 0000000000000000
opitsk()+2408             CALL     ttcpip()+0
opiino()+2080             CALL     opitsk()+0
opiodr()+2540             PTR_CALL 0000000000000000
opidrv()+1656             CALL     opiodr()+0
sou2o()+16                CALL     opidrv()+0
main()+172                CALL     sou2o()+0
_start()+380              CALL     main()+0
/*8.1.7中stack trace还附带着寄存器信息,但我们可读不懂:)  */

opicca->kkscls->kghfrf->kgherror(heap层报错)->kgesic1。问题主要发生在调用kghfrf函数的时候,《famous summary stack trace from Oracle Version 8.1.7.4.0 Bug Note》 一文罗列了Oracle的一些stack summary,其中kghfrx函数的作用是”Free extent. This is called when a heap is unpinned to request that it”;可以猜测kghfrf函数是用来释放某种内存结构的。在MOS上输入”kghfrf 8.1.7.4″关键词,可以找到Note 291936.1:

ORA-00600 [17182] on Oracle 8.1.7.4.0 After a CTRL-C or Client Termination
Applies to:
Oracle Server – Enterprise Edition – Version: 8.1.7.4
This problem can occur on any platform.
Checked for relevance on 06-Mar-2007

Oracle RDBMS Server Versions prior to 9i
Symptoms
1. Intermittent heap corruptions errors like ORA-00600 [17182] are reported in the alert.log file.

2. There is no impact to the database other than the process which encounters the errors getting killed.

3. From the trace file generated for this ORA-00600 error, check if the top few functions are :

kgherror kghfrf kkscls opicca

Cause
If the trace file shows that kkscls calls kghfrf, then it is related to:

Bug 2281320 — ORA-600[17182] POSSIBLE AFTER CTRL-C OR CLIENT DEATH
Solution
The problem is when we call kghfrf to free a chunk of memory, we expect that this chunk to have been allocated from the Heap Memory and hence have a valid header, although internally we have used Frame Memory managed chunk. As a result, kghfrf errors out with the “Bagic Magic Number” in the Memory Chunk header error message.

If you are running Oracle 8174, encounter this ORA-00600 [17182], and the call stack indicates the following functions { kgherror kghfrf kkscls }, then download and apply Patch 2281320 from MetaLink.

This issue has been fixed in Oracle Server 8.1.7.5 and later versions.

Note 2281320.8 is not limited to dblinks and can occur during normal database operation as well.

该文档叙述描述在9i以前版本中可能因堆损坏而出现该ORA-00600 [17182]错误,该错误不会导致致命问题或数据库损坏,最坏的情况是遭遇该错误的服务进程被杀死。与该问题匹配的主要依据是stack trace为kgherror kghfrf kkscls opicca,同我们的实际情况一致。可以通过打上one-off patch 2281320或者升级到8.1.7.5来避免该内部错误的发生,当然也可以置之不理,显然它不会造成太大的麻烦。
此外kghfrf函数用以释放内存chunk,Oracle development起初以为所有这些可能被释放的chunk都是从堆内存中分配而来,因此都该有一个有效的header;而实际上它们可能是以帧式内存管理的chunk。kghfrf因读取到这种chunk header中的错误幻数(Bagic Magic Number)而误入歧途了。

如何公开Oracle trace文件?

隐式参数_trace_files_public决定了Oracle产生的trace文件是否公开,该参数默认值为FALSE,也就是非DBA/OINSTALL组的用户是没有权限读取数据库产生的trace文件的;在某些场合中我们需要让非DBA组的用户也能访问trace文件,就可以通过修改该参数实现。请看下面的例子:

SQL> select * from v$version;
BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
PL/SQL Release 10.2.0.4.0 - Production
CORE    10.2.0.4.0      Production
TNS for Linux: Version 10.2.0.4.0 - Production
NLSRTL Version 10.2.0.4.0 - Production
SQL> col name for a20
SQL> col value for a20
SQL> col describ for a40
SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
3   WHERE x.inst_id = USERENV ('Instance')
4   AND y.inst_id = USERENV ('Instance')
5   AND x.indx = y.indx
6  AND x.ksppinm LIKE '%_trace_files_public%'
7  order by x.ksppinm;
NAME                 VALUE                DESCRIB
-------------------- -------------------- ----------------------------------------
_trace_files_public  FALSE                Create publicly accessible trace files
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug ipc;
Information written to trace file.
SQL> oradebug tracefile_name;
/s01/10gdb/admin/YOUYUS/udump/youyus_ora_10268.trc
SQL> !ls -l /s01/10gdb/admin/YOUYUS/udump/youyus_ora_10268.trc
-rw-r----- 1 maclean oinstall 4206 Aug 11 20:51 /s01/10gdb/admin/YOUYUS/udump/youyus_ora_10268.trc
/*所产生的trace文件权限为640,非oinstall组用户无权限读取该文件*/
SQL> alter system set "_trace_files_public"=true;
alter system set "_trace_files_public"=true
*
ERROR at line 1:
ORA-02095: specified initialization parameter cannot be modified
/*修改该参数需要重启实例*/
SQL> alter system set "_trace_files_public"=true scope=spfile;
System altered.
SQL> startup force;
ORACLE instance started.
Total System Global Area 1577058304 bytes
Fixed Size                  2084264 bytes
Variable Size             922747480 bytes
Database Buffers          637534208 bytes
Redo Buffers               14692352 bytes
Database mounted.
Database opened.
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug ipc;
Information written to trace file.
SQL> oradebug tracefile_name;
/s01/10gdb/admin/YOUYUS/udump/youyus_ora_10430.trc
SQL> ! ls -l /s01/10gdb/admin/YOUYUS/udump/youyus_ora_10430.trc
-rw-r--r-- 1 maclean oinstall 5471 Aug 11 20:54 /s01/10gdb/admin/YOUYUS/udump/youyus_ora_10430.trc
/*other组用户也具有了读权限*/
SQL> ! ls -l /s01/10gdb/admin/YOUYUS/
total 24
drwxr-x--- 2 maclean oinstall 4096 Aug 11 20:56 adump
drwxr-x--- 2 maclean oinstall 4096 Aug 11 20:54 bdump
drwxr-x--- 2 maclean oinstall 4096 Aug  5 21:35 cdump
drwxr-x--- 2 maclean oinstall 4096 Aug  5 21:36 dpdump
drwxr-x--- 2 maclean oinstall 4096 Aug  5 21:37 pfile
drwxr-x--- 2 maclean oinstall 4096 Aug 11 20:54 udump
/*请注意修改_trace_files_public为true,并不会修改trace所在目录的权限,Oracle默认建立bdump/udump等trace目录时分配的权限为750,other组用户无法进入这些目录,需要修改目录权限为755,即o+r+x*/
SQL> ! chmod o+r+x /s01/10gdb/admin/YOUYUS/*dump
SQL>  ! ls -l /s01/10gdb/admin/YOUYUS/
total 24
drwxr-xr-x 2 maclean oinstall 4096 Aug 11 20:56 adump
drwxr-xr-x 2 maclean oinstall 4096 Aug 11 20:54 bdump
drwxr-xr-x 2 maclean oinstall 4096 Aug  5 21:35 cdump
drwxr-xr-x 2 maclean oinstall 4096 Aug  5 21:36 dpdump
drwxr-x--- 2 maclean oinstall 4096 Aug  5 21:37 pfile
drwxr-xr-x 2 maclean oinstall 4096 Aug 11 20:54 udump
/*需要注意的另一点是修改_trace_files_public参数并不会引起既有的trace文件的权限被修改,典型的例子是alert log告警日志*/
[maclean@rh2 bdump]$ ls -l
total 20
-rw-r----- 1 maclean oinstall 12971 Aug 11 21:17 alert_YOUYUS.log
-rw-r--r-- 1 maclean oinstall   690 Aug 11 21:12 youyus_lgwr_10514.trc
SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
3   WHERE x.inst_id = USERENV ('Instance')
4   AND y.inst_id = USERENV ('Instance')
5   AND x.indx = y.indx
6  AND x.ksppinm LIKE '%_trace_files_public%'
7  order by x.ksppinm;
NAME                 VALUE                DESCRIB
-------------------- -------------------- ----------------------------------------
_trace_files_public  FALSE                Create publicly accessible trace files
SQL> alter system set "_trace_files_public"=true scope=spfile;
System altered.
SQL> startup force;
ORACLE instance started.
Total System Global Area 1577058304 bytes
Fixed Size                  2084264 bytes
Variable Size             922747480 bytes
Database Buffers          637534208 bytes
Redo Buffers               14692352 bytes
Database mounted.
Database opened.
SQL> !ls -l
total 32
-rw-r----- 1 maclean oinstall 21189 Aug 11 21:20 alert_YOUYUS.log
-rw-r--r-- 1 maclean oinstall   690 Aug 11 21:12 youyus_lgwr_10514.trc
-rw-r--r-- 1 maclean oinstall   690 Aug 11 21:20 youyus_lgwr_11136.trc

11g中AWR新快照视图

DBA_HIST_IOSTAT_DETAIL视图记录了不同类型和组件功能所作IO的统计数据。这个视图的数据来自于V$IOSTAT_FILE和V$IOSTAT_FUNCTION 2个动态视图的快照。值得一提的是V$IOSTAT_FILE,它是11g中新引入的动态性能视图:

SQL> select filetype_name, asynch_io, access_method, retries_on_error
2    from v$iostat_file;
FILETYPE_NAME                ASYNCH_IO ACCESS_METH RETRIES_ON_ERROR
---------------------------- --------- ----------- ----------------
Other                        ASYNC_OFF OS_LIB                     0
Control File                 ASYNC_OFF                            0
Log File                     ASYNC_OFF                            0
Archive Log                  ASYNC_OFF                            0
Data File Backup             ASYNC_OFF                            0
Data File Incremental Backup ASYNC_OFF                            0
Archive Log Backup           ASYNC_OFF                            0
Data File Copy               ASYNC_OFF                            0
Flashback Log                ASYNC_OFF                            0
Data Pump Dump File          ASYNC_OFF                            0
Data File                    ASYNC_ON  OS_LIB                     0
/*ASYNCH_IO列很好地标示了Oracle对于该类型文件是否启用了异步IO,这样我们就无需通过SYSTEM CALL TRACE来确定这一点了;
retries_on_error累计了物理读取的失败次数,对我们发现磁盘坏道有一定帮助。目前的11.2.0.1官方Reference没有ACCESS_METHOD列的资料,猜想可能分为OS_LIB和ASM及Exdata等多种情况,有待验证。

我们回过头来继续讨论DBA_HIST_IOSTAT_DETAIL视图!

SQL> desc dba_hist_iostat_detail;
Name                  Type         Nullable Default Comments
--------------------- ------------ -------- ------- --------
SNAP_ID               NUMBER
DBID                  NUMBER
INSTANCE_NUMBER       NUMBER
FUNCTION_ID           NUMBER
FUNCTION_NAME         VARCHAR2(30)
FILETYPE_ID           NUMBER
FILETYPE_NAME         VARCHAR2(30)
SMALL_READ_MEGABYTES  NUMBER
SMALL_WRITE_MEGABYTES NUMBER
LARGE_READ_MEGABYTES  NUMBER
LARGE_WRITE_MEGABYTES NUMBER
SMALL_READ_REQS       NUMBER
SMALL_WRITE_REQS      NUMBER
LARGE_READ_REQS       NUMBER
LARGE_WRITE_REQS      NUMBER
NUMBER_OF_WAITS       NUMBER
WAIT_TIME             NUMBER
SQL> col SMALL_READ_MEGABYTES for 999999;
SQL> col SMALL_WRITE_MEGABYTES for 999999;
SQL> col LARGE_READ_MEGABYTES for 999999;
SQL> col LARGE_WRITE_MEGABYTES for 999999;
SQL> col FILETYPE_NAME for a25;
SQL> select snap_id,
2         function_name,
3         filetype_name,
4         SMALL_READ_MEGABYTES,
5         SMALL_WRITE_MEGABYTES,
6         LARGE_READ_MEGABYTES,
7         LARGE_WRITE_MEGABYTES,
8         WAIT_TIME
9    from dba_hist_iostat_detail
10   where rownum < 16;
SNAP_ID FUNCTION_NAME                  FILETYPE_NAME             SMALL_ SMALL_ LARGE_ LARGE_  WAIT_TIME
---------- ------------------------------ ------------------------- ------ ------ ------ ------ ----------
1 DBWR                           Control File                   1      0      0      0        310
1 LGWR                           Control File                   0      0      0      0         94
1 Others                         Control File                 122     37      0      0      71635
2 DBWR                           Control File                   1      0      0      0        310
2 LGWR                           Control File                   0      0      0      0         94
2 Others                         Control File                 251     77      0      0     159025
3 Others                         Control File                  14      7      0      0      10339
4 Others                         Control File                  96     60      0      0      87516
5 Others                         Control File                 151     96      0      0     139796
6 DBWR                           Control File                   0      0      0      0         15
6 Others                         Control File                 210    135      0      0     189114
7 DBWR                           Control File                   0      0      0      0         15
7 Others                         Control File                 269    174      0      0     239640
8 DBWR                           Control File                   0      0      0      0         15
8 Others                         Control File                 328    213      0      0     288425
15 rows selected

其中SMALL_READ/WRITE代表单块读写,LARGE_READ/WRITE代表多块读写,wait_time的单位是千分之一秒(ms)。

SQL> select snap_id,
2         function_name,
3         filetype_name,
4         SMALL_READ_MEGABYTES,
5         SMALL_WRITE_MEGABYTES,
6         LARGE_READ_MEGABYTES,
7         LARGE_WRITE_MEGABYTES,
8         WAIT_TIME
9    from dba_hist_iostat_detail
10   where filetype_name = 'Control File'
11     and (LARGE_READ_REQS > 0 or LARGE_WRITE_REQS > 0);
未选定行
/*Oracle对控制文件只做单块读写*/
SQL> col FILETYPE_NAME for a15;
SQL> col function_name for a10;
SQL> select function_name,
2         filetype_name,
3         small_read_reqs,
4         small_write_reqs,
5         large_read_reqs,
6         large_write_reqs
7    from dba_hist_iostat_detail
8   where filetype_name = 'Log File'
9  and (SMALL_READ_REQS > 0 or LARGE_READ_REQS > 0);
FUNCTION_N FILETYPE_NAME   SMALL_READ_REQS SMALL_WRITE_REQS LARGE_READ_REQS LARGE_WRITE_REQS
---------- --------------- --------------- ---------------- --------------- ----------------
LGWR       Log File                      4             9140               0               86
LGWR       Log File                      4             2762               0              218
LGWR       Log File                      8             3512               0              222
LGWR       Log File                      8             4304               0              226
LGWR       Log File                      4             1996               0              210
LGWR       Log File                      8             5296               0              252
LGWR       Log File                      8             6016               0              254
LGWR       Log File                      8             7224               0              274
LGWR       Log File                      4            11536               0              232
LGWR       Log File                      8            13320               0              256
SQL> select snap_id,
2         function_name,
3         filetype_name,
4         SMALL_READ_MEGABYTES,
5         SMALL_WRITE_MEGABYTES,
6         LARGE_READ_MEGABYTES,
7         LARGE_WRITE_MEGABYTES,
8         WAIT_TIME
9    from dba_hist_iostat_detail
10   where filetype_name = 'Log File';
SNAP_ID FUNCTION_NAME                  FILETYPE_NAME             SMALL_ SMALL_ LARGE_ LARGE_  WAIT_TIME
---------- ------------------------------ ------------------------- ------ ------ ------ ------ ----------
2 LGWR                           Log File                       0     60      0     27         30
35 LGWR                           Log File                       0     23      0     48          0
6 LGWR                           Log File                       0     12      0      8          0
7 LGWR                           Log File                       0     15      0     10          0
8 LGWR                           Log File                       0     18      0     12          0
13 LGWR                           Log File                       0      5      0      4          0
15 LGWR                           Log File                       0      6      0      2          0
17 LGWR                           Log File                       0      4      0      3          0
19 LGWR                           Log File                       0     11      0      7          0
20 LGWR                           Log File                       0     14      0      8          0
37 LGWR                           Log File                       0     13      0     27          0
38 LGWR                           Log File                       0     15      0     29          0
41 LGWR                           Log File                       0     13      0    152         46
42 LGWR                           Log File                       0     16      0    153         61
43 LGWR                           Log File                       0     19      0    155         61
49 LGWR                           Log File                       0      2      0      0          0
3 LGWR                           Log File                       0      1      0      0          0
4 LGWR                           Log File                       0      7      0      4          0
5 LGWR                           Log File                       0      9      0      6          0
12 LGWR                           Log File                       0      1      0      0          0
/*日志文件在写出时会伴有少量的日志单块读操作,日志文件的写兼有单块写和多块写2种操作*/

另外,你大概和我一样不太喜欢使用OEM界面,不过OEM界面有个很方便的功能就是显示短期内的Avg Active Session Count(AAS)。什么?那你从来没看到过这种东西?下面这张截图大概可以勾起你的回忆:


早在10g时代就有人写了一个显示短期内AAS的脚本,在11g中该脚本得到了简化了:

set echo off;
set verify off;
alter session set nls_date_format='HH24:MI';
select *
from (select nvl(wait_class, 'CPU') activity,
trunc(sample_time, 'MI') time
from v$active_session_history) v pivot(count(*) for activity in('CPU' as
"CPU",
'Concurrency' as
"Concurrency",
'System I/O' as
"System I/O",
'User I/O' as
"User I/O",
'Administrative' as
"Administrative",
'Configuration' as
"Configuration",
'Application' as
"Application",
'Network' as
"Network",
'Commit' as
"Commit",
'Scheduler' as
"Scheduler",
'Cluster' as
"Cluster",
'Queueing' as
"Queueing",
'Other' as
"Other"))
where time > sysdate - interval '&last_min' minute
order by time;

我们也可以通过ASH查找Oracle中的TOP SESSION和TOP SQL:

/*找出短期内TOP SQL的sql_id和活动历史*/
select ash.SQL_ID,
sum(decode(ash.session_state, 'ON CPU', 1, 0)) "CPU",
sum(decode(ash.session_state, 'WAITING', 1, 0)) -
sum(decode(ash.session_state,
'WAITING',
decode(en.wait_class, 'User I/O', 1, 0),
0)) "WAIT",
sum(decode(ash.session_state,
'WAITING',
decode(en.wait_class, 'User I/O', 1, 0),
0)) "IO",
sum(decode(ash.session_state, 'ON CPU', 1, 1)) "TOTAL"
from v$active_session_history ash, v$event_name en
where SQL_ID is not NULL
and en.event# = ash.event#
group by sql_id
order by sum(decode(session_state, 'ON CPU', 1, 1)) desc;
SQL_ID               CPU       WAIT         IO      TOTAL
------------- ---------- ---------- ---------- ----------
a01hp0psv0rrh          0          2          7          9
24g90qj2b7ywk          0          5          1          6
2amsp6skc6tjv          0          0          5          5
46quk68k7akpa          0          3          1          4
2ufrf9vk4kcwj          0          0          3          3
1w8m6dwy66ttn          0          0          3          3
8uxr3scz9bmxd          0          0          3          3
6htq3p9j91y0s          0          0          3          3
cvn54b7yz0s8u          0          0          3          3
92f47aa2q2rmd          0          2          1          3
/*找出变量ivl指定分钟内的TOP CPU SESSION*/
Select session_id, count(*)
from v$active_session_history
where session_state = 'ON CPU'
and SAMPLE_TIME > sysdate -(&ivl/(24 * 60))
group by session_id
order by count(*) desc;
输入 ivl 的值:  10
原值    4:    and SAMPLE_TIME > sysdate -(&ivl/(24 * 60))
新值    4:    and SAMPLE_TIME > sysdate -(10/(24 * 60))
SESSION_ID   COUNT(*)
---------- ----------
136          4
/*找出变量ivl指定分钟内TOP WAITING SESSION*/
Select session_id, count(*)
from v$active_session_history
where session_state = 'WAITING'
and SAMPLE_TIME > SYSDATE - (&ivl / (24 * 60))
group by session_id
order by count(*) desc;
输入 ivl 的值:  10
原值    4:    and SAMPLE_TIME > SYSDATE - (&ivl / (24 * 60))
新值    4:    and SAMPLE_TIME > SYSDATE - (10 / (24 * 60))
SESSION_ID   COUNT(*)
---------- ----------
3         11
/*找出短期内的TOP SESSION及活动历史*/
select ash.session_id,
ash.session_serial#,
ash.user_id,
ash.program,
sum(decode(ash.session_state, 'ON CPU', 1, 0)) "CPU",
sum(decode(ash.session_state, 'WAITING', 1, 0)) -
sum(decode(ash.session_state,
'WAITING',
decode(en.wait_class, 'User I/O', 1, 0),
0)) "WAITING",
sum(decode(ash.session_state,
'WAITING',
decode(en.wait_class, 'User I/O', 1, 0),
0)) "IO",
sum(decode(session_state, 'ON CPU', 1, 1)) "TOTAL"
from v$active_session_history ash, v$event_name en
where en.event# = ash.event#
group by session_id, user_id, session_serial#, program
order by sum(decode(session_state, 'ON CPU', 1, 1));

以上脚本完全可以被ashrpt报表所替代,但在短期内做针对检查仍十分有效。

UNION ALL returning wrong results?

有应用人员反映某套Linux上的11.2.0.1数据库系统中出现了UNION ALL后返回的结果集不正确的问题,我们具体分析下出现问题的其中一条语句:

SELECT MTL_SECONDARY_INVENTORIES.SECONDARY_INVENTORY_NAME,
MTL_SECONDARY_INVENTORIES.ORGANIZATION_ID,
MTL_SECONDARY_INVENTORIES.DESCRIPTION,
MTL_SECONDARY_INVENTORIES.AVAILABILITY_TYPE,
MTL_SECONDARY_INVENTORIES.MATERIAL_ACCOUNT,
MTL_SECONDARY_INVENTORIES.MATERIAL_OVERHEAD_ACCOUNT,
MTL_SECONDARY_INVENTORIES.RESOURCE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.OVERHEAD_ACCOUNT,
MTL_SECONDARY_INVENTORIES.OUTSIDE_PROCESSING_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ASSET_INVENTORY,
MTL_SECONDARY_INVENTORIES.EXPENSE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ENCUMBRANCE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ATTRIBUTE3,
MTL_SECONDARY_INVENTORIES.ATTRIBUTE5,
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
FROM REPEMEAERP.MTL_SECONDARY_INVENTORIES,
REPEMEAERP.WORKFLOW_START_TIMES
WHERE MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT >
TO_DATE('01/01/1900 00:00:00', 'MM/DD/YYYY HH24:MI:SS')
AND MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT <=
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
AND WORKFLOW_START_TIMES.WORKFLOW_NAME =
LTRIM(RTRIM('w_int_FreqBatch_EMEA'))
/*以上是QUERY A*/
UNION ALL
/*以下是QUERY B*/
SELECT DISTINCT 'WORKORDERS',
MTL_SECONDARY_INVENTORIES.ORGANIZATION_ID,
'WORK ORDERS WITH WIP AS CATEGORY VALUE',
1,
0,
0,
0,
0,
0,
1,
0,
0,
'MOI',
'0',
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
FROM REPEMEAERP.MTL_SECONDARY_INVENTORIES, EIMMAINT.WORKFLOW_START_TIMES
WHERE MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT >
TO_DATE('01/01/1900 00:00:00', 'MM/DD/YYYY HH24:MI:SS')
AND MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT <=
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
AND WORKFLOW_START_TIMES.WORKFLOW_NAME =
LTRIM(RTRIM('w_int_FreqBatch_EMEA'))
/
138 rows selected.

以上查询语句中,QUERY A部分(也就是UNION ALL之前的SELECT语句)单独查询时返回返回69条记录,QUERY B部分单独查询时返回15记录,UNION ALL后返回的结果却是138条记录,而非84条记录。实际上这套系统也是最近才从10g迁移到11gr2上,之前在10g中同样的应用没有出过类似的问题,可以猜测是11g中新引入的某种特性存在可能引发wrong result的Bug。

具体思路虽然有了,但仍无法确定问题的关键所在;我们来看看该SQL的执行计划:

-----------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                          | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                               |     7 |  2443 |    52   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                   |                               |     7 |  2443 |    52   (0)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL             | WORKFLOW_START_TIMES          |     1 |    29 |    48   (0)| 00:00:01 |
|   3 |   VIEW                          | VW_JF_SET$9BAED2EA            |     1 |   320 |     4   (0)| 00:00:01 |
|   4 |    UNION ALL PUSHED PREDICATE   |                               |       |       |            |          |
|*  5 |     FILTER                      |                               |       |       |            |          |
|   6 |      TABLE ACCESS BY INDEX ROWID| MTL_SECONDARY_INVENTORIES     |     3 |   336 |     2   (0)| 00:00:01 |
|*  7 |       INDEX RANGE SCAN          | IDX_MTL_SECONDARY_INVENTORIES |     1 |       |     1   (0)| 00:00:01 |
|*  8 |     FILTER                      |                               |       |       |            |          |
|   9 |      TABLE ACCESS BY INDEX ROWID| MTL_SECONDARY_INVENTORIES     |     3 |    36 |     2   (0)| 00:00:01 |
|* 10 |       INDEX RANGE SCAN          | IDX_MTL_SECONDARY_INVENTORIES |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("WORKFLOW_START_TIMES"."WORKFLOW_NAME"='w_int_FreqBatch_EMEA')
5 - filter(TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd
hh24:mi:ss')<"WORKFLOW_START_TIMES"."WORKFLOW_START_TIME") 7 - access("MTL_SECONDARY_INVENTORIES"."DW_UPDATE_DT">TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd
hh24:mi:ss') AND "MTL_SECONDARY_INVENTORIES"."DW_UPDATE_DT"<="WORKFLOW_START_TIMES"."WORKFLOW_START_TIME"
)
8 - filter(TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd
hh24:mi:ss')<"WORKFLOW_START_TIMES"."WORKFLOW_START_TIME") 10 - access("MTL_SECONDARY_INVENTORIES"."DW_UPDATE_DT">TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd
hh24:mi:ss') AND "MTL_SECONDARY_INVENTORIES"."DW_UPDATE_DT"<="WORKFLOW_START_TIMES"."WORKFLOW_START_TIME"
)

你可能从以上执行计划中发现了两处十分陌生的字眼:UNION ALL  PUSHED PREDICATE和VW_JF_SET$。它们是什么!?

先来说说JF,JF是join factorization的缩写,你可以把它翻译作链接因式分解,如果你学过离散数学或者数据库原理的话,那么这种在11.2.0.1中最新推出的基于成本的变换操作对你来说并不陌生。用公式的样式来表达大概是下面这样:

YYA,YYB和YYC是3个关联的数据对象亦或者是3个关联的结果集;
(YYA JOIN YYB) UNION [ALL] (YYA JOIN YYC)
可以转换成为:
YYA JOIN (YYB UNION [ALL] YYC)

这样做YYA部分只需要读取一次,还可以少做一次JOIN,听上去是挺不错的吧!
下面我们来看一个Oracle使用join factorization的十分简单的实例:

SQL> select * from v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
PL/SQL Release 11.2.0.1.0 - Production
CORE    11.2.0.1.0      Production
TNS for Linux: Version 11.2.0.1.0 - Production
NLSRTL Version 11.2.0.1.0 - Production
SQL> drop table yya;
drop table yya
*
ERROR at line 1:
ORA-00942: table or view does not exist
SQL> drop table yyb;
drop table yyb
*
ERROR at line 1:
ORA-00942: table or view does not exist
SQL> create table yya as select rownum id1,rownum id2,rownum id3 from dual connect by level<=20000;
Table created.
SQL> create table yyb as select rownum id1,rownum id2,rownum id3 from dual connect by level<=20000;
Table created.
SQL> explain plan for
2  select * from yya ,yyb where yya.id1=yyb.id1
3  union all
4  select * from yya, yyb where yya.id1=yyb.id1;
Explained.
SQL> set linesize 100 pagesize 1400;
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 744914999
-------------------------------------------------------------------------------------------
| Id  | Operation            | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                    | 40000 |  2500K|    49   (3)| 00:00:01 |
|*  1 |  HASH JOIN           |                    | 40000 |  2500K|    49   (3)| 00:00:01 |
|   2 |   TABLE ACCESS FULL  | YYA                | 20000 |   234K|    16   (0)| 00:00:01 |
|   3 |   VIEW               | VW_JF_SET$6E3F6682 | 40000 |  2031K|    32   (0)| 00:00:01 |
|   4 |    UNION-ALL         |                    |       |       |            |          |
|   5 |     TABLE ACCESS FULL| YYB                | 20000 |   761K|    16   (0)| 00:00:01 |
|   6 |     TABLE ACCESS FULL| YYB                | 20000 |   761K|    16   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("YYA"."ID1"="ITEM_1")
/*执行计划中出现了VW_JF_SET$F22B2A93,Oracle选择了使用join factorization,该执行计划总成本49*/
SQL> alter session set "_optimizer_join_factorization"=false;
Session altered.
/*隐藏参数_optimizer_join_factorization决定了优化器是否可以选用join factorization,现在我们禁用它*/
SQL> explain plan for
2  select * from yya join yyb on yya.id1=yyb.id1
3  union all
4  select * from yya join yyb on yya.id1=yyb.id1;
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 3439541885
----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      | 40000 |  1992K|    66  (52)| 00:00:01 |
|   1 |  UNION-ALL          |      |       |       |            |          |
|*  2 |   HASH JOIN         |      | 20000 |   996K|    33   (4)| 00:00:01 |
|   3 |    TABLE ACCESS FULL| YYA  | 20000 |   234K|    16   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| YYB  | 20000 |   761K|    16   (0)| 00:00:01 |
|*  5 |   HASH JOIN         |      | 20000 |   996K|    33   (4)| 00:00:01 |
|   6 |    TABLE ACCESS FULL| YYA  | 20000 |   234K|    16   (0)| 00:00:01 |
|   7 |    TABLE ACCESS FULL| YYB  | 20000 |   761K|    16   (0)| 00:00:01 |
----------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("YYA"."ID1"="YYB"."ID1")
5 - access("YYA"."ID1"="YYB"."ID1")
/*禁用链接因式分解后,Oracle使用了常规的"笨办法",成本上升到66*/
/*有趣的是下面的测试*/
SQL> alter session set "_optimizer_join_factorization"=true;
Session altered.
SQL> create table yyc as select * from yyb;
Table created.
SQL> explain plan for
2  select * from yya,yyc where yya.id1=yyc.id1
3  union all
4  select * from yya,yyb where yya.id1=yyb.id1;
Explained.
SQL>  select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 4240055274
----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      | 40000 |  1992K|    66  (52)| 00:00:01 |
|   1 |  UNION-ALL          |      |       |       |            |          |
|*  2 |   HASH JOIN         |      | 20000 |   996K|    33   (4)| 00:00:01 |
|   3 |    TABLE ACCESS FULL| YYA  | 20000 |   234K|    16   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| YYC  | 20000 |   761K|    16   (0)| 00:00:01 |
|*  5 |   HASH JOIN         |      | 20000 |   996K|    33   (4)| 00:00:01 |
|   6 |    TABLE ACCESS FULL| YYA  | 20000 |   234K|    16   (0)| 00:00:01 |
|   7 |    TABLE ACCESS FULL| YYB  | 20000 |   761K|    16   (0)| 00:00:01 |
----------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("YYA"."ID1"="YYC"."ID1")
5 - access("YYA"."ID1"="YYB"."ID1")
/*confused,Oracle有什么理由在这里反而不用join factorization了呢?看起来短期内join factorization的实际应用还有待"商榷"
*/
/*10053事件能解释这一问题吗?*/
SQL> alter system flush shared_pool;
System altered.
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug event 10053 trace name context forever,level 1;
Statement processed.
SQL> explain plan for
2  select * from yya join yyb on yya.id1=yyb.id1
3  union all
4  select * from yya join yyc on yya.id1=yyc.id1;
Explained.
SQL> oradebug event 10053 trace name context off;
Statement processed.
SQL> oradebug tracefile_name;
/home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_7907.trc
view /home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_7907.trc
***********************************
Cost-Based Join Factorization
***********************************
Join-Factorization on query block SET$1 (#1)
JF: Using search type: exhaustive
JF: Generate basic transformation units
Validating JF unit: (branch: {2, 3} table: {YYA, YYA})
rejected: join predicates do not match
JF: Generate transformation units from basic units
JF: No state generated.
/*优化器认为其链接谓词不符合使用join  factorization的条件,JF题案被驳回,"悬案"!*/

join factorization是很棒的新技术,这点没错,但新技术往往又是horrible(可怕的),最近我常用这个词。我们的问题是不是这个新来的引起的呢?通过join factorization关键字检索MOS,可以发现一个今年(2010)3月出现的Bug 9504322,quote:

Hdr: 9504322 11.2.0.1 RDBMS 11.2.0.1 QRY OPTIMIZER PRODID-5 PORTID-226
Abstract: WRONG RESULTS WITH UNION_ALL AND INLINE VIEWS

*** 03/24/10 05:38 am ***

PROBLEM:
--------
Wrong results on 11.2 for queries of type:

SELECT * FROM
(
SELECT ... FROM view, table WHERE ...
UNION ALL
SELECT ... FROM view, table WHERE NOT ...
);

DIAGNOSTIC ANALYSIS:
--------------------
Problem seen between 10.2.0.4 and 11.2.0.1.
If we remove the use of inline view the correct results are returned.

WORKAROUND:
-----------
N/A

RELATED BUGS:
-------------

REPRODUCIBILITY:
----------------
It is reproducing on generic 11.2.0.1

呵呵,似乎有点眉目了,不过实践是检验真理的唯一标准:

SQL> alter session set "_optimizer_join_factorization"=true;
Session altered.
SELECT MTL_SECONDARY_INVENTORIES.SECONDARY_INVENTORY_NAME,
MTL_SECONDARY_INVENTORIES.ORGANIZATION_ID,
MTL_SECONDARY_INVENTORIES.DESCRIPTION,
MTL_SECONDARY_INVENTORIES.AVAILABILITY_TYPE,
MTL_SECONDARY_INVENTORIES.MATERIAL_ACCOUNT,
MTL_SECONDARY_INVENTORIES.MATERIAL_OVERHEAD_ACCOUNT,
MTL_SECONDARY_INVENTORIES.RESOURCE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.OVERHEAD_ACCOUNT,
MTL_SECONDARY_INVENTORIES.OUTSIDE_PROCESSING_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ASSET_INVENTORY,
MTL_SECONDARY_INVENTORIES.EXPENSE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ENCUMBRANCE_ACCOUNT,
MTL_SECONDARY_INVENTORIES.ATTRIBUTE3,
MTL_SECONDARY_INVENTORIES.ATTRIBUTE5,
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
FROM REPEMEAERP.MTL_SECONDARY_INVENTORIES,
REPEMEAERP.WORKFLOW_START_TIMES
WHERE MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT >
TO_DATE('01/01/1900 00:00:00', 'MM/DD/YYYY HH24:MI:SS')
AND MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT <=
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
AND WORKFLOW_START_TIMES.WORKFLOW_NAME =
LTRIM(RTRIM('w_int_FreqBatch_EMEA'))
/*以上是QUERY A*/
UNION ALL
/*以下是QUERY B*/
SELECT DISTINCT 'WORKORDERS',
MTL_SECONDARY_INVENTORIES.ORGANIZATION_ID,
'WORK ORDERS WITH WIP AS CATEGORY VALUE',
1,
0,
0,
0,
0,
0,
1,
0,
0,
'MOI',
'0',
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
FROM REPEMEAERP.MTL_SECONDARY_INVENTORIES, EIMMAINT.WORKFLOW_START_TIMES
WHERE MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT >
TO_DATE('01/01/1900 00:00:00', 'MM/DD/YYYY HH24:MI:SS')
AND MTL_SECONDARY_INVENTORIES.DW_UPDATE_DT <=
WORKFLOW_START_TIMES.WORKFLOW_START_TIME
AND WORKFLOW_START_TIMES.WORKFLOW_NAME =
LTRIM(RTRIM('w_int_FreqBatch_EMEA'))
/
138 rows selected.

结果和我们猜想的大相径庭,join factorization并非罪魁,找不到终点让我们回到原点。
至此UNION ALL PUSHED PREDICATE有了极大的嫌疑,什么是PUSH PREDICATE?我把它叫做谓词前推,这玩样最早出现在10g上,但一直问题多多!它到底是何种OPERATION呢?让我们来看看下面的例子:

SQL> select * from v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
PL/SQL Release 11.2.0.1.0 - Production
CORE    11.2.0.1.0      Production
TNS for Linux: Version 11.2.0.1.0 - Production
NLSRTL Version 11.2.0.1.0 - Production
SQL> create table youyus (t1 int,t2 varchar2(20));
Table created.
SQL> alter table youyus add primary key(t1);
Table altered.
SQL> explain plan for
2  select *
3    from youyus
4  union all
5  select * from youyus;
Explained.
/*在之后的语句中将用到这个子查询*/
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 1959159425
-----------------------------------------------------------------------------
| Id  | Operation          | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |     2 |    50 |     4  (50)| 00:00:01 |
|   1 |  UNION-ALL         |        |       |       |            |          |
|   2 |   TABLE ACCESS FULL| YOUYUS |     1 |    25 |     2   (0)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| YOUYUS |     1 |    25 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------
/*在之后的语句中将用到这个子查询,这里它的"原始"执行计划十分简单*/
SQL> explain plan for
2  select v2.t1, v2.t2
3    from (select t1 from youyus where rownum=1) v1,
4         (select *
5            from youyus
6          union all
7          select * from youyus) v2
8   where v1.t1 = v2.t1;
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 2456530141
-----------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |     1 |    27 |     1   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                  |              |     1 |    27 |     1   (0)| 00:00:01 |
|   2 |   VIEW                         |              |     1 |    13 |     1   (0)| 00:00:01 |
|*  3 |    COUNT STOPKEY               |              |       |       |            |          |
|   4 |     INDEX FULL SCAN            | SYS_C0010819 |     1 |    13 |     1   (0)| 00:00:01 |
|   5 |   VIEW                         |              |     1 |    14 |     0   (0)| 00:00:01 |
|   6 |    UNION ALL PUSHED PREDICATE  |              |       |       |            |          |
|   7 |     TABLE ACCESS BY INDEX ROWID| YOUYUS       |     1 |    25 |     0   (0)| 00:00:01 |
|*  8 |      INDEX UNIQUE SCAN         | SYS_C0010819 |     1 |       |     0   (0)| 00:00:01 |
|   9 |     TABLE ACCESS BY INDEX ROWID| YOUYUS       |     1 |    25 |     0   (0)| 00:00:01 |
|* 10 |      INDEX UNIQUE SCAN         | SYS_C0010819 |     1 |       |     0   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - filter(ROWNUM=1)
8 - access("YOUYUS"."T1"="V1"."T1")
10 - access("YOUYUS"."T1"="V1"."T1")
/* PUSHED PREDICATE将谓词逻辑前推到UNION ALL的子查询中,其优势在于可以避免全表扫描,利用索引*/
SQL> set linesize 100 pagesize 1400;
SQL>
SQL> explain plan for
2  select /*+ no_push_pred(v2) */ v2.t1, v2.t2
3    from (select t1 from youyus where rownum=1) v1,
4         (select *
5            from youyus
6          union all
7          select * from youyus) v2
8   where v1.t1 = v2.t1;
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 2769827061
-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |     1 |    38 |     6  (17)| 00:00:01 |
|*  1 |  HASH JOIN           |              |     1 |    38 |     6  (17)| 00:00:01 |
|   2 |   VIEW               |              |     1 |    13 |     1   (0)| 00:00:01 |
|*  3 |    COUNT STOPKEY     |              |       |       |            |          |
|   4 |     INDEX FULL SCAN  | SYS_C0010819 |     1 |    13 |     1   (0)| 00:00:01 |
|   5 |   VIEW               |              |     2 |    50 |     4   (0)| 00:00:01 |
|   6 |    UNION-ALL         |              |       |       |            |          |
|   7 |     TABLE ACCESS FULL| YOUYUS       |     1 |    25 |     2   (0)| 00:00:01 |
|   8 |     TABLE ACCESS FULL| YOUYUS       |     1 |    25 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("V1"."T1"="V2"."T1")
3 - filter(ROWNUM=1)
/*no_push_pred hint让Oracle 放弃使用PUSHED PREDICATE,使用常规UNION-ALL操作后,子查询执行计划回归成全表扫描,整个计划成本上升*/

沪ICP备14014813号

沪公网安备 31010802001379号