Oracle Database Connect 2018 エキスパートはどう考えるか？ 体感！パフォーマンスチューニング Ⅱ （番外編＝没ネタ） Tweet
これ、パフォーマンスチューニングネタをまとめ上げるまで、みなさんスケジュール調整し、
オンライン／オフラインミーティングを繰り返してネタを詰めていくという、かなーり面倒なことをやっています。
私なんて、ネタの候補検討だけで16時間ぐらい使ってますからねw（自分の余暇を使って、半分楽しみながら、締め切りがあるので半分苦しみながらw）
余談はこれくらいにして、今日の本題です。:)
Oracle Database Connect 2018 エキスパートはどう考えるか？ 体感！パフォーマンスチューニング Ⅱ で没にしたネタがあるのですが、
そのまま捨てるのも勿体ないので、多少取得情報を追加した状態で公開しちゃおうと思います。
お時間のありますときに、頭の体操、AWRレポートの解析方法（最近はADDM、ASHレポートまで含まれています）のトレーニングにどうぞ。
遅延原因の想定と、想定原因の特定情報は、このエントリでは公開しません。おそらくGW開けの12日あたりか、その一週間後の19日ごろには原因を公開しようかと:)の後半に追記してあります:)
なお、本ページに公開した情報以外に、追加で見たい情報がある場合は、コメント欄やtwのmentionで具体的にリクエストいただければ、取得されている情報の範囲内で追加公開します。取得されてない情報はその旨を追記していきます。:)
まずは、エスパー力全開で、原因を想定してみてください。>
(かなり難易度高めだとは思いますが、過去この状況に遭遇した経験をお持ちのかたは、ここに公開した程度の情報から勘で言い当てたりしちゃうんですよね。実は、昨年末に、何年か振りでこの症状を目にしたのでネタにしよう思いました。)
以下取得された情報は以下のとおり。以下の情報を元に遅延原因を想定してみてください。
なーんでだ？！
状況説明
試験時には問題のなかった処理（30分以内に終了する状態が正常な状態です。）をリリースしました。
ところが、30分以上経過しても終了しません。遅延原因を想定、特定してください。
なお、本番環境のメンテナンス時間中に試験を行ったため、データベースインスタンス内で試験を行いリリースしています。
ちなみに、試験時の処理時間は、約21分でしたが、リリース時は約56分と大幅に遅延。
他のトランザクションが走行している状況をミックスするとより
本物っぽくなり、特定に苦労するので面白いのですが、
遅延している処理だけが走行している状況にしてあります。
資料1 試験時（正常時）AWRレポート
資料2 リリース時（遅延時）AWRレポート
資料3 試験時（正常時）とリリース時（遅延時）のAWR DIFFレポート
資料4 試験時（正常時）CPU利用率グラフ(調査による多少のノイズあり）
資料5 リリース時（遅延時）CPU利用率グラグ(スパイク部分調査による多少のノイズあり）
GWも後半スタート、天気は少々荒れそうですが、みなさん、よいGWを！
Twitterでのやり取り....
ここまでくるとなにかが見えてきたかな。。。原因を特定するまであと一歩な感じ。
追加資料1（遅延時）
top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13058 oracle 20 0 10.434g 365704 359548 R 100.0 1.4 1:05.70 oracle_13058_or
5973 oracle 20 0 1955632 253648 73812 S 4.7 1.0 1:42.62 gnome-shell
4657 oracle -2 0 10.417g 58792 55660 S 2.0 0.2 0:12.15 ora_vktm_orcl12
1285 root 20 0 483544 76000 21372 S 1.7 0.3 0:55.11 Xorg
4862 oracle 20 0 10.417g 68960 65868 S 1.3 0.3 0:01.23 ora_lg00_orcl12
223 root 20 0 0 0 0 S 0.7 0.0 0:00.49 kworker/u24:3
13059 oracle 20 0 157976 4564 3544 R 0.7 0.0 0:00.29 top
...略...
追加資料2（遅延時）
sar -P ALL
...略...
02:47:29 AM CPU %user %nice %system %iowait %steal %idle
02:47:34 AM all 4.78 0.00 2.36 0.07 0.00 92.80
02:47:34 AM 0 1.06 0.00 1.06 0.85 0.00 97.03
02:47:34 AM 1 0.20 0.00 0.40 0.00 0.00 99.40
02:47:34 AM 2 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 3 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 4 0.00 0.00 0.20 0.00 0.00 99.80
02:47:34 AM 5 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 6 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 7 68.08 0.00 31.92 0.00 0.00 0.00
02:47:34 AM 8 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 9 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 10 0.00 0.00 0.00 0.00 0.00 100.00
02:47:34 AM 11 0.00 0.00 0.20 0.20 0.00 99.60
...略...
追加資料3（遅延時）
perf top -C 7
Samples: 107K of event 'cpu-clock', Event count (approx.): 29550214790
Overhead Shared Object Symbol
4.36% libc-2.17.so [.] vfprintf
2.77% oracle [.] lxoCpStr
2.00% [kernel] [k] __radix_tree_lookup
1.94% oracle [.] dbgfcsIlcsGetNextDef
1.58% oracle [.] skgovprint
1.48% [kernel] [k] __do_softirq
1.44% [kernel] [k] selinux_file_permission
1.43% oracle [.] dbgaFmtAttrCb_int
1.36% [kernel] [k] system_call_after_swapgs
1.33% oracle [.] dbgaAttrFmtProcArg
1.26% oracle [.] dbgtfmWriteMetadata
1.13% oracle [.] dbgtfdFileWrite
1.02% libc-2.17.so [.] _IO_default_xsputn
...略...
その後のやりとり （Twitter）
そして核心に迫る追加資料が...あったんです。（しばちょうさん風にはしづらかったw）
正常時（試験時）の追加情報はないようです。リリース後は常に遅いらしい。
ふむふむ。
以下、遅延時のstrace -c -pの情報を取得してもらいました。
straceで眺めるとsystem call write()がダントツで上位にきています。その次が lseek()
追加資料4
strace -c -p
[oracle@localhost ˜]$ sudo strace -c -p 13058
Process 13058 attached
^CProcess 13058 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
77.24 47.883538 1 35085592 write
19.22 11.913638 1 17542850 lseek
3.53 2.191099 1 3414889 getrusage
0.01 0.006377 12 524 semop
0.00 0.000403 7 62 close
0.00 0.000210 4 54 chown
0.00 0.000126 2 63 open
0.00 0.000099 2 54 lstat
0.00 0.000050 1 54 chmod
0.00 0.000029 1 54 stat
0.00 0.000028 3 10 semtimedop
0.00 0.000015 0 54 fcntl
0.00 0.000010 1 8 read
0.00 0.000007 1 8 select
0.00 0.000000 0 3 mmap
0.00 0.000000 0 6 rt_sigprocmask
0.00 0.000000 0 1 rt_sigreturn
0.00 0.000000 0 1 readlink
------ ----------- ----------- --------- --------- ----------------
100.00 61.995629 56044287 total
そろそろ突き止めた感が。
なにかを、どこかに、書き出してますよね。
lsofで書き込みに絞って取得してもった結果は以下のとおり。
[root@localhost ˜]# lsof -p 13058 | grep -E '[0-9]+w'
oracle_13 13058 oracle 1w CHR 1,3 0t0 1038 /dev/null
oracle_13 13058 oracle 2w CHR 1,3 0t0 1038 /dev/null
oracle_13 13058 oracle 7w REG 8,17 2351882843 71176413 /u01/app/oracle/diag/rdbms/orcl12c/orcl12c/trace/orcl12c_ora_13058.trc
oracle_13 13058 oracle 8w REG 8,17 358606101 71176414 /u01/app/oracle/diag/rdbms/orcl12c/orcl12c/trace/orcl12c_ora_13058.trm
ほう。 .trcファイルへ大量の書き込みがあります。
このようになるときは、 なにが起っていると思いますか？
.trcファイルに大量の書き込みのあるケースとして、SQLトレースが有効になっている場合です。（意図したSQLトレースなら問題はないですが...意図していない場合はちょいと問題ですよね。）
ということで、確定診断に移りましょう。
SQL*Plus: Release 12.2.0.1.0 Production on Wed Apr 25 01:23:13 2018
Copyright (c) 1982, 2016, Oracle. All rights reserved.
Connected.
ORCL@SYSTEM>
ORCL@SYSTEM> select username,status,event,sql_trace from v$session where paddr = (select addr from v$process where spid = 13058)
USERNAME STATUS EVENT SQL_TRAC
------------------------------ -------- ---------------------------------------------------------------- --------
SCOTT ACTIVE log file switch completion ENABLED
見ての通り、
SQL_TRACE列がdisabled（デフォルト)からenabledに変わっていることから、.trcファイルへの大量の書き出しは、セッションレベルでSQLトレースが有効化されたため、と言えますよね。
今回の新規リリースバッチ処理遅延の原因は、
SQLトレースを有効化したままリリースしたしまったことにより、オーバーヘッドが発生し、グルグル系バッチ処理のスループットが低下したため！
ということでした。SQLトレースを利用したあとの無効化をお忘れなく！ :)
SQLトレースは便利な機能の一つですが、インスタンスレベルやグルグル系バッチ処理での利用時は大量のトレース情報の書き出し等によるオーバーヘッドが発生します。
便利なツールではありますが、スループットの低下等による影響を考慮して利用するタイプのツールでもあります。
また、利用した後は、必ず、無効化することもお忘れなく...
ミイラ取りがミイラになってしまってはいみないですから.....ね :)
| 固定リンク | 0
トラックバック
この記事へのトラックバック一覧です： Oracle Database Connect 2018 エキスパートはどう考えるか？ 体感！パフォーマンスチューニング Ⅱ （番外編＝没ネタ）:
コメント