あなたがデータベース管理者で、処理が遅い！とクレームが入ったらどうしますか？？
すぐにデータベースのSQLチューニングに取り掛かりたくなるかもしれませんが、まずは問題を正しく切り分ける必要があります。
遅い原因がデータベースではないところにあるのに、SQLチューニングを行っても効果がないからです。
本記事は、性能問題の切り分けにはそれほど詳しくない、Oracleデータベース管理者さん向けに書いています。
本記事によって性能問題を切り分けるために必要となる取得すべき情報を理解することができます。
少し難しい内容も含んでいますが、性能問題を切り分けるための参考になれば幸いです。
パフォーマンス遅延の考えられる要因
パフォーマンス遅延には、いろいろな種類があり、その種類によって行うべき対応が異なります。
可能な限りの情報採取と、その情報からの適切な分析を行うことで、どのような種類の遅延なのかを確認していく必要があります。
パフォーマンス遅延は、大きく分けて以下のような要因が考えられます。
- CPUやメモリなどのリソース不足
- ネットワークが遅い
- ディスクI/Oが遅い
- SQL文の実行計画の変化
- リソース競合（ラッチ、ロック）
- データ量の変化
- 不具合によるスピン/ループ/メモリリーク
- SQLそのものが適切でない
- SGA/PGA不足などの基盤設計的な問題
- 索引不足などの論理設計的な問題
状況によっては要因は一つとは限りませんし、一つの要因によって、さらに別の遅延を引き起こすこともありえます。
調査は以下の順序で行います。
- 遅延状況のヒアリングによる把握
- 資料採取
- 性能問題の調査/分析
パフォーマンス遅延状況のヒアリングによる把握
処理遅延に関しては、資料採取だけではわからないこともありますので、状況をヒアリングします。
ヒアリングで把握すべき確認ポイントは以下の通りです。
確認ポイント1：何が遅いのか
「遅い」と一言で言っても、その感覚は様々です。
よくあるのが、過去に実行されたことがない処理で、「処理が終わらない」とか「遅い」という場合です。
どのくらいの時間で処理が終わるか分からない状態で、「速い」とか「遅い」を判断することはできませんので、「遅い」と言われた場合には、過去に速かった実績があるのかなどのヒアリングが必要です。
初めて実行された処理なら、「速い」や「遅い」ではなく、掛かった時間をベースとして、パフォーマンスチューニングに取り組む必要があります。
ヒアリングした上で何が遅いのかを整理します。
- どのような処理か
- インスタンス起動、インスタンス停止、バッチ処理、オンラインのアプリケーションタイムアウト、接続できない、など。
- SQL文が特定できている場合は、そのSQL文。
- アプリケーションタイムアウトの場合はタイムアウトするまでの時間はどの程度なのか。
- 特定のSQL/プロシージャのみで発生しているのか。それともデータベース全体か。
- 接続できない場合
- NET経由のみか。BEQでの接続は可能か。
- as sysdbaでの接続もできないのか。
確認ポイント2：どこで遅いのか
- 特定のクライアントからの処理が遅いのか。全てのクライアントからの処理でも遅いのか。
- RAC環境の場合は、どのノードで発生しているか。全てのノードで発生しているのか。
確認ポイント3：時間軸での把握
- いつからいつまで発生していたか。具体的な日付と時刻を把握する。
- いつ解消したか。具体的な日付と時刻を把握する。
- 解消するにあたり実行したことはないか。それはいつ実行したか。具体的な時刻を把握する。
自然に解消したのか、処理をキャンセルしたのか、プロセスをkillしたのか、alter system kill sessionコマンドを実行したのか、インスタンス/OS再起動をしたのか… など
ヒアリング作業は非常に重要で、特に資料採取と突合する必要があります。
例えば、ヒアリング時にはインスタンスの再起動を実施したと言っていたのに、アラートログ上からは再起動が見れないといった場合もあります。
正確な回答がもらえないことや、誤った回答をもらうことも多々ありますので、ヒアリング内容についてはログからも裏付けを取るようにします。
疑いすぎも良くないですが、鵜呑みにしてしまうと事実と異なる状況から分析することになりますので、原因究明に時間が掛かってしまう可能性があります。
確認ポイント4：再現性
- 同じ処理は定期的に実行されるものなのかどうか。
- 同じ処理を実行したら常に遅いのか。
- 過去に速かった実績のある処理なのか。
- 速かった実績がある場合、それはいつか。（比較資料を採取/確認するため聞いておくこと）
- その時と遅延時は何が違うのか。
パフォーマンス遅延時の問題切り分けのために取得すべき情報
資料採取には、現象発生時にしか取れない資料と、後からでも取得可能な資料があります。
現象発生時に資料採取をしていなくても、後から取得可能な資料から調査が可能なことも多いです。
現象発生時の採取資料
- OS関連
- vmstat
- top
- ps -elf
- iostat
- netstat
- pstack（特定のプロセスの問題とわかっている場合）
- strace（特定のプロセスの問題とわかっている場合）
- Oracle関連
- SYSTEM STATE
- V$SESSIONおよびV$PROCESS
- ASH（V$ACTIVE_SESSION_HISTORY）
- ERRORSTACK （特定のプロセスの問題とわかっている場合）
OS関連の情報（vmstatやiostatなど）については、事象発生後に取得が困難な場合が多いので、
事前に定期的に取得するようにしておくと問題の切り分けがしやすくなります。
pstackやstraceは再現性が見られる場合には取得できますが、再現性がほとんど見られない場合は、取得が難しいかもしれません。
OS関連 / vmstat
vmstatは主にOS上のCPU使用率を確認するために取得します。
5秒間隔で情報を取得したい場合は「vmstat 5」を実行します。
# vmstat 5
procs --------------memory------------- ---swap-- -----io---- ---system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
:
0 1 18405516 14955400 312760 14437460 0 0 18138 175 38246 80417 3 3 91 3 0
0 1 18405516 14959052 312768 14439024 0 0 17570 1134 39299 80979 3 2 92 3 0
0 1 18405512 14927716 312804 14439356 0 0 19190 182 39432 82690 3 2 92 3 0
0 1 18405512 14931708 312820 14440120 0 0 15013 595 39013 81575 3 2 91 3 0
1 1 18405512 14911788 312832 14440456 0 0 18123 258 38681 81480 3 2 91 3 0
:主に確認すべきポイントとしては以下になります。
- r列：CPU割り当て待ちの数（run-queue）を示します。正常時は0あたりを推移しますが、CPU使用率が高い場合は、処理し切れなくなりますので、結果的にr列の値が増加してきます。この値が定常的に大きな値を示している場合は、CPU不足である可能性が高いです。
- si/so列：スワップ領域の使用状況を確認できます。メモリ上で処理できている場合は0ですが、この値が増加している場合は頻繁にスワップ処理が発生しており、メモリとディスク間でのI/Oが発生していることになります。結果的にパフォーマンス劣化が発生している可能性があります。
- ur/sy/id列：ur列はユーザのCPU使用率、sy列はシステムのCPU使用率、id列は空きCPU使用率を示します。CPU使用率が逼迫しているケーズでは、空きCPU使用率が0に近づいているはずです。ユーザのCPU使用率が100%となっている場合は、ユーザ側からの処理が追い付いていない状態となりますので、パフォーマンス劣化が発生している可能性があります。
OS関連 / top
topは主にはプロセス単位でのCPU使用率や具体的なコマンドを確認するために取得します。
5秒間隔で取得する場合は「top -b -d 5」を実行します。
topコマンドもpsコマンドも、特定プロセスのCPU使用率が高いことが見えてきたタイミングで確認するような流れになります。
# top -b -d 5
:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
347239 root 20 0 163012 7224 3708 R 40.7 0.0 0:00.22 top -b -d 5
347002 dbmsvc 20 0 108640 16552 13396 D 22.2 0.0 0:04.80 adrci racle/dbserver/dbms/bin/adrci script=/tmp/adrciPurge8470154110383242429.tmp
29608 oracle 20 0 1940284 49068 41720 S 7.4 0.0 1016:23 /u01/app/19.0.0.0/grid/bin/oraagent.bin
94999 oracle 20 0 20.7g 30260 29708 S 7.4 0.0 148:11.94 ora_o000_socstst012
137909 oracle 20 0 17.8g 63984 45208 S 7.4 0.0 539:05.76 ora_lms0_acdb2
1056 oracle -2 0 7022688 63352 59224 S 3.7 0.0 459:33.26 ora_vktm_emrepc
:主に確認すべきポイントとしては以下になります。
- PID列：プロセスIDを示します。V$SESSIONやV$PROCESSと紐づけるために必要になります。
- %CPU列：プロセスのCPU使用率です。処理遅延時にCPU使用率が高くなっているプロセスが存在しないかを確認し、COMMAND列からどのような処理なのかを確認します。Oracleデータベースのプロセス（バックグラウンドプロセス or サーバプロセス）なのか、全く別の処理がCPUを使っているのかを判断することができます。
- COMMAND列：実行されているコマンドを確認できます。
OS関連 / ps -elf
psも主にはプロセス単位でのCPU使用率や具体的なコマンドを確認するために取得します。
psコマンドでは定期的に実行するオプションはありませんので、シェルスクリプト化するなどで、定期的に取得可能です。
topコマンドもpsコマンドも、特定プロセスのCPU使用率が高いことが見えてきたタイミングで確認するような流れになります。
# ps -elf
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
4 S root 1 0 0 80 0 - 48191 ep_pol 2024 ? 07:23:16 /usr/lib/systemd/systemd --switched-root --system --deserialize 22
1 S root 2 0 0 80 0 - 0 kthrea 2024 ? 00:03:48 [kthreadd]
1 S root 3 2 0 80 0 - 0 smpboo 2024 ? 03:07:24 [ksoftirqd/0]
1 S root 5 2 0 60 -20 - 0 worker 2024 ? 00:00:00 [kworker/0:0H]
:主に確認すべきポイントとしては以下になります。
- PID列：プロセスIDを示します。V$SESSIONやV$PROCESSと紐づけるために必要になります。
- C列：プロセスのCPU使用率です。topコマンドと同様に、処理遅延時にCPU使用率が高くなっているプロセスが存在しないかを確認し、COMMAND列からどのような処理なのかを確認します。
- CMD列：実行されているコマンドを確認できます。
OS関連 / iostat
# iostat -t -x -p 5
avg-cpu: %user %nice %system %iowait %steal %idle
2.93 0.00 1.92 3.63 0.00 91.51
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 34.40 3834.00 69.80 15336.00 527.40 8.13 1.03 0.26 0.24 1.73 0.20 78.24
sda1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda3 0.00 34.40 3834.00 54.80 15336.00 527.40 8.16 1.03 0.27 0.24 2.20 0.20 78.24
:主に確認すべきポイントとしては以下になります。
- avgqu-sz/await列：avgqu-sz列は平均待ち行列長、await列はレスポンスタイムを示しています。平均待ち行列長(avgqu-sz)とレスポンスタイム(await)が大きくなっている場合は、I/O回数が増えて待ちが発生している状況と考えられます。
- avgrq-sz/svctm列：avgrq-sz列は平均I/Oサイズ、svctm列はサービスタイムを示しています。平均I/Oサイズ(avgrq-sz)があまり変化せず、サービスタイム(svctm)が大きくなっている場合は、I/O性能が劣化しているように見えるため、ストレージ（ハードウェア）に問題がある可能性があります。
- %util列：ディスクビジー率を示します。I/O負荷が高いと100%に近づくことになります。
OS関連 / netstat
netstatは主にはネットワークのパケット送受信量を確認するために確認します。
ここではインターフェース単位でのパケットエラーやパケットロスを5秒間隔で確認するため、「netstat -i 5」を実行します。
# netstat -i 5
Kernel Interface table
Iface MTU RX-OK RX-ERR RX-DRP RX-OVR TX-OK TX-ERR TX-DRP TX-OVR Flg
:
eth0 1500 58937027 0 0 0 56780895 0 0 0 BMRU
eth1 1500 116606737 0 0 0 23511357 0 0 0 BMsRU
eth2 1500 0 0 0 0 0 0 0 0 BMsU
lo 65536 1718426091 0 0 0 1718426091 0 0 0 LRU
:主に確認すべきポイントとしては以下になります。
- RX-ERR/RX-DRP列：これらの列は、受信時にエラーとなったパケット数、受信時に破棄したパケット数を示しています。これらの列の値は、正常時は0となっているべきですが、何らかの原因でこれらの値が増加している場合は、ネットワークとしてもどこかでパケットロスが発生している状態となります。パケットロスが発生すると、再送処理が行われるため、ネットワーク遅延に繋がります。
- TX-ERR/TX-DRP列：これらの列は、送信時にエラーとなったパケット数、送信時に破棄したパケット数を示していて、正常時は0となっているべきです。送信時のパケットロスとなるため、OSログにエラーが発生していないかや、ハードウェアに故障がないかを確認してみた方が良さそうです。
ネットワークが関連する遅延の場合は、ネットワーク経路の確認と、ネットワークのエンドポイント間で疎通に問題がないか、ボトルネックとなっている経路が存在しないかを確認してください。
例えば、APサーバ上での処理が遅いという場合でも、APサーバからデータベースに到達するまでに複数のルーター機器を経由しているケースでは、APサーバとルーター機器間のネットワーク遅延が原因となっていることも考えられます。
OS関連 / pstack（特定のプロセスの問題とわかっている場合）
pstackによって、現在のプロセスがどのような処理を実行しているかを確認することができます。
Oracleのセッション情報とOSPIDを結びつける方法は、こちらの記事を参考にしてください。
複数回を取得することで、プロセスが動いているのか、ハングしてしまっているのかを判断しやすくなります。
すべてのプロセスに対してpstackを取得することは現実的ではないため、topコマンドやpsコマンドから、ある程度プロセスが特定されている場合に取得します。
# pstack 91635
#0 0x00007f0e6ffea6e0 in __read_nocancel () from /lib64/libpthread.so.0
#1 0x0000000012ff4e64 in read ()
#2 0x0000000012fedfec in sntpread ()
#3 0x0000000012fede8e in ntpfprd ()
#4 0x0000000012fd6aef in nsbasic_brc ()
#5 0x0000000012fdf726 in nioqrc ()
#6 0x0000000012b708a7 in opikndf2 ()
#7 0x000000000283a80e in opitsk ()
#8 0x000000000283f548 in opiino ()
#9 0x0000000012b73412 in opiodr ()
#10 0x0000000002836966 in opidrv ()
#11 0x00000000033c1155 in sou2o ()
#12 0x0000000000dccde6 in opimai_real ()
#13 0x00000000033ccbf1 in ssthrdmain ()
#14 0x0000000000dccc10 in main ()OS関連 / strace（特定のプロセスの問題とわかっている場合）
straceによって、現在のプロセスの処理状況を追うことができます。
pstackはある時点でのプロセスの処理状況（call stack）を把握できることに対して、straceはプロセスの処理そのものを追い続けることができることです。
以下の出力例にあるように、あるシステムコールでどのくらい時間が掛かっているかなども把握できますので、どこで処理遅延が発生しているかや、どのような処理で発生しているのかの概要を掴める可能性があります。
# strace -tt -T -p 91635 ★OSPIDを指定
strace: Process 91635 attached
17:42:46.194958 read(13, "\0\0\1\212\6\0\0\0\0\0\21i\25\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0\0\1\0\0"..., 8208) = 394 <4.753796>
17:42:50.948968 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 85997}, ru_stime={0, 23723}, ...}) = 0 <0.000023>
17:42:50.949151 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 86059}, ru_stime={0, 23740}, ...}) = 0 <0.000026>
17:42:50.949252 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 86083}, ru_stime={0, 23747}, ...}) = 0 <0.000018>
17:42:50.949441 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 86186}, ru_stime={0, 23775}, ...}) = 0 <0.000020>
17:42:50.950242 write(10, "Wed Apr 2 17:42:50 2024 +09:00\n", 32) = 32 <0.000049>
17:42:50.950347 write(10, "LENGTH : '296'", 14) = 14 <0.000026>
17:42:50.950421 write(10, "\n", 1) = 1 <0.000027>
17:42:50.950497 write(10, "ACTION :[33] 'select distinct si"..., 295) = 295 <0.000020>
:
^Cstrace: Process 91635 detached
<detached ...>
#Oracle関連 / SYSTEM STATE
SYSTEM STATEからは、情報取得したタイミングでのOracleデータベース内のすべてのセッション情報を確認することができます。
Oracleデータベース全体がハング、または、スローダウンしている状況を分析するために、複数回のSYSTEM STATE情報を取得することで、原因を分析しやすくなります。
SYSTEM STATEの取得例は以下になります。
SQL> conn / as sysdba
SQL> alter session set events 'immediate trace name systemstate level 266';
※10秒ぐらい待機する
SQL> alter session set events 'immediate trace name systemstate level 266';
※10秒ぐらい待機する
SQL> alter session set events 'immediate trace name systemstate level 266';SYSTEM STATEから確認できる主な情報は以下です。
複数回取得することで、short stackが変化しているかを確認することができます。
変化していれば何らかの処理が実行されていることを確認できますし、変化していなければハングしているか、単純に待機しているだけということを判断できます。
- セッションの状態
- short stack（Oracle関数での現在の処理状況）
- library cache lock、row cache lock、cursor mutex などの保持状況
- 保持されているカーソル情報
- セッションの待機イベントの履歴
- RAC環境の場合はリソースダンプ
SYSTEM STATE (level=10, with short stacks)
:
PROCESS 73:
----------------------------------------
SO: 0x1dbec1d20, type: process (2), map: 0x1dc4e0d80
state: LIVE (0x4532), flags: 0x1
:
(process) Oracle pid:73, ser:435, calls cur/top: 0x19e599e10/0x19e599e10 ★プロセス情報
:
Process Group: DEFAULT, pseudo proc: 0x1dc75eeb8
O/S info: user: oracle, term: UNKNOWN, ospid: 91635
OSD pid info:
Short stack dump:
ksedsts()+426<-ksdxfstk()+58<-ksdxdocmdmultex()+6054<-ksdxdocmdmult()+55<-ksudmp_proc()+1681<-ksudss_main()+2993<-ksudss_opt()+2140<-dbkdaKsdActDriver()+2492<-dbgdaExecuteAction()+354<-dbgdaRunAction()+770<-dbgdRunActions()+83<-dbgdParseCmd()+3674<-dbkdParseCmd()+602<-kkyase()+15670<-kksExecuteCommand()+3751<-opiexe()+51820<-kpoal8()+2226<-opiodr()+1202<-ttcpip()+1218<-opitsk()+1900<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
:
(session) sid: 69 ser: 61993 trans: (nil), creator: 0x1dc4e0d80 ★セッション情報
flags: (0x41) USR/- flags2: (0x40009) -/-/INC
:
Current Wait Stack:
Not in wait; last wait ended 0.028648 sec ago ★待機状況（No in waitは待機が発生していないことを示す）
:Oracle関連 / V$SESSIONおよびV$PROCESS
事象発生時には定期的にV$SESSIONやV$PROCESSを取得しておくことをおすすめします。
取得した時点での、Oracleデータベース内のすべてのセッション情報とプロセス情報を取得することができます。
こちらも複数回取得することで、各セッションや各プロセスの遷移を把握することができます。
Oracle関連 / ASH（V$ACTIVE_SESSION_HISTORY）
ASH（V$ACTIVE_SESSION_HISTORY）は、アクティブなセッションの履歴を1秒間隔で確認できる情報です。
CPUを使っているセッション、または、何らかの待機が発生しているセッションの情報を1秒間隔で追跡することができますので、時系列での調査がしやすくなります。
ブロックしているセッションやブロックされているセッションも分かりますので、ブロッカーとなるセッションを辿ることで、遅延の原因となっているセッションを特定できる場合もあります。
注意点としては、CPUも使用しておらず、待機も何も発生していないアイドルのセッションの情報は出力されないということです。こういったセッションが根本原因となっている場合は、ASHだけでは原因特定が難しいということになります。
ASHには非常に多くの情報が格納されていますので、必要な情報のみを取得する必要があります。
情報取得のためのサンプルを示します。WHERE句のsample_timeには事象発生時の期間を含むようにします。
SQL> set lines 400 pages 300
SQL> col sid format 999999999
SQL> col serial# format 9999999999
SQL> col bsid format 9999999999
SQL> col bserial# format 9999999999
SQL> col bsid_state format a20
SQL> col sample_time format a20
SQL> col event format a30
SQL> col module format a50
SQL> col program format a50
SQL> select to_char(sample_time, 'YYYY-MM-DD HH24:MI:SS') sample_time, session_id sid, session_serial# serial#, seq#, session_state,
event, program, module, blocking_session bsid, blocking_session_serial# bserial#, blocking_session_status bsid_state
from v$active_session_history
where sample_time > to_timestamp('2025-03-30 12:00','YYYY-MM-DD HH24:MI')
and sample_time < to_timestamp('2025-03-30 18:00','YYYY-MM-DD HH24:MI')
order by sample_time;
SAMPLE_TIME SID SERIAL# SEQ# SESSION_STATE EVENT PROGRAM MODULE BSID BSERIAL# BSID_STATE
-------------------- ---------- ----------- ---------- --------------------- ------------------------------ -------------------------------------------------- -------------------------------------------------- ----------- ----------- --------------------
2025-03-30 12:00:52 460 18960 60112 WAITING Sync ASM rebalance oracle@host01 (M003) MMON_SLAVE UNKNOWN
2025-03-30 12:00:53 1172 15582 9773 WAITING log file parallel write oracle@host01 (LG00) NO HOLDER
2025-03-30 12:00:53 460 18960 60140 ON CPU oracle@host01 (M003) MMON_SLAVE NOT IN WAIT
2025-03-30 12:00:54 460 18960 60555 ON CPU oracle@host01 (M003) MMON_SLAVE NOT IN WAIT
2025-03-30 12:01:25 261 52446 15490 ON CPU oracle@host01 (PSP0) NOT IN WAIT
:RAC環境の場合は、GV$表から情報を取得することで、全インスタンスの情報を一度に取得することができます。
GV$表を利用する場合、inst_id列やblocking_inst_id列を含めないと、どのインスタンス上でのセッションか分からなくなりますので注意してください。
SQL> select to_char(sample_time, 'YYYY-MM-DD HH24:MI:SS') sample_time, inst_id, session_id sid, session_serial# serial#, seq#, session_state,
event, program, module, blocking_inst_id binst_id, blocking_session bsid, blocking_session_serial# bserial#, blocking_session_status bsid_state
from gv$active_session_history
where sample_time > to_timestamp('2025-03-30 12:00','YYYY-MM-DD HH24:MI')
and sample_time < to_timestamp('2025-03-30 18:00','YYYY-MM-DD HH24:MI')
order by sample_time;Oracle関連 / ERRORSTACK （特定のプロセスの問題とわかっている場合）
pstackと同様な情報取得方法として、ERRORSTACKを取得する方法があります。
こちらもpstackと同様に、Oracle上でのプロセスがどのような処理状況かを確認するために利用します。
複数回の情報を取得することで、処理がハングしているのか、進んでいるのかを判断できる可能性があります。
SQL> conn / as sysdba
SQL> oradebug setospid 188300 ★OSPIDを指定
SQL> oradebug unlimit
SQL> oradebug dump errorstack 3
※10秒ぐらい待機する
SQL> oradebug dump errorstack 3
※10秒ぐらい待機する
SQL> oradebug dump errorstack 3トレースファイルにERRORSTACK情報が出力されます。
*** 2024-04-02T21:06:47.135463+09:00 (CDB$ROOT(1))
Processing Oradebug command 'dump errorstack 3'
*** 2024-04-02T21:06:47.186270+09:00 (CDB$ROOT(1))
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
----- SQL Statement (None) -----
Current SQL information unavailable - no cursor.
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
*** 2024-04-02T21:06:48.138398+09:00 (CDB$ROOT(1))
ksedst1()+95 call kgdsdst() 7FFF962DC230 000000002
7FFF962D6570 ? 7FFF962D6688 ?
000000000 000000082 ?
:現象発生後でも取得可能な資料
- クライアント関連
- お客様のアプリケーションが遅いなどの状況であればアプリケーションのログ
- sqlnet.log
- OS関連
- OSログ（/var/log/messages）
- Oracle関連
- アラートログ
- トレースファイル
- AWRレポート
- AWR SQLレポート
- ASH（Active Session History）
- リスナーログ
- その他の情報
クライアント関連 / アプリケーションログ
アプリケーションの処理が遅い場合は取得を依頼します。
どこまで詳細なログが出力されているかは、アプリケーションの作りに依存しますが、タイムスタンプとあわせて処理内容まで確認することができると、その他の資料との突合がしやすくなります。
まれにタイムスタンプがデータベース側と合っていない（タイムゾーンが異なっていたり、単純に時刻ずれていたり）場合がありますので注意します。
クライアント関連 / sqlnet.log
Oracle Clientを利用している場合には、何らかのエラー時に（運よく）sqlnet.logが出力されている可能性があります。
sqlnet.logは、主にOracleのネットワーク関連でエラーが発生した場合に出力されるログですが、パフォーマンス遅延との関連性が見えたりする場合がありますので、sqlnet.logが出力されていないか、ローカルディスクを全検索してみてください。
Fatal NI connect error 12541, connecting to:
(DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=c1db)(CID=(PROGRAM=sqlplus)(HOST=host01)(USER=oracle)))(ADDRESS=(PROTOCOL=tcp)(HOST=127.0.0.1)(PORT=1521)))
VERSION INFORMATION:
TNS for Linux: Version 19.0.0.0.0 - Production
TCP/IP NT Protocol Adapter for Linux: Version 19.0.0.0.0 - Production
Version 19.14.0.0.0
Time: 09-12月-2024 18:44:09
Tracing not turned on.
Tns error struct:
ns main err code: 12541
TNS-12541: TNS: リスナーがありません。
ns secondary err code: 12560
nt main err code: 511
TNS-00511: リスナーがありません。
nt secondary err code: 111
nt OS err code: 0OS関連 / OSログ（/var/log/messages）
事象発生時間帯のOSログから、OS上で何か問題が発生しないか、OS再起動などの特徴的な処理が行われていないかを確認することも重要です。
ハードウェア系のエラーなどが検知されている場合もありますので、問題を切り分ける際には確認すべき情報です。
Oracle関連 / アラートログ
データベースの診断情報としては一番最初に確認すべきログです。
事象発生時間帯に以下のような特徴的な出力がないかを確認します。
- ORAエラーが発生していないか
- トレースファイルが出力されていないか
- ログスイッチが頻繁に行われていないか
- インスタンス再起動が行われいないか
RAC環境の場合はすべてのノードのアラートログを確認してください。
Oracle関連 / トレースファイル
Oracleデータベースでは様々な診断情報をトレースファイルに出力しています。
アラートログに出力されているトレースファイルを確認して、調査のヒントにできる場合があります。
まれに、アラートログにも出力されていない情報が調査に有用になるケースもありますので、事象発生時の時間帯の出力を含むトレースファイルは保管しておきます。
トレースファイルは追記書きされると更新時刻がアップデートされますので、事象発生時間帯以降の全てのトレースファイルを保管しておくようにしてください。
RAC環境の場合はすべてのノードのトレースファイルを確認してください。
Oracle関連 / AWRレポート
AWRレポートは、Oracleデータベース全体のワークロードを1時間単位で確認できる情報です。
データベース全体の負荷状況を確認するために有用な情報となります。
具体的には以下の情報を確認することができます。
- CPUの使用状況
- SGA/PGAの使用状況
- 待機イベントの状況
- 時間の掛かっているSQL文
- 実行回数が多いSQL文
デフォルトでは過去8日間のワークロードを確認することができますが、8日間では短い場合もありますので、こちらの期間を延ばしておく場合もあります。
Oracle関連 / AWR SQLレポート
特定のSQL文に対して、実行状況（データ件数など）や実行計画を確認することができます。
こちらは、パフォーマンス遅延が発生しているSQL文を特定できた場合に取得することで、ボトルネックの分析に役立ちます。
こちらもデフォルトで過去8日間の情報を保持していますので、遅かった時と速かった時の情報が残っていれば、実行状況や実行計画を比較することができます。
Oracle関連 / ASH（Active Session History）
使い方は「Oracle関連 / ASH（V$ACTIVE_SESSION_HISTORY）」と同様です。
DBA_HIST_ACTIVE_SESS_HISTORYというディクショナリを利用します。
V$ACTIVE_SESSION_HISTORYとの違いは、10秒毎にサンプリングされた内容が格納されているという点です。
10秒毎のセッション情報となるため、例えば10秒以内に終わるような処理の場合は、情報としては残っていない場合があります。
情報の正確性としてはV$ACTIVE_SESSION_HISTORYの方が優れていますが、デフォルトでは過去8日間の情報を保持していますので、過去に遡って確認したいケースではこちらを利用します。
Oracle関連 / リスナーログ
リスナーログは新規接続が遅いといった事象の場合に確認します。
主には、事象発生時の時間帯で何らかのエラーが発生していないかや、特定の時間帯に大量の新規接続が行われていないかなど確認することで問題を切り分けます。
1秒間に数百といった大量の新規接続があった場合は、サーバプロセスの生成に時間が掛かることが想定されますので、結果的に処理遅延になっているケースもあります。
まとめ
本記事では性能問題を切り分けるために必要となる取得について説明しました。
Oracleでは現象発生後でも取得可能な資料が多く存在しています。
これらを使ってパフォーマンス遅延の分析に役立てることができます。
コメント