The Db2 Persistent Diagnostic Data scripts (available here) collect various Db2 and Operating System diagnostic information, and retain this info for a period of time, allowing for basic triage of many types of issues. Information is collected about every minute (by a script I often call the 'minutely script'), and additional info about every hour (by a script I often call the 'hourly script').
The diagnostic information is sometimes raw in nature, and thus problem triage often requires various scraping and conjugation of the data.
In this particular customer scenario that I recently engaged in, we have a situation where CPU utilization on the database server host spiked for a moderate period of time. We try to narrow the cause of the CPU spike using the information collected by the Db2 Persistent Diagnostic Data scripts.
Examining the vmstat data (collected by the minutely scripts), we can see the user-cpu spike start at approximately 18:15, with user-cpu usage jumping from about 25% to 80+%
$ grep "" OS_vmstat*
OS_vmstat.[hostname].20190917.181501.txt:procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
OS_vmstat.[hostname].20190917.181501.txt: r b swpd free inact active si so bi bo in cs us sy id wa st
OS_vmstat.[hostname].20190917.181501.txt:27 0 0 484832 41316092 22476632 0 0 144 48 1 1 4 3 92 0 0
OS_vmstat.[hostname].20190917.181501.txt:22 1 0 477076 41319924 22478360 0 0 1048 948 38641 59758 80 9 10 0 0
OS_vmstat.[hostname].20190917.181501.txt:22 0 0 510836 41284108 22482420 0 0 968 1072 36293 51284 82 7 11 0 0
OS_vmstat.[hostname].20190917.181501.txt:25 0 0 491156 41298248 22482316 0 0 1668 1196 36069 45501 83 8 8 0 0
OS_vmstat.[hostname].20190917.181501.txt:23 0 0 616992 41242172 22410940 0 0 1928 1468 35699 37067 84 9 7 0 0
OS_vmstat.[hostname].20190917.181501.txt:23 0 0 598428 41254200 22412968 0 0 2196 14028 32377 39835 84 8 8 0 0
OS_vmstat.[hostname].20190917.181501.txt:20 0 0 686944 41206804 22371564 0 0 1918 1572 35247 42502 80 9 11 1 0
OS_vmstat.[hostname].20190917.181501.txt:28 0 0 684656 41212132 22367500 0 0 1952 1664 32867 42681 78 9 13 1 0
OS_vmstat.[hostname].20190917.181501.txt:31 0 0 680500 41216784 22366940 0 0 2648 2688 38645 45578 81 9 9 1 0
OS_vmstat.[hostname].20190917.181501.txt:27 0 0 672308 41223868 22366852 0 0 9688 3940 39261 48969 83 9 7 1 0
Next I confirmed that the cpu spike was associate with the db2sysc database server process, by comparing top data from the two time periods:
$ less OS_top.[hostname].20190917.180001.txt
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
8621 ipportd1 19 -1 38.4g 13g 7.6g S 118.8 21.0 19294:30 db2sysc
13443 root RT 0 637m 65m 48m R 22.3 0.1 2786:46 corosync
12122 root 15 -5 422m 46m 1136 S 14.8 0.1 2067:30 tesvc
12564 root 20 0 328m 290m 2252 S 14.8 0.5 1912:53 rtvscand
5962 root 20 0 6184 1020 336 S 13.0 0.0 1551:54 symcfgd
38663 ipportd1 20 0 15684 1912 884 R 7.4 0.0 0:00.06 top
38766 caapm 20 0 122m 3508 1932 S 5.6 0.0 0:00.03 perl
11857 root 20 0 20.1g 760m 10m S 3.7 1.2 738:29.34 java
$ less OS_top.[hostname].20190917.181502.txt
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
8621 ipportd1 19 -1 38.3g 15g 9.8g S 1853.9 24.3 19363:32 db2sysc
38942 ipportd1 20 0 339m 51m 13m R 32.4 0.1 0:00.26 db2bp
39244 ipportd1 20 0 250m 15m 10m R 25.2 0.0 0:00.14 db2
13443 root RT 0 638m 66m 49m S 18.0 0.1 2788:40 corosync
39285 root 19 -1 36580 1748 904 R 16.2 0.0 0:00.09 clulog
12122 root 15 -5 422m 46m 1136 S 12.6 0.1 2068:48 tesvc
12564 root 20 0 328m 290m 2252 S 10.8 0.5 1914:09 rtvscand
39190 ipportd1 20 0 15684 1924 884 R 10.8 0.0 0:00.10 top
5962 root 20 0 6184 1020 336 S 9.0 0.0 1552:56 symcfgd
358 root 20 0 0 0 0 S 3.6 0.0 6:12.15 kswapd1
11857 root 20 0 20.1g 760m 10m S 3.6 1.2 738:53.95 java
12135 ipporta1 19 -1 52.0g 24g 21g S 3.6 39.8 1227:27 db2sysc
228 root 20 0 0 0 0 S 1.8 0.0 2:36.82 kblockd/2
357 root 20 0 0 0 0 S 1.8 0.0 6:29.98 kswapd0
12223 caapm 20 0 187m 54m 1596 S 1.8 0.1 169:17.21 sysedge
Next, I examined the cumulative user-cpu values of all the Db2 threads in the db2pd_edus output, between a time frame just before the cpu spike (18:00) and during the cpu spike (18:15).
However, I did not find any EDU with a very sharp increase in cumulative user-cpu during this time. Mostly just small increases between the two time-frames:
$ diff db2pd_edus.inst.[hostname].20190917.180002.txt db2pd_edus.inst.[hostname].20190917.181504.txt | lessNext, I examine the db2pd-utilities output, and confirmed that there were no utilities (such as REORGS or BACKUPS running during this time frame).
EDU ID TID Kernel TID EDU Name USR (s) SYS (s)
2770 140698158360320 30841 db2agent (WPJCR) 0 525.340000 24.820000
2769 140698162554624 29837 db2agent (SGROUPDB) 0 10.320000 2.510000
2768 140698166748928 21556 db2agent (WPJCR) 0 360.730000 20.310000
2767 140698170943232 21553 db2agntdp (WPREL ) 0 9.300000 2.270000
---
2770 140698158360320 30841 db2agent (WPJCR) 0 531.230000 25.330000
2769 140698162554624 29837 db2agent (SGROUPDB) 0 10.840000 2.630000
2768 140698166748928 21556 db2agent (WPJCR) 0 398.970000 21.970000
2767 140698170943232 21553 db2agent (WPJCR) 0 10.080000 2.320000
...etc...
$ ls -l db2pd_utilities*Next, I compared the db2pd_agents between the same two time frames. I can see a small increase in the number of active agents (ie. an increase in the number of database connections).
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:00 db2pd_utilities.[hostname].20190917.180004.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:03 db2pd_utilities.[hostname].20190917.180305.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:06 db2pd_utilities.[hostname].20190917.180605.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:09 db2pd_utilities.[hostname].20190917.180904.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:12 db2pd_utilities.[hostname].20190917.181204.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:15 db2pd_utilities.[hostname].20190917.181507.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:18 db2pd_utilities.[hostname].20190917.181812.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:21 db2pd_utilities.[hostname].20190917.182113.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:24 db2pd_utilities.[hostname].20190917.182414.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:27 db2pd_utilities.[hostname].20190917.182707.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:30 db2pd_utilities.[hostname].20190917.183006.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:33 db2pd_utilities.[hostname].20190917.183306.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:36 db2pd_utilities.[hostname].20190917.183605.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:39 db2pd_utilities.[hostname].20190917.183904.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:42 db2pd_utilities.[hostname].20190917.184205.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:45 db2pd_utilities.[hostname].20190917.184505.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:48 db2pd_utilities.[hostname].20190917.184804.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:51 db2pd_utilities.[hostname].20190917.185105.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:54 db2pd_utilities.[hostname].20190917.185405.txt
-rwxrwxr-x 1 ecuunpck swsupt 410 Sep 18 00:57 db2pd_utilities.[hostname].20190917.185705.txt
$ diff db2pd_agents.inst.[hostname1].20190917.180003.txt db2pd_agents.inst.[hostname1].20190917.181807.txt | lessand I also see some cases where the cumulative rows-read values increase sharply, such as this example, where AppHandl 3698 read about 31M rows between the two time frames:
< Active coord agents: 797
< Active agents total: 797
< Pooled coord agents: 78
< Pooled agents total: 78
---
> Active coord agents: 828
> Active agents total: 828
> Pooled coord agents: 47
> Pooled agents total: 47
$ diff db2pd_agents.inst.[hostname1].20190917.180003.txt db2pd_agents.inst.[hostname1].20190917.181807.txt | less
Address AppHandl [nod-index] AgentEDUID Priority ... Rowsread Rowswrtn ...
0x00007FFCEC3F6900 3695 [000-03695] 1123 0 Coord ... 11560 0 ...
0x00007FFCEBBEB4C0 3696 [000-03696] 1086 0 Coord ... 54716 0 ...
0x00007FFCEB8985C0 3698 [000-03698] 1081 0 Coord ... 200138526 312789 ...
---
Address AppHandl [nod-index] AgentEDUID Priority ... Rowsread Rowswrtn ...
0x00007FFCEC3F6900 3695 [000-03695] 1123 0 Coord ... 0 0 ...
0x00007FFCEBBEB4C0 3696 [000-03696] 1086 0 Coord ... 0 0 ...
0x00007FFCEB8985C0 3698 [000-03698] 1081 0 Coord ... 231755161 334148 ...
Next, using the AgentEDUID value of 1081 for this agent, I examined the db2pd-apinfo data to see what this agent was executing:
$ less db2pd_apinfo.[hostname1].20190917.181507.txt
Application :
Address : 0x00007FFCEBD00080
AppHandl [nod-index] : 3698 [000-03698]
TranHdl : 25
Application PID : 0
Application Node Name : [ipaddr]
IP Address: [ipaddr]
Connection Start Time : (1567261562)Sat Aug 31 10:26:02 2019
Client User ID : n/a
System Auth ID : APPWPS
Coordinator EDU ID : 1081 ...
Last executed statements :
Package cache ID : 0x0000021900000002
Anchor ID : 537
Statement UID : 2
QL Type : Dynamic
Statement Type : DML, Insert/Update/Delete
Statement : DELETE FROM JCR.ICMSTJCRREMOVEHLP WHERE WSID = ? AND LID = ?
So we might consider this a suspect query... but let's keep looking....
Next, I input the MON_GET_ACTIVITES output from the 8:15 cpu spike time-frame into a spreadsheet, however it did not reflect the activities of the 800+ agents in the database, it only contains 4 records, none of which show high total_cpu_time values, or large rows read or written values, or query cost estimates.
So I suspect whatever is causing the CPU increase is not a single long execution of a large query which was captured in the minutely data collections, but rather many successive executions of a single query or small set of queries, which may not have been executing at the moment when the minutely data is collected every minute.
Next, I examined the mon_get_pkg_cache_stmnt output from the hourly data collection script.
I crafted the following awk query to calculate the average cpu time per query execution from the mon_get_pkg_cache_stmt() output.
I do see some relatively expensive individual queries which are compounded by many executions:
Find the entry with this total_cpu_time value within the mon_get_pkg_cache_stmt data files, we see this particular query is:
DELETE FROM jcr.WCM_USER_SHORTCUT t0 WHERE (t0.VPID = ? AND t0.LOCATION_DATA LIKE ? ESCAPE '\') AND t0.KIND = ?
At this point, I'd consider these two DELETE statements to be suspects, and recommend using the db2batch bench-marking tool against these statements to determine their execution metrics (rows read, updated, written, etc) and whether any possible tuning is required.
I do see some relatively expensive individual queries which are compounded by many executions:
$ awk -F' ' '{avg=0; if($9+0 != 0 && $13+0 != 0){ $avg=$13/$9 }; print "pkg_sch:" $3 ",pkg_nam:" $4 ",pkg_ver:" $5 ",sec_num:" $6 ",num_execs:" $9 ",total_cpu_time:" $13 ",average_cpu_time:" $avg;}' qry3.out | less
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:155337498,total_cpu_time:78672618581,average_cpu_time:506.463...
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:2447636,total_cpu_time:25020306619,average_cpu_time:10222.2
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:2853649,total_cpu_time:14116987481,average_cpu_time:4947
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:25452,total_cpu_time:7238807540,average_cpu_time:284410
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:109301657,total_cpu_time:4889890787,average_cpu_time:44.7376
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:41021,total_cpu_time:4850725299,average_cpu_time:118250
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:38909250,total_cpu_time:3761535928,average_cpu_time:96.6746
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:58972,total_cpu_time:3707165379,average_cpu_time:62863.1
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:11536,total_cpu_time:3488732997,average_cpu_time:302421
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:17642026,total_cpu_time:3051013622,average_cpu_time:172.94
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:17226,total_cpu_time:2038784887,average_cpu_time:118355
...
pkg_sch:-,pkg_nam:-,pkg_ver:-,sec_num:-,num_execs:73,total_cpu_time:120223152,average_cpu_time:1.64689e+06
Find the entry with this total_cpu_time value within the mon_get_pkg_cache_stmt data files, we see this particular query is:
DELETE FROM jcr.WCM_USER_SHORTCUT t0 WHERE (t0.VPID = ? AND t0.LOCATION_DATA LIKE ? ESCAPE '\') AND t0.KIND = ?
At this point, I'd consider these two DELETE statements to be suspects, and recommend using the db2batch bench-marking tool against these statements to determine their execution metrics (rows read, updated, written, etc) and whether any possible tuning is required.
No comments:
Post a Comment