掲載元 2012年11/12月

テクノロジー：チューニング

パフォーマンス・チューニング入門：過去を診断

Oracle Databaseのパフォーマンス問題の診断を一歩進める。

Oracle Magazine 2012年7/8月号の"パフォーマンス・チューニング入門"では、Oracle Databaseのパフォーマンス問題の基本的な診断方法を紹介しました。この記事では、パフォーマンス・チューニングを一歩進め、パターンを特定したり、リソース使用状況を測定する方法を紹介します。前回の記事の場合と同様に、この記事の例はセットアップ・スクリプト（setup.sql）を実行して作成できます。

過去の待機時間

"パフォーマンス・チューニング入門"で説明したように、動作の遅いセッションが現在待機しているイベントが何なのかをV$SESSIONビューで確認すれば、セッションが遅い理由を突き止められます。問題が発生しているときにこのビューを見ることができる場合はこのテクニックが有効ですが、セッションの応答時間が長くなったことがあったが現在は正常な状態に戻っているとユーザーから報告があった場合はどうでしょうか。すでに問題は解消しているため、STATE列の値はWAITED KNOWN TIMEと表示され、セッションは生産的に動作しているように見える可能性があります。おまけに、V$SESSIONビューに表示される現在の待機イベントは、ユーザーが以前に遭遇した問題とは関係ないものである可能性があります。この問題を診断するには、セッションが現在待機しているイベントではなく、過去に待機する必要があったイベントすべてを知る必要があります。この情報の取得にはどれほど手間がかかるのでしょうか。

幸い、たいした手間ではありません。V$SESSION_EVENTという別のビューがあり、このビューにはこれまでセッションが待機したすべての待機イベントの詳細が表示されます。このビューで重要な列は次のとおりです。 

• SID：セッションID

• EVENT：セッションが待機したイベントの名前

• TOTAL_WAITS：セッションがその待機イベントを待機せざるをえなかった回数の合計

• TIME_WAITED：セッションがそのイベントを待機せざるをえなかった時間の長さの合計をセンチ秒（cs：100分の1秒）単位で記録した値

• AVERAGE_WAIT：セッションがそのイベントを待機していた時間の長さの平均値（センチ秒単位）

• MAX_WAIT：セッションがそのイベントを待機していた時間の長さの最大値（センチ秒単位） 

例を使ってビューの使い方を確認しましょう。"テスト・ケースのセットアップ"の説明に従って、例をセットアップしておいてください。Oracle DatabaseインスタンスにARUPで接続し、test1.sqlスクリプトを実行します。スクリプトも"テスト・ケースのセットアップ"より入手可能です。（スクリプトが完了するまで少し時間がかかります。）このスクリプトを実行している間に、別のセッションからSYSで接続し、次のコマンドを実行してARUPセッションのSIDを検索します。 

select sid from v$session 
where username = 'ARUP';
 
 SID
—————
  37

次に、リスト1のスクリプトを実行して、SID 37のセッション・イベントを表示します。V$SESSION_EVENT列は値の単位がセンチ秒であるため、センチ秒よりは馴染みのあるミリ秒（ms）単位で表示されるように値を10倍にしました。出力結果をよく見てみましょう。ここには、現在セッションが待機しているイベントではなく、過去に待機していたさまざまなイベントが表示されています。セッションが、"kfk: async disk IO"という1つのイベントを待機していたことがわかります。セッションはこのイベントを904,818回待機しましたが、待機していた時間の合計はわずか3,050ミリ秒です。平均待機時間は0（ゼロ）と表示されていますが、平均待機時間が短すぎて小数点以下2桁以内で表示できなかっただけです。つまり、このイベントを待機した回数の合計は多いのですが、セッション全体の時間に追加されたのはわずか3,050ミリ秒と、微々たる数値です。したがって、この待機イベントはセッションの遅延の原因から除外できます。 

コード・リスト1：特定のセッションで発生した待機イベントの履歴 

set lines 120 trimspool on
col event head "Waited for" format a30
col total_waits head "Total|Waits" format 999,999
col tw_ms head "Waited|for (ms)" format 999,999.99
col aw_ms head "Average|Wait (ms)" format 999,999.99
col mw_ms head "Max|Wait (ms)" format 999,999.99
select event, total_waits, time_waited*10 tw_ms,
       average_wait*10 aw_ms, max_wait*10 mw_ms
from v$session_event
where sid = 37
/
                                  Total      Waited     Average         Max
Waited for                        Waits    for (ms)   Wait (ms)   Wait (ms)

—————————————————————————— ————————————  ———————————  ——————————  —————————
Disk file operations I/O              8         .00         .10         .00
KSV master wait                       2      350.00      173.20      340.00
os thread startup                     1       20.00       19.30       20.00
db file sequential read               5      160.00       32.10       70.00
direct path read                  1,521   51,010.00       33.50      120.00
direct path read temp           463,035  513,810.00        1.10      120.00
direct path write temp               20      370.00       18.70       50.00
resmgr:cpu quantum                   21      520.00       24.60      110.00
utl_file I/O                          8         .00         .00         .00
SQL*Net message to client            20         .00         .00         .00
SQL*Net message from client          20    9,620.00      481.20    9,619.00
kfk: async disk IO              904,818    3,050.00         .00         .00
events in waitclass Other            35       20.00         .70       20.00

この場合は、セッションをもっとも長く待機させる原因となったイベントに注目する必要があります。リスト1の出力結果から、セッション37（SID = 37）は"direct path read temp"イベントを513,810ミリ秒（8.5分以上）待機していたことがわかります。セッションがこのイベントを待機するたびに、平均で1.1ミリ秒の待機が発生していたため、このイベントの待機時間を短縮できれば、セッション全体の時間を短縮できます。セッションのイベント履歴を見れば、現在セッションに影響を与えているものなのか、過去に影響を与えたものなのかに関係なく、セッションの遅延を引き起こす最大の原因を突き止めることができます。

最大待機時間を表す列、"Max Wait (ms)"に気付いたでしょうか。なぜこの情報が役立つのでしょうか。ご存知のとおり、平均待機時間を見ても全体を把握することはできません。リスト1の出力結果にある"SQL*Net message from client"イベントを検討してみましょう。セッションはこのイベントを20回待機し、平均待機時間は481ミリ秒でした。これは、20回発生した待機に毎回約481ミリ秒の時間が費やされたことを意味するのでしょうか。それとも、ほとんどのイベント・インスタンスの待機時間は非常に短かったが、ある1回のイベントにのみ非常に長い待機時間が費やされたことを意味するのでしょうか。後者の場合は平均が高い値に偏りますが、永続的な問題というよりも単独の問題があることを意味します。つまり、2つの可能性から大きく異なる結論が導き出されるのです。

"Max Wait (ms)"列は、このイベントの1回の待機にセッションが費やさざるをえなかった最大時間を表します。このケースでの値は9,619ミリ秒ですが、合計待機時間が9,620ミリ秒であるため、このセッションは1回の待機に9,619ミリ秒を費やし、残りの1ミリ秒はほかの19回分の待機時間の合算値のようです。つまり、毎回の待機時間は極めて短いと考えられます。長時間の待機が発生したのが1回であることを考慮すると、このイベントは問題の一般的な原因ではないはずです。これに対し、最大時間と平均時間がほぼ同じになっているイベントがあれば、すべての待機でほぼ同じ長さの時間を費やす必要があったと推測できます。そのような場合は、イベントに費やされる時間を短縮することですべての待機の時間が一様に短縮され、結果として経過時間全体の短縮につながる可能性があります。

V$SESSION_EVENTビューには、セッションが過去に待機していたのがどのイベントだったかは表示されますが、いつ待機していたかは表示されません。この情報は、V$ACTIVE_SESSION_HISTORYというもう1つのビュー（別途ライセンスが必要なOracle Diagnostics Packの一部）で表示できます。ただし、このビューについて、この記事では説明しません。

統計情報

セッション遅延の原因を把握する上では待機イベントが大いに役立ちますが、セッションのもう1つの重要な属性であるCPU、I/O、メモリなどのリソース使用状況については知ることはできません。リソース消費量の多いセッションは他のセッションから同じリソースを奪うため、パフォーマンスの問題が発生します。セッションのCPU消費量が多すぎることが問題の主因である場合は、待機の対象になっているイベントではなく、セッション別のリソース消費量を調べる必要があります。幸い、この情報を見つけるのはいたって簡単で、V$SESSTATという名前のビューで表示できます。このビューには次の3つの列があります。 

• SID：セッションID

• STATISTIC#：取得している統計情報のID（統計情報の名前はV$STATNAMEという別のビューのNAME列から取得できます。問合せにはこのIDを使用します）

• VALUE：統計情報の値 

あるパフォーマンス問題の例を使用して、この情報の使用方法を説明します。

CPUスパイク

パフォーマンスが全体的に著しく低下していると、複数のユーザーから言われたとします。また、UNIXシステム管理者からは、サーバーのCPUとメモリの消費量が両方とも非常に高くなっており、消費の大半はOracle Databaseのプロセスによるものであると報告を受けたとします。よく聞く話ではないでしょうか。私の経験によると、これはOracle Databaseシステムで2番目に多いパフォーマンス問題です。この問題は、ユーザーARUPでtest1.sqlスクリプトを実行して再現できます。スクリプトはこの記事のスクリプト例に含まれています。

このリソース問題を診断するには、UNIXのコマンド・プロンプトでtopコマンドを発行し、リソース消費量がもっとも多いプロセスを確認します。リスト2はtopコマンドの出力結果です。 

コード・リスト2：topコマンドの出力結果 

top - 10:56:49 up 18 days, 18:48, 4 users, load average:1.02, 0.92, 0.48 
Tasks:180 total, 2 running, 178 sleeping, 0 stopped, 0 zombie
Cpu(s):49.8%us, 0.5%sy, 0.0%ni, 49.2%id, 0.5%wa, 0.0%hi, 0.0%si, 0.0%st
Mem:1815256k total, 1771772k used, 43484k free, 66120k buffers 
Swap:2031608k total, 734380k used, 1297228k free, 747740k cached 
 
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 5946 oracle    25   0  706m 177m 159m R  100 10.0   9:20.26 oracle
 6104 oracle    15   0  2324 1060  800 R    1  0.1   0:00.12 top
31446 oracle    15   0  688m 135m 129m S    0  7.7   0:08.24 oracle
… 出力結果は省略されています …  

リスト2の出力結果を見ると、ID 5946のプロセスがCPU（100%）とメモリ（10%）をもっとも消費しているため、このプロセスを重点的に調査する必要があることがわかります。プロセスの詳細情報を確認するには、UNIXのプロンプトから次のコマンドを入力します。 

$ ps -aef|grep 5946

oracle    5946  5945 63 10:59 ?
00:01:52 oracleD112D2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

出力結果にはこのプロセスの情報がすべて表示されます。このプロセスは明らかにOracleの"サーバー・プロセス"（セッションが確立されたときにOracle Databaseによって作成されたプロセス）であり、1分52秒間実行され続けています。では、次の質問です。このプロセスはどのOracle Databaseセッションのために作成されたのでしょうか。これを確認するには、V$PROCESSという別のビューを調査する必要があります。このビューのSPID列がサーバー・プロセスIDです。ただし、このビューにはセッションの情報が表示されないため、次に示すように、このビューとおなじみのV$SESSIONビューとを結合する必要があります。 

select sid
from v$session s, v$process p
where p.spid = 5946
and s.paddr = p.addr;

SID

———
37

SIDがわかれば、セッションを確立したユーザー、接続元のマシン、オペレーティング・システム・ユーザー、実行中のSQLなど、セッションに関して把握すべきあらゆる情報をV$SESSIONビューから取得できます。情報取得に使用するこのスクリプトは、Oracle Magazine 2012年7/8月号の"パフォーマンス・チューニング入門"のリスト5に記載されています。セッション37が実行しているSQLを検索するには、次の問合せを使用します。 

select sql_fulltext
from v$sql l, v$session s
where s.sid = 37
and l.sql_id = s.sql_id;

出力結果は次のようになります。 

select max(test1.owner)
from test1, test2, test2, test2,
     test2, test2, test2, test2,
     test2, test2, test2, test2,
     test2, test2, test2, test2,
     test2, test2, test2, test2,
     test2, test2, test2, test2;

このSQLは複数のデカルト結合を実行しているため、これほど多くのCPUとメモリが消費されていても不思議ではありません。

これで問題の原因が見つかったわけですが、単にセッションを終了してCPUの消費をやめさせるだけでよいのでしょうか。ところが、そう簡単には終わりません。まず、CPUの大量消費が最近のことなのか、最初から消費し続けているのかを知る必要があります。ここでとても役立つのがV$SESSTATビューです。このビューには、特定のセッションによるリソース消費量（今回のケースではCPU）が表示されます。セッション37が使用しているCPUを検索するには、次の問合せを使用します。 

select s.value
from v$sesstat s, v$statname n
where s.sid = 37
and n.statistic# = s.statistic#
and n.name = 'CPU used by this session';

VALUE
—————
47379

この出力結果には、このセッションが開始以降に消費したCPU"ティック"数が表示されます。このセッションの実行時間が約2分間であることを考慮すると、CPU消費量はかなり多いため、このセッションは常にCPUを消費し続けてきた可能性があります。ここでも、実行中のSQLなど、セッションの他の詳細を確認すると、このような事態（必然的にCPUを大量消費する複数表のデカルト結合がセッションで実行されている状態）に陥っている理由をかなり容易に理解することができます。ここまでわかれば、CPUの大量消費を止めるためにセッションを終了する決断を下してもよいでしょう。あるいは、デカルト積の作成を回避するために、ひとまず実行を続け、後でSQLを修正することにしてもよいでしょう。

すべての統計情報

現在発生している問題を再検討するために、次の問合せを使用してCPU消費量をもう一度確認しましょう。 

select s.valuez
from v$sesstat s, v$statname n
where s.sid = 37
and n.statistic# = s.statistic#
and n.name = 'CPU used by this session';

VALUE
—————
69724

問合せ結果（CPU使用量）は69,724です。この値は、前回CPU使用量を確認したときの値（47,379）より大きくなっています。なぜなら、統計値は時間の経過とともに増加するためです。最初にCPU使用量を確認したとき、複数表のデカルト積が原因でCPU消費量が多くなっていると推測しましたが、証明することはできるのでしょうか。これには、「はい、他の統計情報を使用して証明できます」ときっぱり答えられます。

リスト3は、セッション37のすべての統計情報を収集するための問合せです。統計情報"table scan rows gotten"の値を出力結果で確認すると、1.0236E+10と表示されています。約100億行です。1つのセッションが2分間にアクセスした行数として、これは確かに非常に大きい値です。統計情報"consistent gets"の値は25,898,543で、約2,590万ブロックがバッファ・キャッシュから読み取られています。バッファ取得の数値が高いということは、相当量のCPUが占有されています。

コード・リスト3：すべてのセッション統計情報 

select name, value
from v$sesstat s, v$statname n
where sid = 37
and n.statistic# = s.statistic#
order by value desc
/

NAME                                        VALUE
———————————————————————————————   ———————————————
table scan rows gotten                 1.0236E+10
session logical reads                    25898547
consistent gets                          25898543
table scan blocks gotten                 25325165
session pga memory max                   21250020
session pga memory                       21250020
session uga memory max                   20156552
session uga memory                       20156552
bytes sent via SQL*Net to client           878760
recursive calls                            576848
opened cursors cumulative                  143367
parse count (total)                        143292
parse count (hard)                         143118
table scans (short tables)                 143086
sql area evicted                           141996
DB time                                     70007
CPU used by this session                    69724
… 出力結果は省略されています …

CPUが大量消費されているもう1つの原因は、SQL文の解析です。リスト3の出力結果には、統計情報"parse count (total)"が143,292と、かなり高い数値が示されています。簡単に言うと、セッションは約2分間でこれだけ多くの回数、単にSQL文を実行するのではなく解析する必要もあったことになり、極めて異常な事態です。セッションで実行されたSQL文（"テスト・ケースのセットアップ"のtest2.sqlスクリプト）を調査してみましょう。別々のリテラルSQL文が作成されていることがわかります。それぞれのリテラルSQL文に解析が必要ですが、それは解析カウントを調べて確認してあります。したがって、リスト3の出力結果から、このセッションのCPU使用率が高くなっている原因は、バッファ取得数が多いことと解析数が多いことの2つであると推測できます。

リスト3では、他の2つの統計情報"session pga memory max"と"session uga memory max"も確認します。これは、セッションが消費したメモリ量の合計を示します。先ほど、オペレーティング・システムのtopコマンドの出力結果で確認した、Oracleのサーバー・プロセスによる大量のメモリ消費は、この非常に高い数値で説明がつきます。サーバーのCPU消費量とメモリ消費量を減らす必要がある場合は、セッションが発行するSQL文を適切に修正し、これらのリソースがセッションに消費される量を少なくする必要があります。

REDOの急増

CPUやメモリの消費量ほどOSレベルにはっきりと表れないパフォーマンスの問題が発生することもあります。そのようなケースの1つが、データベース・インスタンスによるREDOの生成です。これによってREDOログの急な切替え、およびアーカイブ・ログの作成率と作成数の両方が増加します。これによりファイル・システム（またはOracle Automatic Storage Managementのディスク・グループ）の全体的なI/Oが増加し、システム全体のパフォーマンス問題が発生する可能性があります。この種の問題を軽減するには、大量のREDOが生成される原因となったセッション（1つまたは複数）を特定する必要があります。ところが、OSメトリックを見ても問題を引き起こしているセッションに関する情報は得られません。このケースでは、ほとんどの負荷の原因となっているセッション、つまりREDOをもっとも多く生成しているセッションを調べる必要があります。この情報も、同じV$SESSTATビューから極めて簡単に入手できます。次の問合せは、生成しているREDOの多い順にセッションを表示します。 

select sid, value
from v$sesstat s, v$statname n
where n.statistic# = s.statistic#
and n.name = 'redo size'
order by value desc;

 SID     VALUE
————  ————————

 13   11982752
 10    3372240
 17     964912
 26     571324
… 出力結果は省略されています …

この出力結果から、SID 13がもっとも多くのREDOを生成し、後にSID 10などが続いていることがはっきりします。

REDOを生成しているSQL文の検索方法はサイドバーのセットアップで説明されています。また、置き換えるSQL文の提供、新しいSQL文を使用したREDO生成のテストもここで行っています。

その他の統計情報

• physical reads：ディスクから取得されたデータベース・ブロックの数

• db block changes：セッション中に変更されたデータベース・ブロックの数

• bytes sent via SQL*Net to client：ネットワーク経由でクライアントから受信したバイト数（クライアントからのデータ通信量を判定するときに使用されます） 

これらは、V$SESSTATビューから入手できる604の有用な統計情報のほんの一部に過ぎません。それらを1つずつ説明することはできませんが、セッションで使用されるさまざまなリソースの確認とパフォーマンス問題の原因の絞り込みに統計情報を使用する方法の概要はつかんでいただけたのではないでしょうか。（V$SYSSTATという別のビューもあり、このビューではインスタンス全体の統計情報が表示されます。）

結論

この記事では、パフォーマンス・チューニングに使用できるOracle Databaseの2つの重要な情報源、（1）セッションで発生した待機イベントの履歴（V$SESSION_EVENTで表示可能）と、（2）セッション別のリソース消費量（V$SESSTATで表示可能）について学習しました。履歴からは、セッションが過去に待機していた理由と待機した時間の長さがわかり、すでに問題が解消しているときにパフォーマンスの問題を診断するのに非常に役立ちます。リソースの統計情報には、CPU、メモリ、REDOなどのさまざまなリソースの消費量が特定のセッション別に表示されるため、リソース消費量の多いセッションの絞り込みに非常に役立ちます。この記事で紹介したこれら2つのビューとスクリプトを使用すれば、Oracle Databaseインスタンスで発生する多くのパフォーマンス問題を解決できます。それでは、楽しいチューニングを。

-- Script: setup.sql

connect sys/<password> as sysdba

create user arup identified by arup
default tablespace users
/
alter user arup quota unlimited on users
/ 
-- now connect as arup
connect arup/arup
-- drop the tables if present already
drop table test1
/
drop table test2
/
drop table test3
/
create table test1 
as
select * from all_objects
/
create table test2
as
select * from test1
/
create table test3
as
select rownum, created
from test3
/

-- Script test1.sql

declare
    l_dummy varchar2(200);
begin
    select max(test1.owner)
    into l_dummy
    from test1, test2, test2, test2, test2,
        test2, test2, test2, test2,
        test2, test2, test2, test2,
        test2, test2, test2, test2,
        test2, test2, test2, test2,
        test2, test2, test2, test2;
    dbms_lock.sleep(120);
end;
/

-- Script test2.sql

declare
    l_dummy_1   varchar2(2000);
    l_dummy_2   varchar2(2000);
    l_stmt      varchar2(2000);
begin
    for i in 1..71540 loop
        l_stmt :=
            ‘select to_char(col2,’’mm/dd/yyyy hh24:mi:ss’’)’||
            ‘ from test3’||
            ‘ where col1 = to_char(‘||i||’)’;
        dbms_output.put_line(‘l_stmt=’||l_stmt);
        execute immediate l_stmt into l_dummy_1;
        l_stmt :=
            ‘select col1 ‘||
            ‘from test3 ‘||
            ‘where col2 = to_date(‘’’||
            l_dummy_1||
            ‘’’,’’mm/dd/yyyy hh24:mi:ss’’)’||
            ‘ and col1 = ‘’’||to_char(i)||’’’’;
        dbms_output.put_line(‘l_stmt=’||l_stmt);
        execute immediate l_stmt into l_dummy_2;
    end loop;
end;
/

Part 1. パフォーマンス・チューニング入門
Part 2. パフォーマンス・チューニング入門：過去を診断
Part 3. パフォーマンス・チューニング入門：アクティブ・セッション履歴