データベースのパフォーマンスって？
データベースの性能を評価する指標は多々あります。IBM Db2ならMONREPORT.DBSUMMARYをcallすると指定した単位時間で以下のようなパフォーマンスサマリーを取得できます。
Db2 V11.5 Windows と Windows Server 2016で確認しています。
MONREPORT.DBSUMMARY （左の三角を下にすると展開します）
MONREPORT.DBSUMMARY
TEXT
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
Monitoring report - database summary
--------------------------------------------------------------------------------
Database: APIUS01
Generated: 2014-04-22 16:55:10
Interval monitored: 300
================================================================================
Part 1 - System performance
Work volume and throughput
--------------------------------------------------------------------------------
Per second Total
--------------------- -----------------------
TOTAL_APP_COMMITS 0 18
ACT_COMPLETED_TOTAL 2 704
APP_RQSTS_COMPLETED_TOTAL 4 1416
TOTAL_CPU_TIME = 1232404
TOTAL_CPU_TIME per request = 870
Row processing
ROWS_READ/ROWS_RETURNED = 3 (7327/2069)
ROWS_MODIFIED = 0
Wait times
--------------------------------------------------------------------------------
-- Wait time as a percentage of elapsed time --
% Wait time/Total time
--- ----------------------------------
For requests 0 1469/306835
For activities 0 509/301763
-- Time waiting for next client request --
CLIENT_IDLE_WAIT_TIME = 302078
CLIENT_IDLE_WAIT_TIME per second = 1006
-- Detailed breakdown of TOTAL_WAIT_TIME --
% Total
--- ---------------------------------------------
TOTAL_WAIT_TIME 100 1469
I/O wait time
POOL_READ_TIME 33 487
POOL_WRITE_TIME 0 0
DIRECT_READ_TIME 14 220
DIRECT_WRITE_TIME 0 0
LOG_DISK_WAIT_TIME 0 0
LOCK_WAIT_TIME 0 0
AGENT_WAIT_TIME 0 0
Network and FCM
TCPIP_SEND_WAIT_TIME 0 0
TCPIP_RECV_WAIT_TIME 0 0
IPC_SEND_WAIT_TIME 0 7
IPC_RECV_WAIT_TIME 0 3
FCM_SEND_WAIT_TIME 0 0
FCM_RECV_WAIT_TIME 0 0
WLM_QUEUE_TIME_TOTAL 0 0
CF_WAIT_TIME 0 0
RECLAIM_WAIT_TIME 0 0
SMP_RECLAIM_WAIT_TIME 0 0
Component times
--------------------------------------------------------------------------------
-- Detailed breakdown of processing time --
% Total
---------------- --------------------------
Total processing 100 305366
Section execution
TOTAL_SECTION_PROC_TIME 0 511
TOTAL_SECTION_SORT_PROC_TIME 0 9
Compile
TOTAL_COMPILE_PROC_TIME 0 990
TOTAL_IMPLICIT_COMPILE_PROC_TIME 0 0
Transaction end processing
TOTAL_COMMIT_PROC_TIME 0 1
TOTAL_ROLLBACK_PROC_TIME 0 0
Utilities
TOTAL_RUNSTATS_PROC_TIME 0 0
TOTAL_REORGS_PROC_TIME 0 0
TOTAL_LOAD_PROC_TIME 0 0
Buffer pool
--------------------------------------------------------------------------------
Buffer pool hit ratios
Type Ratio Reads (Logical/Physical)
--------------- --------------- ----------------------------------------------
Data 95 6243/297
Index 95 2782/139
XDA 0 0/0
Temp data 0 0/0
Temp index 0 0/0
Temp XDA 0 0/0
GBP Data 0 (0 - 0)/0
GBP Index 0 (0 - 0)/0
GBP XDA 0 (0 - 0)/0
LBP Data 98 (6717 - 589)/(6243 + 0)
LBP Index 95 (2643 - 0)/(2782 + 0)
LBP XDA 0 (0 - 0)/(0 + 0)
I/O
--------------------------------------------------------------------------------
Buffer pool writes
POOL_DATA_WRITES = 0
POOL_XDA_WRITES = 0
POOL_INDEX_WRITES = 0
Direct I/O
DIRECT_READS = 1600
DIRECT_READ_REQS = 102
DIRECT_WRITES = 0
DIRECT_WRITE_REQS = 0
Log I/O
LOG_DISK_WAITS_TOTAL = 0
Locking
--------------------------------------------------------------------------------
Per activity Total
------------------------------ ----------------------
LOCK_WAIT_TIME 0 0
LOCK_WAITS 0 0
LOCK_TIMEOUTS 0 0
DEADLOCKS 0 0
LOCK_ESCALS 0 0
Routines
--------------------------------------------------------------------------------
Per activity Total
------------------------ ------------------------
TOTAL_ROUTINE_INVOCATIONS 0 237
TOTAL_ROUTINE_TIME 427 301090
TOTAL_ROUTINE_TIME per invocation = 1270
Sort
--------------------------------------------------------------------------------
TOTAL_SORTS = 12
SORT_OVERFLOWS = 0
POST_THRESHOLD_SORTS = 0
POST_SHRTHRESHOLD_SORTS = 0
Network
--------------------------------------------------------------------------------
Communications with remote clients
TCPIP_SEND_VOLUME per send = 0 (0/0)
TCPIP_RECV_VOLUME per receive = 0 (0/0)
Communications with local clients
IPC_SEND_VOLUME per send = 363 (503863/1387)
IPC_RECV_VOLUME per receive = 129 (178817/1382)
Fast communications manager
FCM_SEND_VOLUME per send = 0 (0/0)
FCM_RECV_VOLUME per receive = 0 (0/0)
Other
--------------------------------------------------------------------------------
Compilation
TOTAL_COMPILATIONS = 32
PKG_CACHE_INSERTS = 42
PKG_CACHE_LOOKUPS = 484
Catalog cache
CAT_CACHE_INSERTS = 60
CAT_CACHE_LOOKUPS = 701
Transaction processing
TOTAL_APP_COMMITS = 18
INT_COMMITS = 6
TOTAL_APP_ROLLBACKS = 9
INT_ROLLBACKS = 0
Log buffer
NUM_LOG_BUFFER_FULL = 0
Activities aborted/rejected
ACT_ABORTED_TOTAL = 0
ACT_REJECTED_TOTAL = 0
Workload management controls
WLM_QUEUE_ASSIGNMENTS_TOTAL = 0
WLM_QUEUE_TIME_TOTAL = 0
DB2 utility operations
--------------------------------------------------------------------------------
TOTAL_RUNSTATS = 0
TOTAL_REORGS = 0
TOTAL_LOADS = 0
================================================================================
Part 2 - Application performance drill down
Application performance database-wide
--------------------------------------------------------------------------------
TOTAL_CPU_TIME TOTAL_ TOTAL_APP_ ROWS_READ +
per request WAIT_TIME % COMMITS ROWS_MODIFIED
---------------------- ----------- ------------- ----------------------------
870 0 18 7327
Application performance by connection
--------------------------------------------------------------------------------
APPLICATION_ TOTAL_CPU_TIME TOTAL_ TOTAL_APP_ ROWS_READ +
HANDLE per request WAIT_TIME % COMMITS ROWS_MODIFIED
------------- ------------------- ----------- ------------- -------------
7 26832 20 2 1179
18 31200 0 0 75
Application performance by service class
--------------------------------------------------------------------------------
SERVICE_ TOTAL_CPU_TIME TOTAL_ TOTAL_APP_ ROWS_READ +
CLASS_ID per request WAIT_TIME % COMMITS ROWS_MODIFIED
-------- ------------------- ----------- ------------- -------------
11 0 0 0 0
12 264 29 12 5907
13 15326 0 6 1420
Application performance by workload
--------------------------------------------------------------------------------
WORKLOAD_ TOTAL_CPU_TIME TOTAL_ TOTAL_APP_ ROWS_READ +
NAME per request WAIT_TIME % COMMITS ROWS_MODIFIED
------------- ---------------------- ----------- ------------- -------------
SYSDEFAULTADM 0 0 0 0
SYSDEFAULTUSE 16483 0 6 1420
================================================================================
Part 3 - Member level information
- I/O wait time is
(POOL_READ_TIME + POOL_WRITE_TIME + DIRECT_READ_TIME + DIRECT_WRITE_TIME).
TOTAL_CPU_TIME TOTAL_ RQSTS_COMPLETED_ I/O
MEMBER per request WAIT_TIME % TOTAL wait time
------ ---------------------- ----------- ---------------- -----------------
0 870 0 1416 1072
236 レコードが選択されました。
リターン状況 = 0
どうでしょう、ピンときたでしょうか。私はピンときません。だから、なに？と言った感じです。データベースの専門家が見れば、わかるのでしょうが第三者に説明しずらいです。もっと、パッと見て素人でも納得感のある性能情報を取れないものでしょうか。
何を知りたいのか
そもそも、パフォーマンスの何を測れば、納得感があるのでしょうか。私は何を知りたいのでしょうか。Webアプリケーションに代表されるトランザクション処理ならターンアラウンドタイム、つまり、応答時間が重要な性能指標です。そう考えるとデータベースならSQLの応答時間であれば、しっくりきます。SQL平均応答時間が時系列に並べば良いのでは！ イメージはこんな感じです。
5分単位にSQL平均応答時間とSQL実行回数を表示
DATE TIME SQL_AVG_TIME ACT_COMPLETED_TOTAL ACT_COMPLETED_TOTAL TOTAL_ACT_TIME TOTAL_CPU_TIME TOTAL_WAIT_TIME TOTAL_COMPILE_TIME LOCK_WAIT_TIME POOL_READ_TIME POOL_WRITE_TIME LOG_DISK_WAIT_TIME
---------- -------- ---------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- --------------------
2021-03-12 08:00:03 0.234 ** 108233 25408 105640625 17179 69812 531 5463 822 4461
2021-03-12 08:05:03 0.194 ** 118817 23116 66125000 12627 31142 185 10924 2657 1930
2021-03-12 08:10:03 0.212 *** 166159 35345 90171875 23356 43337 409 14279 1098 2871
2021-03-12 08:15:03 0.293 ** 134872 39606 88343750 23271 42726 190 14007 1634 2095
2021-03-12 08:20:03 0.232 ***** 255068 59385 164921875 30765 83400 691 22087 1923 2729
2021-03-12 08:25:03 0.227 ***** 286130 65114 168203125 35558 80317 1146 22880 1890 2964
2021-03-12 08:30:03 0.218 ***** 261607 57188 172671875 29156 88775 1653 14065 2831 3581
2021-03-12 08:35:03 0.261 ******** 405944 106021 260015625 59630 133654 1088 43014 2995 4471
2021-03-12 08:40:03 0.212 ********* 473994 100602 305921875 56576 160269 2480 29064 4887 7094
2021-03-12 08:45:03 0.231 ********* 460303 106767 299125000 61996 158771 1695 33690 4293 5636
2021-03-12 08:50:03 0.211 ********** 512336 108549 329015625 62329 180038 2668 30417 5011 7070
2021-03-12 08:55:03 0.289 ********* 465219 134581 347390625 86306 199397 1762 55881 4914 8315
5分単位でSQL平均応答時間(SQL_AVG_TIME)とSQL実行回数(ACT_COMPLETED_TOTAL)を表示しています。午前8時のSQL平均応答時間は0.234ミリ秒でSQL実行回数は108,233回という具合です。SQL実行回数は量をイメージしやすいように棒グラフでも表示しています。
SQL平均応答時間の計算方法
Db2ですとモニター表関数でMON_GET_DATABASEを実行するとパフォーマンスに関する指標を取得できます。その中にある TOTAL_ACT_TIME を ACT_COMPLETED_TOTAL で割るとSQL平均応答時間を求めることができます。
SQL平均応答時間(ミリ秒) ＝ TOTAL_ACT_TIME ÷ ACT_COMPLETED_TOTAL
| モニター・エレメント | 内容 | 単位 |
|---|---|---|
| TOTAL_ACT_TIME | SQL総実行時間 | ミリ秒 |
| ACT_COMPLETED_TOTAL | SQL実行回数 | 回 |
こちらについての詳細な情報はIBMのウェブサイトをご覧ください。
Db2 を「見える化」するためのモニタリング運用
※IBMのコンテンツが移行中のためリンク切れしている可能性があります(2021-03-22)。
性能情報を記録する
モニター表関数で取得できる指標の値はデータベースが開始してからの積算、つまり、その時点での総合計です。単位時間ごとに推移を見たいのであれば、単位時間ごとに値を記録する必要があります。ここでは記録用のテーブルをcreateし、モニター表関数の値をinsertするSQLを用意、Windowsのタスクスケジューラに登録します。
1.記録用のテーブルをcreateするDDL
create_mon_get_db.ddl
create table mon_get_db (
ts,
act_completed_total,
total_act_time,
total_cpu_time,
total_wait_time,
total_compile_time,
lock_wait_time,
pool_read_time,
pool_write_time,
log_disk_wait_time
) as (
select current timestamp,
act_completed_total,
total_act_time,
total_cpu_time,
total_wait_time,
total_compile_time,
lock_wait_time,
pool_read_time,
pool_write_time,
log_disk_wait_time
from table(mon_get_database(-2)))
with no data in USERSPACE1 ;
create index idx_mon_get_db_1 on mon_get_db
(ts asc) allow reverse scans ;
Db2コマンド・ウィンドウからテーブルをcreateします。
db2 -tvf create_mon_get_db.ddl
2.モニター表関数の値をinsertするSQL
insert_mon_get_db_mydatabase.sql
connect to mydatabase user db2admin using mypassword ;
INSERT INTO mon_get_db
select current timestamp,
act_completed_total,
total_act_time,
total_cpu_time,
total_wait_time,
total_compile_time,
lock_wait_time,
pool_read_time,
pool_write_time,
log_disk_wait_time
from table(mon_get_database(-2)) ;
connect reset ;
接続するデータベースとユーザー、パスワードを環境に合わせて編集してください。
3.SQLを実行するバッチファイル
insert_mon_get_db_mydatabase.bat
D:\SQLLIB\BIN\db2cmd /w /c /i "db2 -tvf D:\my_task\sqlavg\insert_mon_get_db_mydatabase.sql"
このバッチファイルを単位時間（例では5分）ごとに実行するよう、タスクスケジューラに登録します。登録はPowershellで行うと簡単です。
4.タスクスケジューラに登録するPowershell
タスク登録.ps1
Param([String]$password)
$taskname = "mydatabaseモニター表関数"
$action = New-ScheduledTaskAction -Execute "D:\my_task\sqlavg\insert_mon_get_db_mydatabase.bat"
$trigger = New-ScheduledTaskTrigger -DaysInterval 1 -Daily -At "00:55:00"
$user = "Administrator"
$Task = Register-ScheduledTask -TaskPath \ -TaskName $taskname -Action $action -Trigger $trigger -User $user -Password $password -Force
$Task.Triggers.Repetition.Duration = "PT23H"
$Task.Triggers.Repetition.Interval = "PT5M"
$Task | Set-ScheduledTask -User $user -Password $password
以下のコマンドでタスクスケジューラに登録します。
powershell .\タスク登録.ps1 {Administratorのパスワード}
性能情報を表示する
記録した性能情報を単純にselectしてみます。
select_simple.sql
select * from mon_get_db where date(ts) = current date and time(ts) between '08:00:00' and '09:00:00' order by ts ;
Db2コマンド・ウィンドウからSQLファイルを実行します。
db2 -tvf select_simple.sql
select_simple.sqlの実行結果
select * from mon_get_db where date(ts) = current date and time(ts) between '08:00:00' and '09:00:00' order by ts
TS ACT_COMPLETED_TOTAL TOTAL_ACT_TIME TOTAL_CPU_TIME TOTAL_WAIT_TIME TOTAL_COMPILE_TIME LOCK_WAIT_TIME POOL_READ_TIME POOL_WRITE_TIME LOG_DISK_WAIT_TIME
-------------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- --------------------
2021-03-16-08.00.03.779000 14742243 4969146 19874546292 2780203 6875625 154056 2383383 370939 198112
2021-03-16-08.05.03.791000 14774819 4980881 19915452542 2785417 6896106 154091 2386115 371496 198497
2021-03-16-08.10.03.772000 14842853 5002631 19958593167 2790193 6913566 154091 2389311 372055 199160
2021-03-16-08.15.03.802000 14883452 5019426 20002968167 2795354 6930419 154163 2393117 372169 199576
2021-03-16-08.20.03.845000 14946946 5044740 20078218167 2803382 6966482 154243 2402336 373273 200373
2021-03-16-08.25.03.812000 15013303 5066530 20158030667 2811981 7009366 154381 2407998 373966 201002
2021-03-16-08.30.03.799000 15105414 5096334 20262811917 2823867 7065035 154468 2415395 374535 202065
2021-03-16-08.35.03.821000 15201085 5126500 20370765042 2835620 7123726 154534 2421734 375903 203271
2021-03-16-08.40.03.742000 15316212 5158479 20490686917 2849722 7189198 154576 2429962 377038 204986
2021-03-16-08.45.03.821000 15429010 5192443 20621108792 2864827 7263679 154662 2444971 379303 206551
2021-03-16-08.50.03.825000 15560552 5229290 20751546292 2882317 7336472 154765 2467925 381155 208314
2021-03-16-08.55.03.848000 15682599 5263918 20870546292 2897044 7397522 154966 2478376 383758 209706
12 レコードが選択されました。
記録した指標の値はデータベースを開始してからの積算値です。つまり、値はどんどん増えていきます。単位時間ごとの値を算出するためには、一つ前のレコードの値との差を求める必要があります。
エクセルを使うのも面倒なのでSQLで書いてみます。具体的には一つ前のレコードの値との差をOLAP関数であるLAGを使って求めます。WITH句を使って求めた差分の中間テーブルを作成し、見た目を整えるSQLを書きました。
select_mon_get_db.sql
with snap_diffs as (
select ts,
act_completed_total - lag(act_completed_total,1,act_completed_total) over (order by ts) as act_completed_total,
total_act_time - lag(total_act_time, 1,total_act_time) over (order by ts) as total_act_time,
total_cpu_time - lag(total_cpu_time, 1,total_cpu_time) over (order by ts) as total_cpu_time,
total_wait_time - lag(total_wait_time, 1,total_wait_time) over (order by ts) as total_wait_time,
total_compile_time - lag(total_compile_time, 1,total_compile_time) over (order by ts) as total_compile_time,
lock_wait_time - lag(lock_wait_time, 1,lock_wait_time) over (order by ts) as lock_wait_time,
pool_read_time - lag(pool_read_time, 1,pool_read_time) over (order by ts) as pool_read_time,
pool_write_time - lag(pool_write_time, 1,pool_write_time) over (order by ts) as pool_write_time,
log_disk_wait_time - lag(log_disk_wait_time, 1,log_disk_wait_time) over (order by ts) as log_disk_wait_time
from mon_get_db
where date(ts) = current date - 0 day
and time(ts) between '08:00:00' and '09:00:00'
)
select date(ts) as date,
time(ts) as time,
case act_completed_total
when 0 then 0
else decimal((decimal(total_act_time) / act_completed_total), 8, 3)
end as sql_avg_time,
case act_completed_total
when 0 then ''
else substr(repeat('*',(act_completed_total / 50000)),1,20)
end as act_completed_total,
act_completed_total,
total_act_time,
total_cpu_time,
total_wait_time,
total_compile_time,
lock_wait_time,
pool_read_time,
pool_write_time,
log_disk_wait_time
from snap_diffs
order by ts ;
Db2コマンド・ウィンドウからSQLファイルを実行します。
db2 -tvf select_mon_get_db.sql
select_mon_get_db.sqlの実行結果
with snap_diffs as ( select ts, act_completed_total - lag(act_completed_total,1,act_completed_total) over (order by ts) as act_completed_total, total_act_time - lag(total_act_time, 1,total_act_time) over (order by ts) as total_act_time, total_cpu_time - lag(total_cpu_time, 1,total_cpu_time) over (order by ts) as total_cpu_time, total_wait_time - lag(total_wait_time, 1,total_wait_time) over (order by ts) as total_wait_time, total_compile_time - lag(total_compile_time, 1,total_compile_time) over (order by ts) as total_compile_time, lock_wait_time - lag(lock_wait_time, 1,lock_wait_time) over (order by ts) as lock_wait_time, pool_read_time - lag(pool_read_time, 1,pool_read_time) over (order by ts) as pool_read_time, pool_write_time - lag(pool_write_time, 1,pool_write_time) over (order by ts) as pool_write_time, log_disk_wait_time - lag(log_disk_wait_time, 1,log_disk_wait_time) over (order by ts) as log_disk_wait_time from mon_get_db where date(ts) = current date - 0 day and time(ts) between '08:00:00' and '09:00:00' ) select date(ts) as date, time(ts) as time, case act_completed_total when 0 then 0 else decimal((decimal(total_act_time) / act_completed_total), 8, 3) end as sql_avg_time, case act_completed_total when 0 then '' else substr(repeat('*',(act_completed_total / 50000)),1,20) end as act_completed_total, act_completed_total, total_act_time, total_cpu_time, total_wait_time, total_compile_time, lock_wait_time, pool_read_time, pool_write_time, log_disk_wait_time from snap_diffs order by ts
DATE TIME SQL_AVG_TIME ACT_COMPLETED_TOTAL ACT_COMPLETED_TOTAL TOTAL_ACT_TIME TOTAL_CPU_TIME TOTAL_WAIT_TIME TOTAL_COMPILE_TIME LOCK_WAIT_TIME POOL_READ_TIME POOL_WRITE_TIME LOG_DISK_WAIT_TIME
---------- -------- ---------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- --------------------
2021-03-18 08:00:03 0.000 0 0 0 0 0 0 0 0 0
2021-03-18 08:05:03 0.302 * 80660 24433 49765625 12973 19927 369 9230 1196 996
2021-03-18 08:10:03 0.287 *** 153696 44139 111453125 27635 60007 745 16883 1358 2516
2021-03-18 08:15:03 0.264 *** 194856 51616 183640625 33674 121153 562 18196 1553 5334
2021-03-18 08:20:03 0.266 *** 197913 52730 117906250 33975 58484 560 27169 2530 2987
2021-03-18 08:25:03 0.238 ***** 260442 62196 167187500 33469 83654 928 21856 2502 3738
2021-03-18 08:30:03 0.216 ****** 306731 66360 202593750 35487 107329 1570 16760 3632 3524
2021-03-18 08:35:03 0.214 ******** 442872 95042 285796875 51032 150848 1448 17968 3350 4834
2021-03-18 08:40:03 0.213 ********** 516655 110104 320593750 61859 169012 2945 28179 5255 4622
2021-03-18 08:45:03 0.227 ********** 532909 121341 360687500 72780 200698 2588 38129 5023 6142
2021-03-18 08:50:03 0.228 ********** 543220 124013 393968750 73121 231882 2233 37931 5984 6667
2021-03-18 08:55:03 0.222 ********** 509297 113424 357437500 67362 208918 1697 32955 5907 6598
12 レコードが選択されました。
単位時間ごとの差分が時系列に並びました（例では5分ごと）。SQL実行回数がアスタリスクの棒グラフでも表示され量のイメージがつかみやすくなっています。
さいごに
このような単位時間当たりのSQL総実行時間とSQL実行回数を普段から取得しておくとシステムが遅延したときに役立ちます。例えば、過去と比較してみて
- 昔に比べてSQL平均応答時間(SQL_AVG_TIME)が増えている
- 昔と比べてSQL実行回数(ACT_COMPLETED_TOTAL)が増えている
のであれば、トランザクションが増えているからパフォーマンスが落ちていると推測ができます。
また、他施設の性能情報を取得できれば、性能を評価するうえで基準(相場)を知ることができて有益です。