Monday, August 31, 2009

Cursor Pin競合と関連して必ず見るべきのMetalinkノート

Oracle10gからcursor: pin ... のような名前の待機イベントがよく見つかります。Mutexが同期化客体で使用されながら現れた現状なのに、このMutexの問題はHolderを観察するのがむずかしいと言うことです。残念ながらMaxgaugeのようなモニタリングツールもMutexのHolderは提供しません。


しかし、下のMetalinkノートを呼んでみますと以外に易しくMutexのHolderを見付けられるということが分かります。



ノートID: 786507.1
題目: HOW TO FIND BLOCKING SESSION FOR MUTEX WAIT EVENT cursor: pin S wait on X

Metalink使用権限がない方たちのために簡略にスクリプトだけ紹介すれば次のようです(ノートの内容全体をCopy&Pasteするのは不法です)。


-- 64ビットシステムでは8の位、32ビットシステムでは4の位を取る
SELECT p2raw
,to_number(substr(to_char(rawtohex(p2raw)), 1, 8), 'XXXXXXXX') sid
FROM v$session
WHERE event = 'cursor: pin S wait on X';

P2RAW SID
---------------- ---
0000001F00000000 31


31は始めの8位0000001F値の10進数の値です。すなわち現在のHolderが31番のセッションという意味です。Maxgaugeのようにアクティブセッションのリストと待機イベントのリストを貯蔵しているモニタリングツールではHolderセッションを上のように手軽に見付けることができますね。


もちろんAWRでも同一に使用できます。


11gからはV$SESSION.BLOCKING_SESSIONにHolder情報が記録されます。ずいぶんよくなりました。


でも、本当の問題はHolderセッションを見付けた後からですよ。:)

Wednesday, August 26, 2009

Index Prefetch? db file parallel read? db file scattered read?

(このポストは多少専門的な内容を含んでいるので、関心ある方だけ読んでみてください)


Index Prefetchは少しは混乱な機能です。下の情報を読んでみれば私のいうことを理解できるでしょう。


一般的な意見は次のようです。

  1. Index Prefetchが発生すればIndex Range ScanとTable Lookup By ROWIDに対してNon-Contignous Multiblock Readを行います. すなわち, 隣接しないブロックたちをParallelに一度に読みます。
  2. この際db file parallel readという待機イベントが発生します。
  3. 一度に読み込める最大のブロックの数は_db_file_noncontig_mblock_read_count(基本値は11)によって決まります。
    Index PrefetchはOracle(CBO)が全的に決めるし、実行計画が同一してもIndex Prefetchが選択されるかどうかは確信できません。

でも、時々Index Range ScanとTable Lookup By ROWIDに対してdb file scattered readイベントを待機するばあいが報告されています。私も以前にこの現状を始めて見つけてずいぶん驚いた覚えがあります。なぜdb file parallel readでもなくdb file scattered readなのか。これはIndex Prefetchなのか、それとも全然違うPrefetch方法なのか。


この問題に対してはまだ明確な説明が存在しないと思います。


それでテストデータベースでIndex Prefetchを直接再現してみました。


まず次のようにClutering FactorがよくないIndexを作ります。Clustering Factorが不良ならばSingle Block I/Oの性能が遅くなるからOracleがMulti Block I/Oを選択する確率が高くなるからです。


UKJA@ukja1106> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
PL/SQL Release 11.1.0.6.0 - Production
CORE 11.1.0.6.0 Production
TNS for 32-bit Windows: Version 11.1.0.6.0 - Production
NLSRTL Version 11.1.0.6.0 - Production

Elapsed: 00:00:00.00

UKJA@ukja1106> create table t1(c1 int, c2 int);

Table created.

Elapsed: 00:00:00.14
UKJA@ukja1106> insert into t1
2 select level, 1 from dual connect by level <= 100000
3 order by dbms_random.random;

100000 rows created.

Elapsed: 00:00:01.82
UKJA@ukja1106> create index t1_n1 on t1(c1);

Index created.

Elapsed: 00:00:00.28
UKJA@ukja1106>
UKJA@ukja1106> @gather t1
UKJA@ukja1106> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.20

Index Prefetchが選択される確率を極端的に高めます。

UKJA@ukja1106> alter session set "_index_prefetch_factor" = 1;

Session altered.

Elapsed: 00:00:00.00
UKJA@ukja1106> alter session set db_file_multiblock_read_count = 128;

Session altered.

Elapsed: 00:00:00.00

Buffer CacheをFlushしてからIndex Range ScanとTable Lookup By ROWIDを選択するようにヒントを与えてQueryを遂行します。
 
UKJA@ukja1106> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.37
UKJA@ukja1106> select /*+ index(t1) */ count(*)
2 from t1 where c1 between 1 and 1000 and c2 = 1;

COUNT(*)
----------
1000

Elapsed: 00:00:00.03

SQL*Traceの結果はdb file parallel readイベントを報告します。

select /*+ index(t1) */ count(*)
from t1 where c1 between 1 and 1000 and c2 = 1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.03 0.11 182 998 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.04 0.13 182 998 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 88

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=998 pr=182 pw=182 time=0 us)
1000 TABLE ACCESS BY INDEX ROWID T1 (cr=998 pr=182 pw=182 time=8601 us cost=999 size=7000 card=1000)
1000 INDEX RANGE SCAN T1_N1 (cr=4 pr=4 pw=4 time=21 us cost=4 size=0 card=1000)(object id 72154)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file sequential read 12 0.01 0.02
db file parallel read 15 0.03 0.08
SQL*Net message from client 2 0.00 0.00
********************************************************************************

原本のTraceファイルの待機イベントに対してもっと詳しい分析をしてみます。

UKJA@ukja1106> @trace_file_short
TRACE_FILE_NAME
--------------------------------------------------------------------------------
ukja1106_ora_31724.trc

Elapsed: 00:00:00.01
ukja1106_ora_31724.trc
UKJA@ukja1106> @wait_analyze &trace_file % 'db file parallel read' nam,files,blocks
NAM FILES BLOCKS COUNT(*)
------------------------------ ---------- ---------- ----------
'db file parallel read' 1 15 1
'db file parallel read' 1 2 3
'db file parallel read' 1 37 1
'db file parallel read' 1 3 1
'db file parallel read' 1 4 2
'db file parallel read' 1 27 1
'db file parallel read' 1 11 1
'db file parallel read' 1 7 3
'db file parallel read' 1 30 1
'db file parallel read' 1 12 1

10 rows selected.

Elapsed: 00:00:00.25

Multi Block Readのブロック数が11ではなく3から37まで広範囲に分布しているのが分かります。文書化されたのとは違う現状ですよ。


Multi Block I/OがどんなObjectで発生しているのかを見ればIndexではないTableに対してだけ発生しているのが分かります。


UKJA@ukja1106> col obj new_value obj_no
UKJA@ukja1106> @wait_analyze &trace_file % 'db file parallel read' nam,obj
NAM OBJ COUNT(*)
------------------------------ ---------- ----------
'db file parallel read' 72153 15

Elapsed: 00:00:00.09
UKJA@ukja1106> @obj &obj_no
UKJA@ukja1106> exec print_table('select * from all_objects where object_id = &1');
OWNER : UKJA
OBJECT_NAME : T1
SUBOBJECT_NAME :
OBJECT_ID : 72153
DATA_OBJECT_ID : 72153
OBJECT_TYPE : TABLE
CREATED : 2009/08/26 18:02:30
LAST_DDL_TIME : 2009/08/26 18:02:32
TIMESTAMP : 2009-08-26:18:02:30
STATUS : VALID
TEMPORARY : N
GENERATED : N
SECONDARY : N
NAMESPACE : 1
EDITION_NAME :
-----------------

やっぱり文書化されたのとは違う現状です。多分Oracleが判断するにのにIndexはSingle Block I/Oで読み込むのが効果的だけど、Tableへ行く過程は重いので(Clustering Factorがよくないから)Multi Block I/Oが効果的だと判断しているみたいです。あくまでも推測です。もちろんこんなOracleの判断がいつも性能に効果的なのではありません。やや大きい性能低下が発生する可能性もあります。


やっぱり解かない疑問は”それではOracleは何時db file parallel readイベントではなくdb file scattered readイベントを報告するのか”すなわち”何時Non-Contiguous Multi Block I/OではなくContiguous Multi Block I/Oをするのか”です。まだは分かりません.:)

Footnote:wait_analyze.sqlファイルはここにあります。

Tuesday, August 25, 2009

Preliminary ConnectionとOradebug Direct Access

Oracle10gでPreliminary Connectionという機能を使ったことがあるでしょう。Preliminary Connectionというのはインスタンスに接続しないで、Direct Memory Accessで作業を行うのを指します。


この意味からこの機能をSessionless Sessionと言う場合もあります。


Oracleが完全にHang状態に落ちいて正常的なSessionを作ることができない時、System State DumpやHang AnalyzeなどのデータをDBAが収集できるようにする機能だと見れば正確です。

(もちろんMaxgaugeのようなDirect Memory Access基盤の製品を使ってもいいですね。)


次のような方法でSQL*Plusを実行すればPreliminary Connection状態になります。


set oracle_sid=ukja1106

sqlplus -prelim sys/oracle as sysdba

-- または

sqlplus /nolog
@> set _prelim on
@> conn sys/oracle as sysdba

この状態では一般的なQueryは実行されません。

SYS@ukja1106> select * from dual;
select * from dual
*
ERROR at line 1:
ORA-01012: not logged on
Process ID: 0
Session ID: 0 Serial number: 0

次のようにSystem State DumpやHang Analyzeは成功的に実行されます。

SYS@ukja1106> oradebug setmypid
Statement processed.
SYS@ukja1106> oradebug dump systemstate 266
Statement processed.
SYS@ukja1106> oradebug dump hanganalyze 10
Statement processed.

ただし、SGA Heap DumpのようなOperationは不可能なようです。すべてのVersionで確認したことではありません。

SYS@ukja1106> oradebug dump heapdump 0x20000002
ORA-00600: internal error code, arguments: [ksfglt:no_proc], [], [], [], [], [],
[], []

Oracle11gではoradebugにdirect accessという機能が追加されました。Direct Memory AccessでFixed Table(X$ Table)を読む機能です。この機能はPreliminary Connectionまたは一般Connectionで使えます。

例えは、次のようにSessionデータを読みます。

SYS@ukja1106> oradebug direct_access select * from x$ksuse;
ORA-15655: Fixed table "X$KSUSE" cannot be accessed safely in prelim connection.

エラーです。この場合には次のようにUnsafeモードを指定します。

SYS@ukja1106> oradebug direct_access set mode=unsafe
Statement processed.

....
ADDR = 2F0D0850
INDX = 170
INST_ID = 1
KSSPAFLG = 1
KSSPAOWN = 2FA92228
KSSPATYP = 1
KSUUDSES = 0
KSUUDUID = 0
KSUUDNAM = SYS
KSUUDLUI = 0
KSUUDLNA =
KSUUDPRV = 0
KSUUDOCT = 0
KSUUDFLG = 0
KSUUDPFN = 0
KSUUDSID = 0
KSUUDSNA = SYS
KSUUDSAE = 0
KSQPSWAT = 0
KSQPSRES = 0
KSQPSRESLAT = 0
KSUSEPRO = 2FA92228
KSUSETRN = 0
KSUSEBRN = 0
KSUSENUM = 170
KSUSESER = 14
KSUSEFLG = 81
KSUSEIDL = 1
KSUSESOW = 2147483644
KSUSEPID = 2064
KSUSEUNM = SYSTEM
KSUSEMNM = XXXX-3C2E2AF808
KSUSEPNM = ORACLE.EXE (CJQ0)
KSUSETID = XXXX-3C2E2AF808
KSUSESQL = 0
KSUSESQH = 0
KSUSESQI =
KSUSESCH = 0
KSUSESPH = 0
KSUSEPSI =
KSUSEPSQ = 0
KSUSEPHA = 0
KSUSEPCH = 0
KSUSEPPH = 0
KSUSEPEO = 0
KSUSEPES = 0
KSUSEPCO = 0
KSUSEPCS = 0
KSUSEOBJ = 5653
KSUSEFIL = 1
KSUSEBLK = 11378
KSUSESLT = 0
KSUSEFIX = 2362004
KSUSEAPP =
KSUSEAPH = 0
KSUSEACT =
KSUSEACH = 0
KSUSECLI =
KSUSECTM = 528627
KSUSELTM = 19-AUG-09 02.04.55 PM
KSUSEFT = 0
KSUSEFM = 0
KSUSEFS = 0
KSUSEQCSID = 0
KSUSEGRP =
KSUSEPFL = 0
KSUSEPXOPT = 17
KSUSETMC = 0
KSUSECQD = 0
KSUSEPGAMAN = 0
KSUSEPGAAUTO = 0
KSUSECLID =
KSUSEBLOCKER = 4294967292
KSUSESEQ = 12717
KSUSEOPC = 6
KSUSEP1 = 500
KSUSEP1R = 00000000000001F4
KSUSEP2 = 0
KSUSEP2R = 0000000000000000
KSUSEP3 = 0
KSUSEP3R = 0000000000000000
KSUSETIM = 0
KSUSEWTM = 1
KSUSESVC = SYS$BACKGROUND
KSUSEFLG2 = 1032
KSUSESESTA =
KSUSESEID = 0
KSUSEPESTA =
KSUSEPEID = 0
KSUSECRE = 2FA92228
KSUSECSN = 6

170 rows selected

私が想像するDirect Accessの用度は「OracleがHangに陥った時、System State DumpやHang Analyzeの他にFixed Tableから別度の情報を得たい場合」です。例えば、次のようなFixed Tableを通じればSession,Wait,Latch Missなどのような情報を得ることができます。

oradebug direct_access select * from x$ksuse;

oradebug direct_access select * from x$kslwt;

oradebug direct_access select * from x$kslwsc;


Direct Accessの用度は想像するのによって多様なものなどがあるでしょう。

Thursday, August 20, 2009

LOB Concatenationの性能問題

一顧客社でPL/SQLの内で300KBを超えるSQL文章を動的に生成する必要ができました。


最初に使用した方法は次のようでした。

(本来のソースコードを簡単なバージョンに変えた事を知らせて差し上げます)


UKJA@ukja1021> create or replace function make_long_sql(p_idx in number)
2 return clob
3 is
4 v_clob clob;
5 begin
6 v_clob := 'select ';
7 for idx in 1 .. p_idx loop
8 v_clob := v_clob||to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';
9 end loop;
10 v_clob := v_clob || '1 from dual';
11
12 return v_clob;
13 end;
14 /

Function created.

どんな特別な事項も見つけられません。CLOB変数をConcatenationを通じて合わせるとても簡単な作業です。すなわち、改善の事項がぜんぜんないように見えます。


どころが、この関数を実行してみればなんと46秒が掛かります。


UKJA@ukja1021> exec :c := make_long_sql(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:46.00

実際の顧客社では150KB程度の文字列を動的に生成するのに5分以上が掛かりました。


私の処方は次のようにかりにVARCHAR2変数を使ってCLOBに対したConcatenationの回数を減らすのでした。


UKJA@ukja1021> create or replace function make_long_sql2(p_idx in number)
2 return clob
3 is
4 v_clob clob;
5 v_varchar varchar2(1000);
6 begin
7 v_clob := 'select ';
8 for idx in 1 .. p_idx loop
9 v_varchar := to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';
10 v_clob := v_clob||v_varchar;
11 end loop;
12 v_clob := v_clob || '1 from dual';
13
14 return v_clob;
15 end;
16 /

Function created.

結果はとても劇的です。実行時間が42秒から0.5秒に減りました。

UKJA@ukja1021> exec :c := make_long_sql2(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.50

実際の顧客社では5分の作業が5秒程度に減りました。


どこからこんな大きい違いが起こってありますか。V$SESSTATビューとV$LATCHビューを通じてどんな違いがあるかを見れば、ヒントを得ることができます。


NAME VALUE1 VALUE2 DIFF
---------------------------------------- ------------ ------------ ------------
session logical reads 17,376,991 133,035 -17,243,956
db block gets from cache 15,764,933 102,971 -15,661,962
db block gets 15,764,933 102,971 -15,661,962
consistent changes 6,024,802 17,697 -6,007,105
db block changes 6,024,814 17,710 -6,007,104
consistent gets from cache 1,612,058 30,064 -1,581,994
consistent gets 1,612,058 30,064 -1,581,994
free buffer requested 1,432,143 49 -1,432,094
calls to get snapshot scn: kcmgss 480,030 40,019 -440,011
lob writes 120,008 10,004 -110,004
lob writes unaligned 119,962 10,004 -109,958
lob reads 60,001 10,001 -50,000
...

LATCH_NAME D_GETS D_MISSES D_SLEEPS D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
cache buffers chains -45091211 0 0 -1399062
object queue header operation -2864253 0 0 0
cache buffers lru chain -2864138 0 0 0
simulator hash latch -164417 0 0 0
simulator lru latch -112459 0 0 -51952
...

VARCHAR2変数を一時に使う場合にはLogical Reads, LOB Reads, LOB Writesなどが大きく減り、そのほどlatch獲得でも違いが発生します。これが性能の違いで現れたのです。


その理由は下のポストでよく説明しています。

http://jonathanlewis.wordpress.com/2009/07/09/concatenating-lobs/


LOBはConcatenationに脆弱な特徴を持っているから、Concatenationの回数および位置が性能に大きい影響を与える可能性があります。LOBを使うときはこの点に注意する必要があります。

Tuesday, August 18, 2009

オラクルのアラートファイルの分析の自動化

アラートファイル。オラクルに存在する情報の中で一番重要はものたちを提供しています。特に、次のようなエラー情報はとても有効です。

ORA-04031: unable to allocate ORA-04031: unable to allocate 540 bytes of shared memory ("shared pool","DBMS_RLMGR_DR","sga heap(1,1)","library cache")
ORA-06508: PL/SQL: could not find program unit being called: "EXFSYS.DBMS_RLMGR_DR"
...
Errors in file c:\oracle\admin\ukja10\udump\ukja10_ora_11376.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [_kslgetl+95] [PC:0x469AEB] [ADDR:0x12C] [UNABLE_TO_READ] []


でも、運営環境のアラートファイルはあんまり大きいから、目だけで分析するのは不可能な場合が時々あります。私はこのような場合に、次のような自動化されたスクリプトを使用しています。

ed alert_analyze.sql

/* create background dump directory
col value new_value back_dump
@para background_dump_dest
create or replace directory back_dump_dir as '&back_dump';

drop table t_alert_analyze;

create global temporary table t_alert_analyze(
reg_date date,
error_code varchar2(10),
message varchar2(4000)
);

*/

define __ALERT_LOG = "&1"
define __START_DT = "&2"
define __END_DT = "&3"
define __PATTERN = "&4"

set serveroutput on

delete from t_alert_analyze;

declare
v_date date;
v_start_dt date;
v_end_dt date;
v_err_code varchar2(10);
v_message varchar2(4000);
b_include boolean := false;
begin
select decode('&__START_DT', '%', sysdate - 100000,
to_date('&__START_DT', 'yyyy/mm/dd')) into v_start_dt from dual;

select decode('&__END_DT', '%', sysdate + 1,
to_date('&__END_DT', 'yyyy/mm/dd')) into v_end_dt from dual;

for r in (select column_value as txt
from table(get_trace_file3('BACK_DUMP_DIR', '&__ALERT_LOG'))) loop
--dbms_output.put_line(r.txt);
if regexp_like(r.txt, '[0-9][0-9]:[0-9][0-9]:[0-9][0-9] [0-9][0-9][0-9][0-9]') then
v_date := to_date(r.txt, 'Dy Mon dd hh24:mi:ss yyyy');
if b_include = false then
if v_date between v_start_dt and v_end_dt then
b_include := true;
end if;
end if;
end if;

if b_include then
if r.txt like '%&__PATTERN%' then
if r.txt like 'ORA-%' then -- error code exists
v_err_code := substr(r.txt, 1, 9);
v_message := substr(r.txt, 12);
else
v_err_code := '-';
v_message := r.txt;
end if;

insert into t_alert_analyze(reg_date, error_code, message)
values(v_date, v_err_code, v_message);
end if;
end if;

end loop;
end;
/


select to_char(reg_date,'yyyy/mm/dd') as "when" , error_code, count(*)
from t_alert_analyze
group by to_char(reg_date,'yyyy/mm/dd'), error_code
order by 1 desc, 3 desc
;

このalert_analyze.sqlスクリプトを利用すれば、次のように日別、エラーコード別にどんなエラーが発生しているのかを手軽にわかることができます。

UKJA@ukja116> @alert_analyze alert_back.log % % %

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/18 - 2
2009/08/17 - 7
2009/08/16 - 5
2009/08/15 - 5
2009/08/13 - 6
2009/08/12 - 32
2009/08/12 ORA-07445 6
2009/08/11 - 206
2009/08/11 ORA-00470 8
2009/08/11 ORA-07445 1
2009/08/11 ORA-19815 1

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/10 - 14
2009/08/09 - 6
2009/08/08 - 331
2009/08/08 ORA-19815 2
2009/08/08 ORA-04031 1
2009/08/08 ORA-00604 1
2009/08/07 - 97
2009/08/07 ORA-04031 9
2009/08/07 ORA-12012 5
2009/08/07 ORA-06512 1
2009/08/07 ORA-06508 1

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/06 - 7
2009/08/05 - 8
2009/08/05 ORA-1597 1
2009/08/04 - 711
2009/08/04 ORA-01555 8
2009/08/04 ORA-1652: 2
2009/08/04 ORA-19815 2
2009/08/04 ORA-1543 2
2009/08/04 ORA-30013 2
2009/08/04 ORA-27056 1
2009/08/04 ORA-01265 1

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/04 ORA-30036 1
2009/08/02 - 75
2009/08/01 - 5
2009/07/31 - 19
2009/07/30 - 7
2009/07/29 - 5
2009/07/28 - 3
2009/07/27 - 416
2009/07/27 ORA-27302 33
2009/07/27 ORA-27300 33
2009/07/27 ORA-27301 25

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/07/27 ORA-04030 16
2009/07/27 ORA-06512 12
2009/07/27 ORA-12012 6
2009/07/27 ORA-00604 4
2009/07/27 ORA-19815 1
2009/07/26 - 5
2009/07/25 - 252
2009/07/25 ORA-04030 2
2009/07/25 ORA-22303 1
2009/07/25 ORA-27302 1
2009/07/25 ORA-19815 1

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/07/25 ORA-27300 1
2009/07/24 - 158
2009/07/24 ORA-19815 1
2009/07/23 - 99
2009/07/23 ORA-04030 9
2009/07/23 ORA-00603 2
2009/07/23 ORA-00604 2
2009/07/22 - 200
2009/07/22 ORA-959 s 1
2009/07/22 ORA-19815 1
2009/07/22 ORA-3249 1

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/07/21 - 74
2009/07/20 - 5
2009/07/19 - 5
2009/07/18 - 9
2009/07/17 - 35

71 rows selected.

UKJA@ukja116> @alert_analyze alert_back.log % % 4031

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/08 ORA-04031 1
2009/08/07 ORA-04031 9

UKJA@ukja116> @alert_analyze alert_back.log 2009/08/08 % ORA-

when ERROR_CODE COUNT(*)
---------- ---------- ----------
2009/08/12 ORA-07445 6
2009/08/11 ORA-00470 8
2009/08/11 ORA-19815 1
2009/08/11 ORA-07445 1
2009/08/08 ORA-19815 2
2009/08/08 ORA-00604 1
2009/08/08 ORA-04031 1

オラクル性能問題をトラブルシューティングする時にはこのような自動化された技法をよく使用する必要があります。

Monday, August 10, 2009

ORA-4031エラーの生成および診断の方法

ORA-4031エラーを今この席で作ることができますか。下で、私が好んで使う方法を紹介します。


UKJA@ukja102> alter system set sga_target=0;

System altered.

Elapsed: 00:00:00.01
UKJA@ukja102>
UKJA@ukja102> alter system set db_cache_size=100m;

System altered.

Elapsed: 00:00:02.39
UKJA@ukja102> alter system set shared_pool_size=200m;

System altered.

Elapsed: 00:00:00.03
UKJA@ukja102> -- open many cursors and SQL statements
UKJA@ukja102> create or replace procedure proc_4031(p_depth in number)
2 is
3 v_cursor sys_refcursor;
4 v_sql varchar2(20000);
5 begin
6 v_sql := 'select 1 ' || rpad(' ', 4000) || rpad(' ', 4000) || rpad(' ', 4000)
7 || rpad(' ', 4000) || 'from dual a_' || p_depth;
8
9 open v_cursor for v_sql;
10
11 proc_4031(p_depth+1);
12
13 end;
14 /

Procedure created.

Elapsed: 00:00:00.11
UKJA@ukja102> -- allow tons of cursors open
UKJA@ukja102> alter system set open_cursors = 65535 scope=memory;

System altered.

Elapsed: 00:00:00.01

UKJA@ukja102> exec proc_4031(1);
BEGIN proc_4031(1); END;

*
ERROR at line 1:
ORA-04031: unable to allocate 536 bytes of shared memory ("shared
pool","unknown object","sga heap(1,1)","library cache")

本当に簡単でしょう?

オラクルはORA-4031エラーに会えば、次のような簡単な診断情報をトレースファイルに遺します。

=================================
Begin 4031 Diagnostic Information
=================================
The following information assists Oracle in diagnosing
causes of ORA-4031 errors. This trace may be disabled
by setting the init.ora _4031_dump_bitvec = 0
...

==============================
Memory Utilization of Subpool 1
================================
Allocation Name Size
_________________________ __________
"free memory " 2092180
"sql area " 10322144
"row cache " 3741868
"CCursor " 4475368
"PCursor " 2462740
"kglsim hash table bkts " 2097152
"KCB Table Scan Buffer " 3981204
"PL/SQL DIANA " 1081972
"ASH buffers " 4194304
"PL/SQL MPCODE " 1994296
"KQR M PO " 2143744
"KGLS heap " 2961796
"library cache " 13010768
"Heap0: KGL " 1167984
...

でも、大部分の状況ではこのような簡単な情報だけでは深みのある分析は難しいです。その場合には、次のようにマニュアルでHeapダンプを残す必要があります。

UKJA@ukja102> alter session set events '4031 trace name heapdump level 0x20000002, lifetime 1';

Session altered.

Elapsed: 00:00:00.01
UKJA@ukja102> alter session set "_4031_dump_bitvec" = 0;

Session altered.

Elapsed: 00:00:00.01
UKJA@ukja102>
UKJA@ukja102> exec proc_4031(1);
BEGIN proc_4031(1); END;

*
ERROR at line 1:
ORA-04031: unable to allocate 800 bytes of shared memory ("shared
pool","unknown object","sga heap(1,1)","library cache")

sga heap(1,1)プールで800バイトのメモリを割り当てできなくて、ORA-4031エラーが起こりました。
(レベル0x20000002のHeapダンプの意味はここで説明しています)

ロウトレースファイルはあんまり読みにくいから、私は自分で作ったheap_analyze.sqlスクリプトを利用してより意味のある情報を作り上げます。次のレポートを見てください。

UKJA@ukja102> @heap_analyze &trace_file

01. size per heap

HEAP_NAME HSZ
-------------------- ----------
sga heap(1,1) 96.0
sga heap(1,0) 40.0
sga heap(1,3) 32.0
sga heap(1,2) 32.0
KSFD SGA I/O b 3.8
CURSOR STATS 2.1
...


02. size per chunk type

HEAP_NAME CHUNK_TYPE CNT SZ HSZ HRATIO
-------------------- --------------- -------- ---------- ---------- ------
CURSOR STATS free 78 .0 2.1 .5
CURSOR STATS freeable 12,359 2.0 2.1 99.5
...
sga heap(1,1) R-free 24 4.9 96.0 5.1
sga heap(1,1) freeable 14,520 5.2 96.0 5.4
sga heap(1,1) recreate 13,150 85.7 96.0 89.3
sga heap(1,1) free 1,016 .2 96.0 .2
sga heap(1,1) R-freeable 48 .0 96.0 .0
...

03. size per object type

HEAP_NAME OBJ_TYPE CNT SZ HSZ HRATIO
-------------------- -------------------- -------- ---------- ---------- ------
...
sga heap(1,1) plwppwp:garbage 1 .0 96.0 .0
sga heap(1,1) listener addres 1 .0 96.0 .0
sga heap(1,1) KGL handles 12,376 81.3 96.0 84.6
sga heap(1,1) 1,040 5.1 96.0 5.3
sga heap(1,1) library cache 13,797 4.0 96.0 4.2
sga heap(1,1) KSFD SGA I/O b 1 3.8 96.0 4.0
...

05. freelists histogram

HEAP_NAME HIST CNT SZ HSZ HRATIO
-------------------- --------------- -------- ---------- ---------- ------
sga heap(1,1) (16~32) 33 .0 .2 .4
sga heap(1,1) (32~64) 140 .0 .2 3.4
sga heap(1,1) (64~128) 256 .0 .2 12.8
sga heap(1,1) (128~256) 253 .1 .2 26.9
sga heap(1,1) (256~512) 330 .1 .2 55.0
sga heap(1,1) (512~1024) 4 .0 .2 1.5
...


レポートの詳細な解析は皆さんに任せます。一つだけ言えば、このレポートだけでもORA-4031エラーの原因を相当に正確に見つけることが出来るというものです。
(heap_analyze.sqlの定義はここにあります)

SGAのHeapダンプにとって気にしなければならないのはこのオペレーションはlatchを過度に使用するというものです。従って本番環境で適用する時はシステムが失敗する可能性を甘受しなければなりません。

Tuesday, August 4, 2009

再現可能なテストケースを作りにくい理由

どこででも再現可能なテストケースを作ることがどんなに難しいかを見せてくれるいい例があります。


まず、下のOTN Forumを読んでください。



Tom KyteがここでORA-01555エラーを起こす確実なテストケースを提供しています。でも、この歴史的に証明された確実なテストケースさえも問題を再現することに失敗しています。


なぜこんな確実なテストケースさえ再現に失敗するのか簡単な例で説明してみます。


1. 私のオラクル環境です。


BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE 10.2.0.1.0 Production
TNS for 32-bit Windows: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production


2. ORA-01555エラーが発生しやすく小さなサイズのUndo Tablespaceを作ります。

alter system set undo_tablespace=UNDOTBS1;

drop table t purge;
create table t as select * from all_objects;
create index t_idx on t(object_id);

drop tablespace small_undo including contents and datafiles;
create undo tablespace small_undo datafile size 200k;

alter system set undo_tablespace=SMALL_UNDO;
alter system flush buffer_cache;



3. Tom Kyteの下のテストケースは必ずORA-01555エラーを起こすようになっています。

UKJA@ukja102> begin
2 for x in ( select * from t where object_id > 0 )
3 loop
4 update t set object_name = lower(object_name)
5 where object_id = x.object_id and rownum=1;
6 commit;
7 end loop;
8 end;
9 /

PL/SQL procedure successfully completed. -- Why no ORA-01555???

でもエラーが発生しません。なぜそうですか。


4. Tom Kyteがテストケースを作った以前のバージョンとは違いに最近のバージョンのオラクルでは該当SQL文章がIndex Range ScanではないTable Full Scanを使用します。


explain plan for select * from t where object_id > 0;

--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 50000 | 4541K| 186 (17)| 00:00:03 |
|* 1 | TABLE ACCESS FULL| T | 50000 | 4541K| 186 (17)| 00:00:03 |
--------------------------------------------------------------------------

Table Full Scanをする場合には一つのブロックの内に入っている行たちを一回に読み込むから一度読んだブロックをまた読む場合がほとんどありません。従ってUpdateによって変更されたブロックを再訪問することがないし、従ってUndoを読む過程でORA-01555エラーに会う確率もとても低くなります。


5. 今、次のようにINDEXヒントを与えてIndex Range Scanを使用するようにします。ただし、1000件の行だけ生成します。この場合にもいぜんとしてORA-01555エラーが発生していません。


UKJA@ukja102> create table t as select * from all_objects where rownum <= &1;
old 1: create table t as select * from all_objects where rownum <= &1
new 1: create table t as select * from all_objects where rownum <= 1000

Table created.

UKJA@ukja102> begin
2 for x in ( select /*+ index(t) */ * from t where object_id > 0 )
3 loop
4 update t set object_name = lower(object_name)
5 where object_id = x.object_id and rownum=1;
6 commit;
7 end loop;
8 end;
9 /

PL/SQL procedure successfully completed. -- Again no ORA-01555 error?


6. 1000件の行が少なすぎてUndoを十分になぞって書けないからです。次のように10,000件の行を読むようにすればとうとうORA-01555エラーが発生します。

UKJA@ukja102> create table t as select * from all_objects where rownum <= &1;
old 1: create table t as select * from all_objects where rownum <= &1
new 1: create table t as select * from all_objects where rownum <= 10000

Table created.

UKJA@ukja102> begin
2 for x in ( select /*+ index(t) */ * from t where object_id > 0 )
3 loop
4 update t set object_name = lower(object_name)
5 where object_id = x.object_id and rownum=1;
6 commit;
7 end loop;
8 end;
9 /
begin
*
ERROR at line 1:
ORA-01555: snapshot too old: rollback segment number with name "" too small
ORA-06512: at line 2



7. 上で言った例の外にもORA-01555エラーが発生しない多様な可能性があるでしょう。


毎度感じるものですが、いつどこでも再現可能なテストケースを作るのがどれほど難しいかわかりません。皆さんも誰かにテストケースをあげる事があったらもしや思えなかった制限や欠点を持っていないか悩まなければいけません。