システムのテスト工程などでSQLの性能試験を行った際に、SQLの実行計画は悪くないはずなのに、期待していたよりレスポンスが遅かったときなどに、何で遅いのか・何の処理過程で時間を消費しているのか調べたくなる時があります。
今回は、SQLトレースを用いて、SQL実行時の処理過程や各処理時間といった内訳を調査する方法について調べてみました。
1.SQLトレースとは
SQLトレースは、Oracle Databaseで使用できる機能で、個々のSQL文に関する詳細な性能情報をトレースファイルとして出力(取得)する機能です。
※現場ではトレースファイルを「SQLトレース」と呼ぶことも多いので、SQLの詳細な性能情報を取得する機能やそれにより出力されたファイルを指していると思えばよいかと思います。
トレースファイルは詳細な情報が出力されているが故に可読性が低いため、tkprofユーティリティを用いて、判読可能なファイルに変換した後に内容を確認するのが一般的です。
2.SQL実行時の処理過程を調査する際のポイント
tkprofで変換後のトレースファイルは、SQL文を実行する際に発生した処理や待機に関する時系列情報が失われ、SQL実行時の処理過程を追えなくなるため、tkprofで変換する前のトレースファイル(生トレースとも呼びます)を使用します。
以下は、トレースファイルの一部分を抜粋したものになります。※便宜上、先頭に行番号を付与しています。
1: EXEC #139933626861888:c=34,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2044041692,tim=125080321222 2: WAIT #139933626861888: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080321262 3: FETCH #139933626861888:c=79,e=79,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2044041692,tim=125080321408 4: WAIT #139933626861888: nam='SQL*Net message from client' ela= 12812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334260 5: WAIT #139933626861888: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334473 6: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 31 driver id=1413697536 #bytes=8102 p3=0 obj#=-1 tim=125080334692 7: …(略) 8: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8101 p3=0 obj#=-1 tim=125080386233 9: FETCH #139933626861888:c=33970,e=51850,p=0,cr=1040,cu=0,mis=0,r=100000,dep=0,og=1,plh=2044041692,tim=125080386294 10: WAIT #139933626861888: nam='SQL*Net message from client' ela= 296449 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080682787
トレースファイルには上記の様に、解析(PARSE)/実行(EXEC)/フェッチ(FETCH)/クローズ(CLOSE)処理や待機イベント(WAIT)情報が1行に1ステップずつ出力されますが、各ステップの処理(待機)が終了したタイミングでトレースファイルに出力される点が、処理過程を調査する際の重要なポイントとなります。
各ステップの終了時刻情報は、tim=の後に数値で出力されます。この時刻情報は、トレースファイル内での相対的な数値で、マイクロ秒単位で出力されます。
開始時刻情報は、終了時刻情報から当該ステップの処理時間を引くことで算出できます。処理時間は、PARSE/EXEC/FETCH/CLOSE処理の場合e=の後に、WAITの場合ela=の後に、マイクロ秒単位で出力されます。
開始時刻情報を算出したら、トレースファイル内の各ステップを開始時刻順に並び変えることで、SQLの処理過程を把握することができます。
例として、上記トレースファイルの各ステップを開始時刻順に並べ替えると、以下の様に9行目のFETCHステップが4行目の後になります。また、この9行目のFETCHステップの終了時刻(tim)は125080386294で、5～8行目のWAITステップは9行目の終了時刻より前に開始/終了しているため、9行目のFETCHステップの処理中に発生していたと読取ることができます。
1: EXEC #139933626861888:c=34,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2044041692,tim=125080321222 2: WAIT #139933626861888: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080321262 3: FETCH #139933626861888:c=79,e=79,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2044041692,tim=125080321408 4: WAIT #139933626861888: nam='SQL*Net message from client' ela= 12812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334260 9: FETCH #139933626861888:c=33970,e=51850,p=0,cr=1040,cu=0,mis=0,r=100000,dep=0,og=1,plh=2044041692,tim=125080386294 5: WAIT #139933626861888: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334473 6: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 31 driver id=1413697536 #bytes=8102 p3=0 obj#=-1 tim=125080334692 7: …(略) 8: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8101 p3=0 obj#=-1 tim=125080386233 10: WAIT #139933626861888: nam='SQL*Net message from client' ela= 296449 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080682787
以降で、SELECTとUPDATEについて、SQLの処理過程の調査例を紹介します。
3. 調査例1: SQL*PlusからのSELECT実行
調査例として、SQL*Plusのarraysizeパラメータを100,000に設定して、500,000件格納されているテーブルをSELECTした際の処理過程を紹介します。
SQLトレースの取得は、以下の様に実施しました。取得レベルを12ではなく8としたのは、今回の取得目的が処理過程の調査であり、バインド変数の中身の情報までは不要であったためです。
[SQLトレースの開始] SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'; [調査対象SQLの実行] SQL> select /*+ array 100000 */ * from tab01; [SQLトレースの終了] SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
トレースファイルの全ては膨大な行数なので、適宜省略したものに説明用の行番号を付与したものを掲載いたします。
1: PARSING IN CURSOR #139933626861888 len=39 dep=0 uid=17 oct=3 lid=17 tim=125080321119 hv=3033295236 ad='712f6900' sqlid='57y8tzyucsuc4' 2: select /*+ array 100000 */ * from tab01 3: END OF STMT 4: PARSE #139933626861888:c=61,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2044041692,tim=125080321118 5: EXEC #139933626861888:c=34,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2044041692,tim=125080321222 6: WAIT #139933626861888: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080321262 7: FETCH #139933626861888:c=79,e=79,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2044041692,tim=125080321408 8: WAIT #139933626861888: nam='SQL*Net message from client' ela= 12812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334260 9: WAIT #139933626861888: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080334473 10: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 31 driver id=1413697536 #bytes=8102 p3=0 obj#=-1 tim=125080334692 11: …(略) 12: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8101 p3=0 obj#=-1 tim=125080386233 13: FETCH #139933626861888:c=33970,e=51850,p=0,cr=1040,cu=0,mis=0,r=100000,dep=0,og=1,plh=2044041692,tim=125080386294 14: WAIT #139933626861888: nam='SQL*Net message from client' ela= 296449 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080682787 15: WAIT #139933626861888: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125080682920 16: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 112 driver id=1413697536 #bytes=8104 p3=0 obj#=-1 tim=125080683187 17: …(略) 18: WAIT #139933626861888: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8101 p3=0 obj#=-1 tim=125081715678 19: FETCH #139933626861888:c=33333,e=36180,p=0,cr=1042,cu=0,mis=0,r=99999,dep=0,og=1,plh=2044041692,tim=125081715794 20: STAT #139933626861888 id=1 cnt=500000 pid=0 pos=1 obj=1783 op='TABLE ACCESS FULL TAB01 (cr=5208 pr=0 pw=0 str=1 time=48379 us cost=1439 size=35000000 card=500000)' 21: 22: *** 2024-03-31T22:10:26.362889+09:00 (ORCLPDB(3)) 23: WAIT #139933626861888: nam='SQL*Net message from client' ela= 5463063 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=125087179008 24: CLOSE #139933626861888:c=23,e=23,dep=0,type=1,tim=125087179228
上記のトレースファイルの出力例に登場する、「PARSING IN CURSOR ～ END OF STMT」(1～3行目)と「STAT」(20行目)には下記の情報が含まれますが、処理過程の追跡という観点では、そこまで重要ではないため、以降では特に触れません。
調査する際のポイントに従い、トレースファイルの各ステップを開始時刻順に並べ替えると、DBサーバ側の処理過程は以下の図の様なイメージになります。なお、トレースファイルからはクライアント側の処理過程や処理時間はわからないため、図中のクライアントについては、DBサーバ側の処理/待機内容から想像して記載したものとなります。
SELECT文の処理過程を調査した際に、気づいた点について幾つか記載します。
FETCHの登場回数について
図では省略していますが、FETCHは6回登場しました。arraysizeを100,000件に設定して500,000件格納されたテーブルのSELECTなので、FETCHは500,000/100,000=5回と想定していましたが、実際は1回多い6回でした。
これは、SQL*Plusの製品仕様で発生するプリフェッチによるもので、1行だけしかフェッチされないFETCHが最初に1回発生することで、FETCH回数が1 + ceil( (500,000 - 1)/100,000 ) = 6回になったためです。
各FETCHステップでフェッチされた行数は、FETCHステップに出力されるr=の値で知ることができ、最初のFETCH(7行目)はr=1、2回目のFETCH(13行目)はr=100000、最後(6回目)のFETCH(19行目)はr=99999となっていることから、FETCH回数と取得レコード件数の辻褄が合うことがわかります。
FETCHに伴い発生する待機イベントについて
最初のFETCH(7行目)以外はFETCHの最中に待機イベント「SQL*Net message to client」と「SQL*Net more data to client」が発生しています。これらの待機イベントはクライアントへデータ転送している際に発生する待機イベント(最初のパケット転送時は「SQL*Net message to client」が、2番目以降は「SQL*Net more data to client」が発生)となります。最初のFETCHだけ待機イベントが発生していないのは、プリフェッチで1行だけしかフェッチされていないからではないかと想像しています。
また、各FETCHの後には、待機イベント「SQL*Net message from client」が必ず発生していました。このイベントはアイドルイベントで、DBサーバ側はクライアントから何らかのリクエスト等が送信されてくるのを(何もせず)待っている状態です。クライアント側でフェッチ結果を受信する処理が全て終わって、続きのデータ取得リクエストが到達するまで待っているのではないと想像しています。
CLOSEの出力タイミングについて
1つのSQLの最終ステップはCLOSEなのですが、実際にSQLトレースを取得してみたところ、最後のCLOSE(24行目)の直前に発生している待機イベント「SQL*Net message from client」(23行目)が、SQL終了時に即トレースファイルに出力されず、次のSQLが実行されたタイミングで出力されていました。偶然なのか仕様なのか、現在も調査中ですが、SQLトレースの開始→SQL実行→SQLトレースの終了を記載したSQLスクリプトを用意して実行すれば、「SQL*Net message from client」待機が余分に長くなるのを防ぎ、CLOSEがすぐ出力される様になるかと思います。
クライアントから見たSQLの処理時間について
クライアントから見たSQLの処理時間は、SQLを発行してから全ての結果が返ってくるまでの時間となります。これを測るためには、本来はクライアント側でSQL開始前と全結果受領後のタイミングでタイムスタンプを取得して差分をとる必要があります。
SQLトレースの出力から、この処理時間に近しい時間を取得したいのであれば、「CLOSEの終了時刻 - PARSEの開始時刻」で算出できますが、前述した様に、CLOSEの出力タイミングの問題があるため、実態と大きく乖離する可能性があります。
対象SQLの処理完了後にCLOSEを出力できていなかった場合は、SELECTに関してはCLOSEの代わりに、最後のFETCH(19行目)の終了時刻を用いて算出した方が、実際の処理時間より短くなってしまう可能性は高いですが、近しい処理時間が得られるかもしれません。
4. 調査例2: SQL*PlusからのUPDATE実行
次の調査例として、SQL*Plusから500,000件格納されているテーブルのうち1件をUPDATEしてcommitした際の処理過程を紹介します。
取得したトレースファイルに、説明用の行番号を付与したものが、以下となります。
1: PARSING IN CURSOR #139854623119160 len=44 dep=0 uid=17 oct=6 lid=17 tim=152722639363 hv=201891209 ad='7335bd90' sqlid='82c07ws60j7c9' 2: update tab01 set val = 666 where id = 200000 3: END OF STMT 4: PARSE #139854623119160:c=1926,e=2036,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2154050724,tim=152722639363 5: EXEC #139854623119160:c=12396,e=13645,p=0,cr=5203,cu=2,mis=0,r=1,dep=0,og=1,plh=2154050724,tim=152722653115 6: STAT #139854623119160 id=1 cnt=0 pid=0 pos=1 obj=1783 op='UPDATE TAB01 (cr=5203 pr=0 pw=0 str=1 time=13574 us)' 7: STAT #139854623119160 id=2 cnt=1 pid=1 pos=1 obj=1783 op='TABLE ACCESS FULL TAB01 (cr=5203 pr=0 pw=0 str=1 time=13285 us cost=1439 size=10 card=1)' 8: WAIT #139854623119160: nam='SQL*Net message to client' ela= 9 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=152722653517 9: 10: *** 2024-04-13T18:33:57.772030+09:00 (ORCLPDB(3)) 11: WAIT #139854623119160: nam='SQL*Net message from client' ela= 2646690 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=152725300270 12: CLOSE #139854623119160:c=29,e=28,dep=0,type=0,tim=152725300506 13: ===================== 14: PARSING IN CURSOR #139854619980864 len=6 dep=0 uid=17 oct=44 lid=17 tim=152725300836 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y' 15: commit 16: END OF STMT 17: PARSE #139854619980864:c=250,e=250,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=152725300836 18: XCTEND rlbk=0, rd_only=0, tim=152725300931 19: EXEC #139854619980864:c=138,e=139,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=152725301055 20: WAIT #139854619980864: nam='log file sync' ela= 628 buffer#=2859 sync scn=2300114 p3=0 obj#=-1 tim=152725301709 21: WAIT #139854619980864: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=152725301805 22: 23: *** 2024-04-13T18:34:14.083850+09:00 (ORCLPDB(3)) 24: WAIT #139854619980864: nam='SQL*Net message from client' ela= 16310275 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=152741612107 25: CLOSE #139854619980864:c=10,e=9,dep=0,type=1,tim=152741612265
SELECTと同様に、調査する際のポイントに従い、トレースファイルの各ステップを開始時刻順に並べ替えると、DBサーバ側の処理過程は以下の図の様なイメージになります。なお、トレースファイルからはクライアント側の処理過程や処理時間はわからないため、図中のクライアントについては、DBサーバ側の処理/待機内容から想像して記載したものとなります。
UPDATEの処理過程について、SELECTで気づいた点以外で新たに気づいた主な箇所は、COMMIT部分(14～25行目)になります。
COMMITの処理過程について
COMMITのEXEC(19行目)中にXCTEND(18行目)が発生していましたが、これはトランザクションの終了を表わすもので、XCTENDと共に出力されるrlbk=が0の場合はCOMMIT、1の場合はROLLBACKを表します。
また、COMMITを(ROLLBACKも)実行した際に、REDOログへの同期書込みが発生するため、待機イベント「log file sync」(20行目)も出現していました。
なお、CLOSE前の「SQL*Net message from client」の待機時間が長くなる(次のSQLが実行されるまで待機する)傾向は、SELECTのときと同様でした。
5.さいごに
SQLトレースを用いたSQL実行時の処理過程や処理時間の調査方法について紹介しましたが、1点注意しなければいけないのが、SQLトレースによるトレースファイル出力を行うと、SQLの処理時間自体がトレース情報出力処理によって遅くなる点です。
そのため、通常の実行時より処理時間が長い結果になったり、SQLトレースを有効にしたことで通常時は発生する/発生しない待機が存在する可能性もあったりするので、通常時とは完全一致しない点が存在する点を理解したうえで、調査の一手段として用いて頂ければと思います。
