ORA-1652が発生 - おらくるのいる生活

梅雨空の続くある日、ora-1652が発生して業務影響が出ていると連絡がありました。
何年も前から稼働している本番環境で、構成は以下の通りです。

Oracle RAC（4ノード） EE 12.1.0.2

RHEL Version 6.7

価格: 2530 円
楽天で詳細を見る

エラーの原因と対処法はマニュアルを見なくてもコマンドラインで確認できます。

$ oerr ora 1652
01652, 00000, "unable to extend temp segment by %s in tablespace %s"
// *Cause: Failed to allocate an extent of the required number of blocks for
// a temporary segment in the tablespace indicated.
// *Action: Use ALTER TABLESPACE ADD DATAFILE statement to add one or more
// files to the tablespace indicated.

一時表領域不足によるエラーで、回避策は当然ながら一時表領域の拡張になります。
一時表領域は約30GBで、同サイズのファイルを追加して2倍の領域にする事で対処してもらいました。

一時表領域の使用率確認は以下のようなSQLで行います。
各カラムの意味ですが、
ALLOCATED_SPACE：現在割り当てられ、使用されている領域と、現在割り当てられ、再利用できる領域を含む、割り当てられた領域の合計量(バイト)
FREE_SPACE：現在割り当てられ、再利用できる領域と、現在割り当てられていない領域を含む、使用可能空き領域の合計量(バイト)
となるので、ALLOCATED_SPACE+FREE_SPACE>=TABLESPACE_SIZEとなります。
以下のSQLでは再利用不可の領域サイズ÷表領域サイズを"ts_used_%"としています。

SQL> select tablespace_name,
2 round(TABLESPACE_SIZE/1024/1024,1) tablespace_MB,
3 round(ALLOCATED_SPACE/1024/1024,1) used_MB,
4 round(FREE_SPACE/1024/1024,1) free_MB,
5 lpad(round((TABLESPACE_SIZE-FREE_SPACE)/(TABLESPACE_SIZE)*100,2)||'%',10,' ') "ts_used_%"
6 from dba_temp_free_space;

TABLESPACE_NAME ABLESPACE_MB USED_MB FREE_MB ts_used_%
------------------------------ ------------- ---------- ---------- ----------
TEMP 50 15 49 6.67%

ちなみに、通常の表領域使用率は以下のSQLで取得します。

SQL> select total.TABLESPACE_NAME tsname,
D nfrags,
C/1024/1024 mxfrag,
A/1024/1024 totsiz,
B/1024/1024 avasiz,
(1-nvl(B,0)/A)*100 pctusd
from
(select sum(bytes) A,
tablespace_name
from dba_data_files
group by tablespace_name) TOTAL,
(select sum(bytes) B,
max(bytes) C,
count(bytes) D,
tablespace_name
from dba_free_space
group by tablespace_name) FREE
where
total.TABLESPACE_NAME=free.TABLESPACE_NAME(+);
2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

TSNAME NFRAGS MXFRAG TOTSIZ AVASIZ PCTUSD
------------------------------ ---------- ---------- ---------- ---------- ----------
SYSAUX 196 2890 5000 3945.375 21.0925
UNDOTBS1 41 3968 8000 5499.75 31.253125
USERS 1 3.3125 5 3.3125 33.75
SYSTEM 2 7 1210 7.125 99.411157

※UNDO表領域については上記の使用率ではなく、(v$undostat.ACTIVEBLKS+v$undostat.UNEXPIREDBLKS)÷UNDO表領域サイズで計算します。

エラーは発生しなくなり業務影響も無くなったので、次に原因調査をします。
必要となるのは障害発生前後の時間帯も含んだAWRレポートと、ASH(ActiveSessionHistory)のダンプファイルです。

ASHのダンプは以下のような手順で取得します。
まず、 sys 以外のDBAロールを付与されたユーザ（例：system）でコピーテーブルを作成します。

SQL> conn system/******
SQL> create table exp_hist_active_sess_history
as select * from dba_hist_active_sess_history
where sample_time
between to_timestamp('16-10-12 21:30:00','YY-MM-DD HH24:MI:SS')
and to_timestamp('16-10-12 21:30:00','YY-MM-DD HH24:MI:SS');

作成したコピーテーブルをエクスポートします。

$ expdp system/****** directory=test_dir dumpfile=exp_ash.dmp tables=exp_hist_active_sess_history

コピーテーブルを作成するのはsysのオブジェクトはエクスポートできないからで、当然、コピーテーブルはsys以外のユーザで作成する必要があります。

上記手順で本番環境からエクスポートしたデータを、検証環境にインポートして、一時表領域を大量に使用しているSQLを確認します。

SQL> select distinct SQL_ID from exp_hist_active_sess_history where TEMP_SPACE_ALLOCATED >=50*1024*1024;

その結果、一時表領域を50MB以上使用していたのはある特定の一つのSQLである事、障害発生時間帯に顕著に使用量が増えている事が判明しました。
障害発生時とその前後の平常時でSQL_PLAN_HASH_VALUEが同じなので、実行計画は変わっていない事も判ります。

被疑SQLは判明したので、次にこのSQLがその時間帯に限って大量に一時表領域を使用した原因を探ります。
まずAWRの処理時間の長いSQLから、負荷の高い時間帯に特に長時間かかったSQLをピックアップしてみました。

障害発生前

SQL Id	Elapsed (s)	CPU (s)	IOWait (s)	Gets	Reads	Rows	Cluster (s)	Execs	Elapsed (s)	CPU (s)	IOWait (s)	Gets	Reads	Rows	Cluster (s)	DB time	DB CPU	IO Wait	Gets	Reads	Cluster	Execs	SQL Text
	Total								Per Execution							Percentage of Total
yyyyyy	5,878.15	5,024.28	171.46	939,177,081	13,532,704	14,819	560.16	11,139	0.53	0.45	0.02	84,314.31	1,214.89	1.33	0.05	28.43	28.73	0.15	31.20	17.37	32.80	0.63	WITH AAA AS ( ...
xxxxxx	5,678.55	4,774.27	708.05	498,777,432	34,474,420	2,790	71.12	885	6.42	5.39	0.80	563,590.32	38,954.15	3.15	0.08	27.46	27.30	0.62	16.57	44.25	4.16	0.05	WITH SSS AS ...
zzzzzz	517.33	488.52	11.53	37,859,990	409,268	18,680	1.69	12,402	0.04	0.04	0.00	3,052.73	33.00	1.51	0.00	2.50	2.79	0.01	1.26	0.53	0.10	0.70	WITH GGG AS ( SELECT GGG...

障害発生時

SQL Id	Elapsed (s)	CPU (s)	IOWait (s)	Gets	Reads	Rows	Cluster (s)	Execs	Elapsed (s)	CPU (s)	IOWait (s)	Gets	Reads	Rows	Cluster (s)	DB time	DB CPU	IO Wait	Gets	Reads	Cluster	Execs	SQL Text
	Total								Per Execution							Percentage of Total
xxxxxx	598,929.85	11,437.04	38,426.76	1,054,682,763	65,319,166	5,202	89,669.01	2,895	206.88	3.95	13.27	364,311.84	22,562.75	1.80	30.97	42.90	32.20	0.58	20.38	48.20	51.11	0.06	WITH SSS AS ...
yyyyyy	346,542.90	12,682.99	17,382.04	2,337,263,005	33,409,125	34,896	43,802.27	27,913	12.42	0.45	0.62	83,733.85	1,196.90	1.25	1.57	24.82	35.71	0.26	45.17	24.65	24.96	0.57	WITH AAA AS ( ...
zzzzzz	322,739.86	1,720.68	2,129.13	136,209,746	1,473,010	56,316	27,983.22	45,095	7.16	0.04	0.05	3,020.51	32.66	1.25	0.62	23.12	4.84	0.03	2.63	1.09	15.95	0.92	WITH GGG AS ( SELECT GGG...

X,Y,Zの3つのSQLで、平常時に比べて処理時間が長くなっています。
このうち、ASHで確認した被疑SQLはXになります。
特にXについては処理件数が約3倍、1実行当たりの処理時間は30倍以上と、顕著に増加しています。

更に「Top SQL with Top Row Sources」で確認すると、X,Y,Z共に「enq: SS - contention」で長時間待機しているので、ソート・セグメント（この場合は一時表領域）で競合が発生し、待機した事になります。

SQL ID	Plan Hash	Executions	% Activity	Row Source	% Row Source	Top Event	% Event	SQL Text
xxx	866674186	3032	42.31	SELECT STATEMENT	38.31	enq: SS - contention	29.57	WITH SSS AS ...
a5r21nr6zyrd3	866674186	3032	42.30503303799904485612254353388978780124	TABLE ACCESS - FULL	2.13	db file scattered read	2.10
a5r21nr6zyrd3	866674186	3032	42.30503303799904485612254353388978780124	LOAD AS SELECT	1.28	CPU + Wait for CPU	0.72
yyy	1102321024	6792	24.58	SELECT STATEMENT	21.64	enq: SS - contention	18.33	WITH AAA AS ( ...
9wbk301r9js8y	1102321024	6792	24.57642220210559329403462752952748889823	TABLE ACCESS - FULL	1.33	CPU + Wait for CPU	0.89
zzz	4180003833	6228	22.81	SELECT STATEMENT	22.50	enq: SS - contention	19.90	WITH GGG AS ( SELECT GGG...

Y,Zについては一時表領域の使用量が少ないので、Xが一時表領域を食い潰した結果、ソート・セグメントが使用できずに待機してしまったようです。
一時表領域枯渇により、1実行当たりの処理時間がソート領域待機によって増え、領域解放までに時間がかかる事で更に領域不足を加速させたと考えられます。
また、CPUやメモリの使用率には余裕があったので、業務影響が出たのもXの実行数が増えて一時表領域を食い潰した事による待機が原因でした。

Xではテーブルのフルスキャンが行われているので、その点が改善できれば一時表領域の使用量が減る可能性がある事をAP開発元に伝えて、今回の調査は終了となりました。