« 2017年11月 | トップページ | 2018年2月 »

2017年12月 4日 (月)

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

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の使い方の影響が大きいということですね。
20171203_202342


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

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

| | コメント (0) | トラックバック (0)