【ORACLE】Functionの実行時間はフェッチに大部分含まれる

IT

OracleのFunctionの実行時間はSQLそのものの完了よりはフェッチの部分に大部分が含まれるように感じる。

Functionを呼び出したタイミングではその中身まで深く計算せず、

フェッチしている中で詳細な計算をしていくようなイメージのようである。



SELECT文の問い合わせの”結果”には、

①Oracleからの検索結果返却開始

②全検索結果のフェッチ完了

の２段階のフェーズがあるが、

SELECTする項目の一つ、ないしそのうちの一部として同じ並びで記述するFunctionは、

基本的には前者「①Oracleからの検索結果返却開始」までの間に全て寄っていて、

検索結果が返却される段階ではもう既に計算済みだと思っていた。

だがどうやらそうではない。

実際にはOracleから検索結果が返却されてから、「②全検索結果のフェッチ完了」までの間に

その計算を行っているようである。

「①Oracleからの検索結果返却開始」が開始した段階では、

実際に発行したSELECTの中に含まれるFunctionの計算は行われていないということなのだな。



仕事のとある案件においてプロジェクトで自作した業務Functionの修正を行った際、

修正前後のスピード比較をしたときにふと疑問が浮かび、簡単な実験をして知った。

Oracle的には常識なのかもしれないが自分用のメモ。



実験用に呼び出すFunctionとして以下のようなものを用意している。
  
create or replace function func_test_sleep(exec_sleep_flg number) return number  
as  
begin  

if exec_sleep_flg = 1 then  
	DBMS_LOCK.SLEEP(2);  
end if;  

return 1;  



end;

/

引数に0を渡すと何もしないで速攻1を返すが、

引数に1を渡すと2秒待ってから1を返す。

渡す引数はSleepをするかしないかの指定になる。



また、Functionの呼び出しはPJ背景を鑑みてJDBCから行う。

以下のように各々のタイミングから各処理の時間を計測する。

（※これはSLEEPする指定（上記のFunctionに引数1を渡す指定）である）

  
//SLEEPするかしないかの設定（0ならしない、1ならする）  
String exec_mode = "1";  
//各タイミングで標準出力にログ出すときの時刻フォーマット  
DateFormat log_format = new SimpleDateFormat("yyyy/MM/dd HH:mm:ss.SSS");  
  
//①DBに接続  
OracleConnectionPoolDataSource opds = new OracleConnectionPoolDataSource();  
opds.setURL("jdbc:oracle:thin:@192.168.0.100:1521:TESTDB");  
opds.setUser("TESTUSER");  
opds.setPassword("TESTPASS");  
Connection con = opds.getConnection();  
//②SQL実行  
Statement st = con.createStatement();  
System.out.println(log_format.format(new Date()) + "（１）SQL開始");  
ResultSet rs = st.executeQuery("SELECT FUNC_TEST_SLEEP(" + exec_mode + ") FROM TEST_TABLE");  
System.out.println(log_format.format(new Date()) + "（２）SQL終了");  
//③とりあえず全フェッチ（フェッチサイズは実際のPJの都合にあわせている）  
rs.setFetchSize(400);  
while(rs.next()) {  
	// フェッチするだけで特に何もしない。全件舐めるのが目的  
}  
System.out.println(log_format.format(new Date()) + "（３）フェッチ終了");  
  
st.close();  
rs.close();  
con.close();

このとき、SELECT先のTEST_TABLEに1000件データを突っ込んで
「0：SLEEPしない」「1：SLEEPする」の各SQLの開始からフェッチ完了までの時間を計測してみる。
５回ほど実施したら以下のような結果になった。
モード（２）SQL終了までの平均時間（３）フェッチ終了までの平均時間
0：SLEEPしない 0.147秒0.184秒
1：SLEEPする 20.024秒33分と20.995秒
一目でわかるし、当然といえば当然だが、
「1：SLEEPする」ほうが（２）も（３）も圧倒的に時間がかかっている。
特に（３）に大きな違いが表れる。
冒頭で記述したように、当初の俺の予想では、
（２）の時点でFunctionの計算は全て終わっているものだと思っていたから、
フェッチの方で差が表れるとは思ってはいなかったけど、
「1：SLEEPする」の場合、（３）の平均は約33分で、2秒×1000件＝2000秒≒33.33…分となり、
1000件に対するFunctionの（Sleepの）処理を”フェッチするときに”実施していることがよくわかる。

また、興味深いのは「1：SLEEPする」場合の（２）の時間である。
平均して大体20秒となっている。
１件に対するSleepが2秒だから、逆算すると10件に対する計算をフェッチ開始前に実施していることになる。
JDBCの設定なのか、Oracle側の設定なのか、それとはまた別のものなのかわからないが、
フェッチ開始までの間に検索結果先頭10件に対する計算は行うらしい。
＝先頭10件の分だけ計算し終えた段階で「Oracle側から検索結果の問い合わせを開始する」ような指示をJDBCが受けるのだろうか？
（上記のサンプルプログラムでいえばResultSetをもらえる段階に来るということになる。）
ないし、JDBCの動きとして、「先頭10件読めればもうResultSet作ってアプリ側に引き継いでいいだろう」という設計思想なのか？
もう少し深い裏があるようにも見えるが、これは少し興味深い実験結果になった。

ところで、「1：SLEEPする」の（３）の時間は33分と20.995秒で、10進数化すると約33.35分くらいになる。
これはテスト用Functionを1000レコードに対して実行した場合の理論値
2秒×1000件＝2000秒≒33.33…分と大体一致しているが、
逆に言えばフェッチ側で全レコードに対してFunctionを実行しているということになる。
実験結果と上述した（２）の考察から見るに、フェッチ開始前に少なくとも先頭10件分は処理しているように思えるが、
これはフェッチ段階では捨てられている（なかったことになっている）のだろうか。
フェッチサイズを400件にしている関係や、
開始・終了の各段階とはいえ標準出力にログ出してる部分で多少ロスはするはずだが、
それが20秒という時間まで膨れ上がるとは到底思えない。
JDBCの動きとして、フェッチ開始前＝ResultSet返却までの動きは、
あくまで先頭10件を適当に舐めるだけの動きであり、フェッチとの関連性はないということなのか。
今回の実験は極端なケースだが、
バッチ処理等で比較的巨大な検索結果を一遍にもってきて処理するようなものがある場合、
ResultSet返却までの分がフェッチ時に考慮されないのはちょっと気になる。
細かくログ出すバッチだと気になるだろうな。(SQLが遅いからフェッチ開始時にログ出すように仕組んでるとか）
やはり設定のような気がするな…

ちなみにJDBC経由じゃない（PL/SQLとか）だとこうならないのだろうか。
実装の根本的な部分は同じはずだから暇が合ったらどこかで実験してみるか。