”utl_file I/O” - この症状はあれの可能性が高いですね。 Tweet

JPOUG Advent Calendar 2017の4日目のエントリーです。

さて、最近あまりお目にかかってなかったUTL_FILEパッケージで表データをcsvに書きだすネタにしました。

先日、UTL_FILEパッケージを利用した処理が想定以上に遅いという相談をうけました。
AWRレポートをみると、上位の待機イベントは、”utl_file I/O"。

！！！！おーーーこれは、珍しいというか、久々にみた病気w

UTL_FILEパッケージを利用したI/Oをグルグルしているとか、でかいファイル読み書きしているかの、どちらかですよねw
ということで、この症状の治療法を考えてみます。

＜参考 - 環境＞

MacBook:˜ system_profiler SPHardwareDataType | grep -E 'Model|Processor|Cores|Memory'
      Model Name: MacBook
      Model Identifier: MacBook9,1
      Processor Name: Intel Core m5
      Processor Speed: 1.2 GHz
      Number of Processors: 1
      Total Number of Cores: 2
      Memory: 8 GB

ホストOS
MacBook:˜ discus$ sw_vers
ProductName:	Mac OS X
ProductVersion:	10.13.1
BuildVersion:	17B1003

MacBook:˜ discus$ VBoxManage -version
5.1.30r118389


ゲストOSとOracle Database
orcl@SYS> !uname -a
Linux localhost.localdomain 4.1.12-94.3.6.el7uek.x86_64 #2 SMP Tue May 30 19:25:15 PDT 2017 x86_64 x86_64 x86_64 GNU/Linux

orcl@SYS> !cat /etc/oracle-release
Oracle Linux Server release 7.3

orcl@SYS> 
orcl@SYS> select * from v$version;

BANNER                                                                               CON_ID
-------------------------------------------------------------------------------- ----------
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production              0
PL/SQL Release 12.2.0.1.0 - Production                                                    0
CORE	12.2.0.1.0	Production                                                            0
TNS for Linux: Version 12.2.0.1.0 - Production                                            0
NLSRTL Version 12.2.0.1.0 - Production                                                    0

UTL_FILEでファイル出力する際、ちょっとした手順の漏れが性能差として現れてしまうことがあります。
表の行長は数百バイト程度ですが、行数は数千万〜数億行なんていう状況だと、性能差が顕著に現れてしまうので注意が必要です。

以下の表、セグメントサイズは1GB程度ですが、行数は1千万行以上あります。
この表データをUTL_FILEパッケージを利用してcsvに出力してみます。

ORCL@SCOTT> select segment_name,sum(bytes)/1024/1024/1024 "GB" from user_segments group by segment_name;

SEGMENT_NAME                           GB
------------------------------ ----------
ABOUT_100BYTES_ROWS              .9140625
PK_ABOUT_100BYTES_ROWS            .171875


ORCL@SCOTT> select count(1) from about_100bytes_rows;

  COUNT(1)
----------
  10737420

表の1行は100bytes(改行コード含）です。

ORCL@SCOTT%gt; r
  1  SELECT
  2  	LENGTH(
  3  		TO_CHAR(id,'FM000000000000000000000000000009')
  4  		||','||FOO
  5  	) row_length
  6  FROM
  7  	about_100bytes_rows
  8  WHERE
  9* 	rownum <= 1

ROW_LENGTH
----------
        99

次の2つのコードの赤太文字部分に着目してください。
その部分が異なるだけで処理時間に大きな差が出ます。

DECLARE
	cDIR_NAME CONSTANT VARCHAR2(30) := 'FILES_DIR';
	cFILE_NAME CONSTANT VARCHAR2(128) := 'no_writebuffering_'||TO_CHAR(systimestamp, 'rrmmddhh24miss.ff')||'.txt';
	cBufferSize CONSTANT BINARY_INTEGER := 32767;
	cOpenMode CONSTANT VARCHAR2(2) := 'w';
	fileHandle UTL_FILE.FILE_TYPE;
	
	cBulkReadLimit CONSTANT PLS_INTEGER := 324;
	TYPE tBulkReadArray IS TABLE OF VARCHAR2(8192) INDEX BY BINARY_INTEGER;
	bulkReadArray tBulkReadArray;
	CURSOR cur_about100bytesRow IS
		SELECT
			TO_CHAR(id,'FM000000000000000000000000000009')
			||','||FOO
			AS csvrow
		FROM
			about_100bytes_rows
		;
BEGIN
	OPEN cur_about100bytesRow;
	fileHandle := UTL_FILE.FOPEN(cDIR_NAME, cFILE_NAME, cOpenMode, cBufferSize);
	LOOP
		FETCH cur_about100bytesRow
			BULK COLLECT INTO bulkReadArray
			LIMIT cBulkReadLimit;
		
		EXIT WHEN bulkReadArray.COUNT = 0;
		
		FOR i IN bulkReadArray.FIRST..bulkReadArray.LAST LOOP
			UTL_FILE.PUT_LINE(
				file => fileHandle
				, buffer => bulkReadArray(i)
				, autoflush => true
			);
		END LOOP;
	END LOOP;
	UTL_FILE.FFLUSH(fileHandle);
	UTL_FILE.FCLOSE(fileHandle);
	CLOSE cur_about100bytesRow;
EXCEPTION
	WHEN OTHERS THEN
		IF UTL_FILE.IS_OPEN(fileHandle) THEN
			UTL_FILE.FCLOSE(fileHandle);
		END IF;
		
		IF cur_about100bytesRow%ISOPEN THEN
			CLOSE cur_about100bytesRow;
		END IF;
		RAISE;
END;
/


PL/SQLプロシージャが正常に完了しました。

経過: 00:02:27.05

DECLARE
	cDIR_NAME CONSTANT VARCHAR2(30) := 'FILES_DIR';
	cFILE_NAME CONSTANT VARCHAR2(128) := 'writebuffering_'||TO_CHAR(systimestamp, 'rrmmddhh24miss.ff')||'.txt';
	cBufferSize CONSTANT BINARY_INTEGER := 32767;
	cOpenMode CONSTANT VARCHAR2(2) := 'w';
	fileHandle UTL_FILE.FILE_TYPE;
	buffer VARCHAR2(32767);
	
	cBulkReadLimit CONSTANT PLS_INTEGER := 324;
	TYPE tBulkReadArray IS TABLE OF VARCHAR2(8192) INDEX BY BINARY_INTEGER;
	bulkReadArray tBulkReadArray;
	CURSOR cur_about100bytesRow IS
		SELECT
			TO_CHAR(id,'FM000000000000000000000000000009')
			||','||FOO
			AS csvrow
		FROM
			about_100bytes_rows
		;
BEGIN
	OPEN cur_about100bytesRow;
	fileHandle := UTL_FILE.FOPEN(cDIR_NAME, cFILE_NAME, cOpenMode, cBufferSize);
	LOOP
		FETCH cur_about100bytesRow
			BULK COLLECT INTO bulkReadArray
			LIMIT cBulkReadLimit;
		
		EXIT WHEN bulkReadArray.COUNT = 0;
	
		buffer := NULL;	
		FOR i IN bulkReadArray.FIRST..bulkReadArray.LAST LOOP
			buffer := buffer || bulkReadArray(i) || UTL_TCP.CRLF;   
 		END LOOP;
		UTL_FILE.PUT(fileHandle, buffer);
		UTL_FILE.FFLUSH(fileHandle);
	END LOOP;
	UTL_FILE.FFLUSH(fileHandle);
	UTL_FILE.FCLOSE(fileHandle);
	CLOSE cur_about100bytesRow;
EXCEPTION
	WHEN OTHERS THEN
		IF UTL_FILE.IS_OPEN(fileHandle) THEN
			UTL_FILE.FCLOSE(fileHandle);
		END IF;
		
		IF cur_about100bytesRow%ISOPEN THEN
			CLOSE cur_about100bytesRow;
		END IF;
		RAISE;
END;
/


PL/SQLプロシージャが正常に完了しました。

経過: 00:00:43.96

何が違うかお分ですよね！
UTL_FILE.PUT_LINE/UTL_FILE.PUTが違う！！w
その部分は重要ではなく、100Bytes単位に書き込んでいるか、約32KB単位で書き込んでいるかが重要なんです。

UTL_FILEは最大32767バイトのバッファを利用できますが、前者はバッファを有効利用せず、100Bytes毎に書き出しています。後者は約32KB単位で書き出しています。

その差はAWRレポートからも見えてきます。

AWRレポート（一部抜粋）
UTL_FILEパッケージによるI/Oの待機は、”utl_file I/O”という待機イベントで現れます。

Avg Waitは短いですが、理由は100バイト単位の小さいなサイズの書き込みを繰り返しているわけなので、そんなとこでしょう。

Top 10 Foreground Events by Total Wait Time

                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
DB CPU                                          147.4             99.3
utl_file I/O                    32,212,266       49.5    1.54us   33.3 User I/O
direct path read                     1,881        1.2  620.61us     .8 User I/O
resmgr:cpu quantum                       1         .1   85.85ms     .1 Schedule
db file sequential read                 17          0     .98ms     .0 User I/O
PGA memory operation                    90          0   35.13us     .0 Other
latch: shared pool                       1          0    1.05ms     .0 Concurre
control file sequential read            80          0   12.83us     .0 System I
Disk file operations I/O                 6          0   73.67us     .0 User I/O
SQL*Net message to client                2          0    9.00us     .0 Network

一方、約32KB単位でバッファリングして書き出している場合、Waits回数が激減しています。
Avg Waitsは大きくなっていますが、書き出しサイズにほぼ比例しているので想定通りというところ。

Top 10 Foreground Events by Total Wait Time

                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
DB CPU                                             45             98.5
utl_file I/O                        66,288       27.4  413.54us   60.1 User I/O
direct path read                     1,881          1  550.71us    2.3 User I/O
db file sequential read                 88          0  443.38us     .1 User I/O
direct path write                        2          0    4.69ms     .0 User I/O
control file sequential read            80          0   33.25us     .0 System I
latch: shared pool                       1          0    2.38ms     .0 Concurre
Disk file operations I/O                 4          0  323.50us     .0 User I/O
PGA memory operation                    79          0   15.73us     .0 Other
SQL*Net message to client                4          0   20.25us     .0 Network

utl_file.put/put_lineでcsvを出力しているdeviceのiostat(util%)
まだまだ余裕があるのでI/Oで詰まっているのではなく、UTL_FILE.PUT/PUT_LINEの使い方の影響が大きいということですね。

最後に、
UTL_FILEパッケージの入出力時にはバッファの有効利用をお忘れなく。(つい忘れちゃうこともあるので、急いでるときとかw）
扱うデータが多い場合は得に。

そして、みなさま、
メリークリスマス（まだエントリーを書くかもしれませんがw）
#JPOUG