fulltime.sh by Craig Shallahamer で DB CPU の内訳を調べる

• 2012年（zusaar.com -&nbspzusaar リソースおよび情報）
• 2013年（zusaar.com -&nbspzusaar リソースおよび情報）

に続き、今年で3年目を迎えた
JPOUG Advent Calendar 2014の2日目です。

1日目は sakita さんの 12.1.0.2 Zone Maps 入門 Part II でした。

Oracle Database のパフォーマンス分析の大家 Craig Shallahamer の fulltime.sh を紹介します。
使用感はこんな感じです。

少し脱線すると、Craig は Oracle Corp.で Method R で有名な Cary Millsap と System Performance Group (SPG) を立ち上げた人で、現在は OraPub という会社を作って、書籍出版、セミナー、講演などで世界中を飛び回っているようです。一番書きたかった（=オススメ）のは彼が考えた Oracle Database の性能分析手法 "ORTA (Oracle Response Time Analysis)" ですが、Oracle Performance Firefighting を読んで勉強中なので、興味のある方は新久保さんが3年前に書かれた 10046 trace name context forever: IOUG (Collaborate11) in Florida 4th をご覧ください。
Craig は Oracle Database 界隈以外でも影響があるらしく、High Performance MySQL の著者でもある Baron Schwartz が Craig のもう1冊の著書 Forecasting Oracle Performanceのレビューを書いていたりします。Craig のスライドを見ていると Sun のパフォーマンスチームの影響を受けているようです。小田さんや Brendan Gregg も間接的または直接的に Sun のパフォーマンスチームの影響を受けていると思います。Sun のパフォーマンスチームは後世に与えた影響は大きいなと思う今日このごろです。

Craig のことはJPOUG運営メンバーで集まった時の帰り道に新久保さんに教えてもらって知ったのですが*1、今年の11月に http://www.insight-tec.com/dbts-tokyo-2014.html でお会いすることができ、Oracle Performance Firefighting にサインをもらいました。

「シンプルでシステマチックなLinux性能分析方法」 @ db tech showcase 東京 2014 - ablog

脱線はこのへんにして fulltime.sh を紹介します。
fulltime.sh は Oracle Database on Linux で、特定セッションの処理時間の内訳を表示するシェルスクリプトです。
このスクリプトのすごいところは待機イベント別の待機時間以外に CPU 時間の内訳を perf コマンドで取得して、待機時間と一緒にCPU時間の内訳を表示してくれるところです。
perf コマンドは本番環境でがしがし実行するようなものではないので、試してみたい方は自分の遊び用環境などで使ってみてください。

使用手順例

• root 以外でも perf を使えるようにする

[root@localhost ~]# echo 0 > /proc/sys/kernel/perf_event_paranoid
[root@localhost ~]# cat /proc/sys/kernel/perf_event_paranoid
0

• fulltime.sh でモニタ対象とするセッションを作り、SQLを実行する

[oracle@localhost ~]$ sqlplus /nolog

SQL*Plus: Release 12.1.0.2.0 Production on Tue Dec 2 03:05:03 2014

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

SQL> conn sys/oracle as sysdba
Connected.
SQL> select s.sid, s.serial#, p.spid from v$session s, v$process p where p.addr = s.paddr and s.sid = sys_context('USERENV','SID');

       SID    SERIAL# SPID
---------- ---------- ------------------------
       273	18604 3609

SQL> select sum(object_id) from all_objects;

• fulltime.sh でセッションをモニタリングする

[oracle@localhost ~]$ sh ./fulltime.sh 3609 10 999

Welcome to the FULLTIME script (v3e)

To see wait time details AND Oracle kernel function CPU details TOGETHER

Use at your own and your organization's risk!

If unable to execute perf, do as root:
   echo 0 > /proc/sys/kernel/perf_event_paranoid

The perf sample method is set to: -e cycles
Use cpu-clock for virtualised hosts, cycles for physical hosts

Command line arguments are:

ospid  : 3609
delay  : 10
cycles : 999

Gathering next 10 second sample...

Fulltime.sh v3e

PID: 3609  SID: 273  SERIAL: 18604  USERNAME: SYS  at 02-Dec-2014 03:10:59
CURRENT SQL: select sum(object_id) from all_objects


total time: 12.763 secs,  CPU: .307 secs (2.41%),  wait: 12.456 secs (97.59%)

                                                                   Time
Time Component                                                     secs       %
------------------------------------------------------------ ---------- -------
wait: SQL*Net message from client                                12.456   97.59
cpu : [?] sum of funcs consuming less than 2% of CPU time         0.134    1.05
cpu : [.] 0x0000000000000998                                      0.120     .94
cpu : [.] __intel_ssse3_memcpy                                    0.009     .07
cpu : [.] expepr                                                  0.009     .07
cpu : [.] kdstf11001010000000km                                   0.008     .06
cpu : [.] _intel_fast_memcmp                                      0.007     .05
cpu : [.] kxhrHash                                                0.007     .05
cpu : [.] kxhrPUcompare                                           0.007     .05
cpu : [.] kcbgtcr                                                 0.006     .05

                                                                   Time
Time Component                                                     secs       %
------------------------------------------------------------ ---------- -------
wait: Disk file operations I/O                                    0.000     .00
wait: SQL*Net message to client                                   0.000     .00

To see the Call Graph, press ENTER or to exit press CNTRL-C.
Samples remaining: 993
Gathering next 10 second sample...
^C

Thanks for using FULLTIME v3e!

To see the latest Call Graph, press ENTER or to exit press CNTRL-C.

The Call Graph file is callgraph.txt

とこんな感じです。

もっと詳しく知りたい方へ

• A  Wider View : BLOG HAS MOVED *HERE*: Creating A Tool: Detailing Oracle Process CPU Consumption

fulltime.sh 入手方法

• http://resources.orapub.com/Fulltime_sh_Report_Oracle_Wait_and_CPU_Details_p/fulltime-sh.htm から "To download click here" をクリックします。
• Email と First Name を記入して "Press if you love OraPub!" をクリックします。
• Download File をクリックしてダウンロードします。

検証に使った環境

• VirtualBox(4.3.18) に Developer Day - Hands-on Database Application Development をインポートして検証に使用しました。
  • Oracle Linux 7
  • Oracle Database 12c Release 1 Enterprise Edition (12.1.0.2 with In-Memory Option)

関連

• Oracle Database や OS の性能統計情報と財務諸表の共通点 - ablog
• Linux で I/Oサイズを調べる方法 - ablog

明日は 2年連続で Oracle Database on Hyper-V ネタを書かれている charade_oo4o さんです。楽しみですね。

*1:彼のブログ A  Wider View : BLOG HAS MOVED *HERE* やライブラリキャッシュ可視化ツールやバッファキャッシュ可視化ツールはそれ以前から知っていましたが、彼のバックグラウンドなどは新久保さんにお話を聞くまで知りませんでした