statspackさわる - kagamihogeの日記でstatspackを自分の環境で手軽に試せるようになった。なので、練習がてら分かりやすくハッキリと差が出るレポートを取得して眺めてみる。
やることは、10万回insertを実行するJavaのプログラムを2種類用意する。1つは、1回ごとにcommitする。もう1つは、1回だけ最後にcommitする。この2つの間でstatspackのレポートにどんな差が出るかを確認する。
環境
テーブルとプログラム準備
データを入れていくテーブルを作る。
DROP TABLE hoge_table PURGE; ALTER SYSTEM SWITCH LOGFILE; CREATE TABLE hoge_table ( ID INTEGER NOT NULL , VALUE VARCHAR2(10) NOT NULL , CONSTRAINT hoge_table_pk PRIMARY KEY ( ID ) ENABLE );
プログラムを実行する前に、下記のSQL実行とOracle再起動をする。ログスイッチは、スイッチの回数に変化が生じるかを見るためにしている。
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM SWITCH LOGFILE;
insertを1回ごとに1回commitするJavaのプログラムを用意する。
public static void main(String[] args) throws SQLException { long start = System.currentTimeMillis(); final String insertStr = "INSERT INTO hoge_table(ID, VALUE) VALUES(?, dbms_random.string('X', 10))"; try (Connection connection = DriverManager.getConnection( "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "a"); PreparedStatement sql = connection.prepareStatement(insertStr);) { connection.setAutoCommit(false); for (int i=0; i<100_000; i++) { sql.setInt(1, i); sql.executeUpdate(); connection.commit(); } } long end = System.currentTimeMillis(); System.out.println(end - start); }
上のコードをちょっと変更して、1回だけ最後にcommitするプログラムを用意する。
for (int i=0; i<100_000; i++) { sql.setInt(1, i); sql.executeUpdate(); } connection.commit();
まず実行時間の比較。
| 種類 | 1 | 2 |
|---|---|---|
| 1回ごと | 1152953 | 1135906 |
| 1回だけ | 49110 | 48859 |
ここまでは10万件INSERTを1件ずつコミットと1回だけコミットしたときの速度比較してみた - kagamihogeの日記とやったこと同じ。JDBC経由で100万件取得・追加してみた - kagamihogeの日記のjava.sql.Statement#addBatch(String sql)でラウンドトリップ減らせば更に速くなる。また、単純なデータロードならダイレクトパスロードでSQL*Loaderを使えば良い。
statspackレポートの比較
Top 5 Timed Events
statspackレポートのレポートを見るときは、まずこのセクションから見るらしい。なお、特に断りが無ければ、先が1回ごと、後が1回だけ、のレポートとする。
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
log file sync 100,026 1,034 10 49.2
log file parallel write 100,052 1,025 10 48.8
CPU time 24 1.1
db file async I/O submit 122 8 62 .4
control file parallel write 424 7 16 .3
-------------------------------------------------------------Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 6 47.0
log file parallel write 54 3 54 24.3
db file async I/O submit 5 2 379 15.9
control file parallel write 39 1 21 7.0
db file sequential read 373 0 0 1.5
-------------------------------------------------------------1回ごとが遅い理由は、ここでほぼ説明が出来る。まず、1回ごとのlog file syncとlog file parallel writeが突出しているが、1回だけの方は極々小さい値になっている。この2つのイベントで待たされているから遅い、ということが分かる。では、この2つの待機イベントとは何者なのか、ということになる。
log file parallel write
LGWRプロセスがカレントログファイルに書込んでいる時の待機です。log file sync
コミットなどのトランザクション確定時のREDOログファイル書込み待ちです（「log file parallel write」はLGWRプロセスの待ちですが、これはサーバープロセスの待ちです）。これは必ず発生する待機イベントです。REDOの書込みは整合性のため同期で行います（必ず書込み終了まで待ちます）ので、この書込み時間は多かれ少なかれ必ず待ちとして発生する訳です。
要するに、コミットするとディスク書き込みが発生する*1し、その書き込みはREDOログ整合性確保のため書き込み終了まで待たなくてはならない。厳密に言うと不正確な書き方ではあるのだけど、このエントリ内ではこんだけの理解でひとまず充分。
1回ごとコミットの場合の動作は、insertプラスcommitをするとREDOログファイル書込みに入る。そして、書き込みが終わる前に次のinsertプラスcommitが来るので待機を余儀なくされる（と思う）。いくら一回のREODログサイズが小さい（inser*1+commit*1だけ）とはいえ、メモリ上のログバッファに追加するほうが余程早いわけで、そこで待機することになる。HDDのアクセスランプを見ていると、1回ごとは点灯しっ放しになる。しかし、1回だけのほうはほとんどランプは点灯しない。この差も待機イベントの数字で説明が付く。
REDOログファイルへの書き込みは、Oracleがトランザクションをログ法で実現している以上避けようが無い。というか有って当たり前なので、log file syncやlog file parallel writeの待機イベントがある程度出てくるのは自然なことである。
かといって、頻繁にディスク書き込みがあっては性能は上がらない。そのための対策の1つがログバッファとなる。メモリ上にREDOログを適当に溜め込んでいって、適当なタイミングでディスクにまとめて書き込むことでディスク書き込みによる待機を減らすことが目的となる。まず、LGWRがREDOログを書き込むタイミングについて。一時的にせよメモリに置くことは喪失の危険があるので、性能とのバランスを見て色んなタイミングで書き込むようになっている、と思われる。
LGWRは、以下のタイミングでREDOデータをREDOログファイルに書き込みます。
・トランザクションがコミットされたとき
・DBWnがREDOデータの書き込みを要求したとき（更新済みブロックのデータファイルへの書き込み時など）
・3秒ごとのタイムアウトが発生したとき
・REDOログバッファの容量が不足したとき
・未書き込みREDOデータがREDOログバッファ全体の3分の1に達したときプロとしてのOracleアーキテクチャ入門 Oracle現場主義 CHAPTER 04 REDOログファイルとREDOデータ - REDOログバッファとLGWR p.52
ここで重要なのは、（LGWRは）トランザクションがコミットされたときREDOログバッファをファイルに書き込む、という点。1回ごとにcommitしていると、ログバッファに貯まるまでもなく即効でディスクにチマチマと書き出されていく。少量かつ高頻度でディスク書き込みが発生している、とも言える。Javaプログラム上では1ループごとなので10万回（Waits）それが発生する。対して1回だけの場合、トランザクションがコミットされたときの書き込みは1回だけとなる。statspack上、1回ごとはWaitsが100,026になっている所に現れている。
ちなみに、log file syncやlog file parallel writeがtop 5に出てくるのは、ぐぐってると割と「あるある」な事例なようである。事例紹介として、いわゆるバッチ系のプログラムで頻繁にコミットをし過ぎてるとこうなる、といった感じで紹介されてることが多い。このエントリでは、なぜそうなるかをカンタンなJavaのコードを書いてstatspackのレポートを取ることで、理解が深められた。
Load Profile
レポート対象期間中の1秒当たり、トランザクション当たりの統計情報。自分が重要だと感じた部分以外は割愛。
Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ ------------------ ----------------- ----------- -----------
Redo size: 70,615.9 845.9
Logical reads: 527.6 6.3
Block changes: 508.8 6.1
User calls: 167.0 2.0
Executes: 88.2 1.1
Transactions: 83.5Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ ------------------ ----------------- ----------- -----------
Redo size: 620,607.8 26,375,832.0
Logical reads: 3,774.8 160,429.5
Block changes: 4,808.1 204,342.0
User calls: 1,176.6 50,006.5
Executes: 1,206.4 51,273.5ここは絶対値にはアンマリ意味がなく、その環境下での相対評価をして意味が出てくる。ここでは1回ごと・1回だけで相対評価することになる。比較してみると、1回だけの方がより多くのREDOやら処理やらをこなせていることが分かる。それは何故かといえば、1回ごとは待機されまくって他の処理が出来なかったから、ということになる。
Statistic
自分が重要だと感じた部分以外は割愛。
Statistic Time (s) % DB time ----------------------------------- -------------------- --------- DB CPU 65.9 6.1 sql execute elapsed time 28.1 2.6 DB time 1,085.6 background elapsed time 1,056.3 background cpu time 23.4
Statistic Time (s) % DB time ----------------------------------- -------------------- --------- DB CPU 32.5 99.1 sql execute elapsed time 20.4 62.3 DB time 32.8 background elapsed time 6.4 background cpu time 0.5
1回ごとは、バックグラウンド実行時間（background elapsed time）が半端無く多い。これは恐らく、上述の通りLGWRの待機イベントだと考えられる。
上の方に書いたがコミット時に現れる待機イベントは大別して2つある。log file parallel writeはLGWRプロセスで、log file syncはサーバプロセスの待機である。これはちょっと想像になってしまうのだが、アプリケーションのプログラマから見るとバックグラウンドプロセスの待機は基本的には不可視である。直接的に見えるのはサーバプロセスの待機のみである。なので、裏側で何かが起きていたとしても気付くのは難しい*2 よって、このエントリの例の場合、Javaのコードだけを見ていると「なんか知らんがコミットが遅い」となるのではなかろうか。
他のサーバプロセスがある環境下で頻繁なコミットを繰り返せば、このエントリの例とは比較にならないほど待機が頻発してコミット処理は遅くなるハズである。自分自身でlog file syncを大量に引き起こすわ、他のプロセスのlog file parallel writeで待機させられるわ、で良いことが無い。この辺については後で改めて触れたい。
Event
Avg %Total
%Tim Total Wait wait Waits Call
Event Waits out Time (s) (ms) /txn Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync 100,025 0 1,034 10 1.0 49.2
db file sequential read 708 0 2 3 0.0 .1
log file switch completion 2 0 0 112 0.0 .0
db file scattered read 8 0 0 4 0.0 .0
resmgr:cpu quantum 1 0 0 7 0.0 .0
control file sequential read 209 0 0 0 0.0 .0
Disk file operations I/O 10 0 0 0 0.0 .0
SQL*Net message from client 200,004 0 1,249 6 2.0
jobq slave wait 601 100 301 501 0.0
SQL*Net message to client 200,004 0 1 0 2.0
-------------------------------------------------------------
Avg %Total
%Tim Total Wait wait Waits Call
Event Waits out Time (s) (ms) /txn Time
---------------------------- ------------ ---- ---------- ------ -------- ------
db file sequential read 368 0 0 0 184.0 1.5
log buffer space 1 0 0 175 0.5 1.5
log file switch completion 1 0 0 134 0.5 1.1
log file sync 3 0 0 24 1.5 .6
db file scattered read 19 0 0 2 9.5 .3
control file sequential read 173 0 0 0 86.5 .0
SQL*Net message from client 100,005 0 104 1 ########
SQL*Net message to client 100,005 0 0 0 ########
-------------------------------------------------------------
このセクションで興味深いのはSQL*Net message from clientのところ。Wait Timeが1,249なのは実際にはlog file syncによるものなので良いとして、Waitsが20万になっている。この数値は、アプリからOracleに対して20万回SQLなどの命令要求があったことを示している。1回ごとでは、insert + commitの2 * 10万で20万と思われる。1回だけのほうは10万である。この例の場合は回数は大して問題になっていないと思われる。
しかし、JDBCのバッチ更新でこの部分の改善をすると更に高速化する。コード例は省略*3するが、バッチサイズを100にすると、この例の場合SQL*Net message from clientが1,000くらいになる。100 * 1000で10万。Oracleとの通信回数を減らすことで性能アップが見込める理由は、このあたりの数値となって現れる。
Statistic
このセクションは各統計情報の項目がどれだけあったかを示している。経過時間ごと、経過トランザクションごとなので、これも相対値で比較して意味が出てくる。ただ、このエントリの例の場合、1回ごとの方が経過時間がかなり長いので、その分だけ相対的に数字が大きくなる。
Statistic Total per Second per Trans --------------------------------- ------------------ -------------- ------------ CPU used by this session 2,394 2.0 0.0 CPU used when call started 2,317 1.9 0.0 IMU Redo allocation size 366,804 306.2 3.7 IMU commits 99,084 82.7 1.0 IMU undo allocation size 106,608,112 88,988.4 1,066.0 db block changes 609,566 508.8 6.1 redo size 84,597,804 70,615.9 845.9 redo synch time (usec) 1,035,021,368 863,957.7 10,349.6 session pga memory max 21,709,712 18,121.6 217.1 session uga memory max 25,763,832 21,505.7 257.6
Statistic Total per Second per Trans --------------------------------- ------------------ -------------- ------------ CPU used by this session 560 6.6 280.0 CPU used when call started 604 7.1 302.0 IMU Redo allocation size 10,056 118.3 5,028.0 IMU commits 0 0.0 0.0 IMU undo allocation size 5,152 60.6 2,576.0 db block changes 408,684 4,808.1 204,342.0 redo size 52,751,664 620,607.8 ############ redo synch time (usec) 71,869 845.5 35,934.5 session pga memory max 9,044,016 106,400.2 4,522,008.0 session uga memory max 8,897,248 104,673.5 4,448,624.0
ここで目を引くのはredo sizeの項目。1回ごとのTotalは約84M、1回だけは約52Mになっている。この差は、コミットしたという情報もREDOログに書き込まれるため、と考えられる。なのでREDOログには insert,commit,insert,commit...という構造になっているハズである。1回だけの場合は、insert,insert,insert,...,commitという構造になるので、サイズは減る。
というわけで、試しにコミットだけを繰り返すプログラムを実行してみる。
connection.setAutoCommit(false); for (int i=0; i<100_000; i++) { connection.commit(); }
このプログラムを実行したあとstatspackのレポートを取るとredo sizeはガン増えする。なので、追加更新削除が何も無くても、コミットをするとただそれだけでOracleに負荷をかけることになる。*4ただ、先にも書いた通りコミットはOracleに無くてはならない処理である。なので、何がコミットすべき単位なのか・トランザクションはどこからどこまでなのか、を考える必要が出てくる。これは後で考えたい。
あと、CPU used by this sessionやsession pga|uga memory maxも1回だけのほうが少なくエコである。
Statistic - log switches
Statistic Total per Hour --------------------------------- ------------------ --------- log switches (derived) 2 6.01
Statistic Total per Hour --------------------------------- ------------------ --------- log switches (derived) 1 42.35
ログスイッチの回数は、1回ごとが2回だが、1回だけは1回で済んでいる。どちらのプログラムも結果として10万件レコードが追加されることには変わらないが、Oracleの内部的にはだいぶ異なる結果となっているのが伺える。なおJDBCのバッチ更新を利用すると0回となった。redo sizeが小さくなるのだから当然といえば当然なのだけど。
感想とかチラ裏
何がトランザクションなのか
Oracleにおけるコミットは、何も更新するものがなくても負荷のかかる処理、ということをレポートを示しながら書いた。また、トランザクションを実現するためにコミットは必要不可欠である。なので、適当な単位でコミットをすることが開発者には要求される。でまぁ、適当な単位とは一体何なんだ、ということになる。
ここから先は、まだ俺自身トランザクションの理解が浅いこともあり、感想あるいはチラ裏なのだけど。
まず、トランザクションを論理レベルの単位として表現しなければいけないものは何か、ということになる。論理レベルというのは、ビジネスとか業務とかの単位のこと。トランザクションの例で出てくる銀行口座のアレとかああいうの。ビジネス上でここからここまでが分解不可能な一単位だ、という代物が、論理レベルのトランザクションの一単位に相当する、と考えられる。でまぁ、オンラインだと注文とかバッチだと残高繰越だとか、基本的には境界がハッキリしているモンである。
論理レベルでのトランザクションは基本的にはハッキリしているのだけど、必ずしもハッキリするとは限らない。会計みたいにルールが決まってるのとか、お客さんの注文みたいに金が絡むから必然的に決まるのは良い。例えばこのエントリの例のようにデータ突っ込むだけのバッチとかは、論理レベル・ビジネス上の一単位は何なんだろうか？ と俺は疑問に思う。まぁこの場合、一件だろうが全件だろうが、データが揃ってさえいればボクは満足するんだ、というのが実際のところなんだろうけど。
ビジネス的というよりシステム的に実施しなければならない処理とか、その会社固有の業務処理で何が一単位なのかイマイチ不明な処理とかは、どこからどこまでをトランザクションと捉えるべきなのか。この辺はこれから勉強しないといかんなーと思う。
もちろん、物理レベルの制約も考慮しなければならない。いくらUNDOセグメントが自動拡張するからって、領域不足になるような大きすぎるトランザクションは実現不可能である。このエントリの例で言えば、1件ずつコミットするのは明らかにオーバーヘッド過剰で、最後に1回だけコミットすれば充分そうである。勿論、この程度の負荷どっちだって知ったことか、というのもアリだと思う。とはいえ、論理レベルの要求を実現するために、物理レベルでなるべく安く済む手段を取ることが、開発者の責務と言えそうな感じである。
が、この辺結構めんどくさいこと色々考えなければならないのだけど、プログラマにまとめて投げ捨てられてるのが現状である。
プログラマの不安
実を言うと、このエントリの1件ずつコミットは俺自身がやっちまったことのある失敗談である。最も、Oracle関連の本とか資料とか見てると、よくある失敗事例として見かけるので、俺に固有の失敗事例というわけでもない。それはともかく、何故そういうコードを書いてしまったか、ということについて考えたい。
まず、コミットが重い処理だと知らないことが挙げられる。コミットすればデータが確定される、ぐらいの知識なので、小まめにセーブしとけばおｋだろう、程度の判断。また、なるべく速くコミットしなければデータが保持されないのではないか、という不安もある。
このような知識不足やそれに起因する不安にかられて過剰にコミットを連発すると性能上不利な事象となって現れる。なお悪いことにコード上では本当に些細な違いでしかない。また、データ量が少なければ特に問題無く動いてしまうので、ずっと後になってから性能劣化が表面化する遠因にもなってしまう。なんつーかまぁ知らないってのは本当に恐ろしい。
俗に経験豊富なDBAがプロジェクト早期から参画すると失敗の確率が減ると言われるけど、こういうポイントを早期に潰していけるからなのだろう、と推測される。
参考URL
- 第19回 UNDOデータとREDOログについて
- OTN Japan - Oracleデータベース 性能対策機能 〜 StatspackとDiagnostics Packを使いこなす 〜 第2回 ケーススタディ（Statspack）
- Oracle Databaseリファレンス11gリリース2 (11.2) -C Oracle待機イベント - 待機イベントの説明
- パフォーマンスセラピー / システム統計情報とセッション統計情報を取得してみよう
- 共有プール - オラクル・Oracleをマスターするための基本と仕組み
- http://www.insight-tec.com/mailmagazine/ora3/vol330.html
- MyKnowledge SE社員: show ～ Oracle チューニング db file sequential read
- 日本エクセム∥EXEM LABO∥Oracle Knowledge
*1:これは不正確で、グループ・コミットがあるので必ずしもそうなるとは限らないが、このエントリでは他のセッションがいないのでほとんど関係が無い
*2:詳しい仕組みを知らなくても利益を享受出来るのがミドルウェアの利点でもあるのだが
*3:http://d.hatena.ne.jp/kagamihoge/20120628/1340884433
*4:Oracleにおいて空コミットはほとんど性能に影響しない http://kagamihoge.hatenablog.com/entry/2014/03/02/160514
