I have oracle 12.1..0.2. My insert base on select is running for hours. I did a trace and I noticed although Io latency is under 1ms . Number of IO per second is only 20. How do I troubleshoot such issue? I have provided top and vmstat output below.
It is 32 cpu Red hat LInux 6 machine. Number of database / process has not changed but we have been seeing high CPU.
*** 2018-06-29 12:23:16.428
*** SESSION ID:(3072.25187) 2018-06-29 12:23:16.428
*** CLIENT ID:() 2018-06-29 12:23:16.428
*** SERVICE NAME:(SYS$USERS) 2018-06-29 12:23:16.428
*** MODULE NAME:(SQL*Plus) 2018-06-29 12:23:16.428
*** CLIENT DRIVER:(SQL*PLUS ) 2018-06-29 12:23:16.428
*** ACTION NAME:() 2018-06-29 12:23:16.428
WAIT #139664461155144: nam='db file sequential read' ela= 439 file#=7 block#=759943 blocks=1 obj#=2339014 tim=91051285741
WAIT #139664461155144: nam='db file sequential read' ela= 442 file#=7 block#=759944 blocks=1 obj#=2339014 tim=91051345308
WAIT #139664461155144: nam='db file sequential read' ela= 5968 file#=153 block#=2756198 blocks=1 obj#=2339029 tim=91051448909
WAIT #139664461155144: nam='db file sequential read' ela= 483 file#=7 block#=759952 blocks=1 obj#=2339014 tim=91051539057
WAIT #139664461155144: nam='db file sequential read' ela= 318 file#=7 block#=759953 blocks=1 obj#=2339014 tim=91051580046
WAIT #139664461155144: nam='db file sequential read' ela= 1642 file#=7 block#=759954 blocks=1 obj#=2339014 tim=91051606628
WAIT #139664461155144: nam='db file sequential read' ela= 482 file#=153 block#=2756199 blocks=1 obj#=2339029 tim=91051666555
WAIT #139664461155144: nam='db file sequential read' ela= 1201 file#=7 block#=759958 blocks=1 obj#=2339014 tim=91051681886
WAIT #139664461155144: nam='db file sequential read' ela= 482 file#=7 block#=759959 blocks=1 obj#=2339014 tim=91051705344
WAIT #139664461155144: nam='db file sequential read' ela= 479 file#=7 block#=759962 blocks=1 obj#=2339014 tim=91051773635
WAIT #139664461155144: nam='db file sequential read' ela= 1442 file#=7 block#=759963 blocks=1 obj#=2339014 tim=91051798536
WAIT #139664461155144: nam='db file sequential read' ela= 363 file#=7 block#=759965 blocks=1 obj#=2339014 tim=91051843812
WAIT #139664461155144: nam='db file sequential read' ela= 441 file#=153 block#=2756200 blocks=1 obj#=2339029 tim=91051856219
WAIT #139664461155144: nam='db file sequential read' ela= 360 file#=7 block#=759966 blocks=1 obj#=2339014 tim=91051873033
*** 2018-06-29 12:23:17.018
WAIT #139664461155144: nam='db file sequential read' ela= 400 file#=7 block#=759967 blocks=1 obj#=2339014 tim=91051897889
WAIT #139664461155144: nam='db file sequential read' ela= 317 file#=7 block#=759968 blocks=1 obj#=2339014 tim=91051932797
WAIT #139664461155144: nam='db file sequential read' ela= 4603 file#=7 block#=759972 blocks=1 obj#=2339014 tim=91052028552
WAIT #139664461155144: nam='db file sequential read' ela= 403 file#=153 block#=2756201 blocks=1 obj#=2339029 tim=91052063660
WAIT #139664461155144: nam='db file sequential read' ela= 203 file#=7 block#=759974 blocks=1 obj#=2339014 tim=91052077030
WAIT #139664461155144: nam='db file sequential read' ela= 360 file#=7 block#=759975 blocks=1 obj#=2339014 tim=91052103969
WAIT #139664461155144: nam='db file sequential read' ela= 359 file#=7 block#=759976 blocks=1 obj#=2339014 tim=91052126905
WAIT #139664461155144: nam='db file sequential read' ela= 237 file#=7 block#=759977 blocks=1 obj#=2339014 tim=91052149723
WAIT #139664461155144: nam='db file sequential read' ela= 401 file#=7 block#=759978 blocks=1 obj#=2339014 tim=91052173304
WAIT #139664461155144: nam='direct path write' ela= 50758 file number=17 first dba=2017728 block cnt=64 obj#=2339014 tim=91052244717
WAIT #139664461155144: nam='db file sequential read' ela= 242 file#=153 block#=2756202 blocks=1 obj#=2339029 tim=91052326140
WAIT #139664461155144: nam='db file sequential read' ela= 239 file#=7 block#=759982 blocks=1 obj#=2339014 tim=91052344671
WAIT #139664461155144: nam='db file sequential read' ela= 478 file#=7 block#=759985 blocks=1 obj#=2339014 tim=91052422613
WAIT #139664461155144: nam='db file sequential read' ela= 323 file#=7 block#=759986 blocks=1 obj#=2339014 tim=91052447032
WAIT #139664461155144: nam='db file sequential read' ela= 281 file#=153 block#=2756203 blocks=1 obj#=2339029 tim=91052523772
WAIT #139664461155144: nam='db file sequential read' ela= 279 file#=7 block#=759991 blocks=1 obj#=2339014 tim=91052560919
WAIT #139664461155144: nam='db file sequential read' ela= 403 file#=7 block#=759993 blocks=1 obj#=2339014 tim=91052600111
WAIT #139664461155144: nam='db file sequential read' ela= 203 file#=7 block#=759995 blocks=1 obj#=2339014 tim=91052635938
WAIT #139664461155144: nam='db file sequential read' ela= 400 file#=153 block#=2756204 blocks=1 obj#=2339029 tim=91052689016
WAIT #139664461155144: nam='db file sequential read' ela= 362 file#=7 block#=760001 blocks=1 obj#=2339014 tim=91052744660
WAIT #139664461155144: nam='db file sequential read' ela= 7924 file#=7 block#=760005 blocks=1 obj#=2339014 tim=91052832605
*** 2018-06-29 12:23:18.116
WAIT #139664461155144: nam='db file sequential read' ela= 281 file#=153 block#=2756205 blocks=1 obj#=2339029 tim=91052995773
WAIT #139664461155144: nam='db file sequential read' ela= 560 file#=7 block#=760010 blocks=1 obj#=2339014 tim=91053153413
WAIT #139664461155144: nam='db file sequential read' ela= 281 file#=7 block#=760011 blocks=1 obj#=2339014 tim=91053199005
WAIT #139664461155144: nam='db file sequential read' ela= 318 file#=7 block#=760012 blocks=1 obj#=2339014 tim=91053227185
WAIT #139664461155144: nam='db file sequential read' ela= 243 file#=7 block#=760013 blocks=1 obj#=2339014 tim=91053250687
WAIT #139664461155144: nam='db file sequential read' ela= 5926 file#=153 block#=2756206 blocks=1 obj#=2339029 tim=91053320058
WAIT #139664461155144: nam='db file sequential read' ela= 839 file#=7 block#=760017 blocks=1 obj#=2339014 tim=91053349559
WAIT #139664461155144: nam='db file sequential read' ela= 443 file#=7 block#=760020 blocks=1 obj#=2339014 tim=91053413131
WAIT #139664461155144: nam='db file sequential read' ela= 1682 file#=7 block#=760022 blocks=1 obj#=2339014 tim=91053448757
WAIT #139664461155144: nam='db file sequential read' ela= 519 file#=153 block#=2756207 blocks=1 obj#=2339029 tim=91053510604
WAIT #139664461155144: nam='db file sequential read' ela= 362 file#=7 block#=760026 blocks=1 obj#=2339014 tim=91053524776
WAIT #139664461155144: nam='db file sequential read' ela= 402 file#=7 block#=760029 blocks=1 obj#=2339014 tim=91053563926
WAIT #139664461155144: nam='db file sequential read' ela= 479 file#=7 block#=760030 blocks=1 obj#=2339014 tim=91053599032
WAIT #139664461155144: nam='db file sequential read' ela= 597 file#=7 block#=760032 blocks=1 obj#=2339014 tim=91053639341
WAIT #139664461155144: nam='db file sequential read' ela= 518 file#=7 block#=760033 blocks=1 obj#=2339014 tim=91053663040
WAIT #139664461155144: nam='db file sequential read' ela= 279 file#=7 block#=760034 blocks=1 obj#=2339014 tim=91053687139
WAIT #139664461155144: nam='db file sequential read' ela= 518 file#=153 block#=2756208 blocks=1 obj#=2339029 tim=91053706712
WAIT #139664461155144: nam='db file sequential read' ela= 482 file#=7 block#=760036 blocks=1 obj#=2339014 tim=91053720567
WAIT #139664461155144: nam='db file sequential read' ela= 480 file#=7 block#=760040 blocks=1 obj#=2339014 tim=91053782051
WAIT #139664461155144: nam='db file sequential read' ela= 556 file#=7 block#=760042 blocks=1 obj#=2339014 tim=91053832448
...
...
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
kwalxorcld102[]> top -Mc
top - 23:38:46 up 1 day, 12:33, 1 user, load average: 21.65, 22.68, 25.06
top - 00:48:03 up 1 day, 13:42, 1 user, load average: 35.34, 34.55, 31.34
Tasks: 2307 total, 43 running, 2263 sleeping, 0 stopped, 1 zombie
Cpu(s): 72.1%us, 20.4%sy, 0.0%ni, 6.2%id, 0.9%wa, 0.0%hi, 0.4%si, 0.0%st
Mem: 252.231G total, 251.349G used, 903.871M free, 363.086M buffers
Swap: 64.000G total, 0.000k used, 64.000G free, 232.556G cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14998 oracle 20 0 9749m 48m 34m R 99.4 0.0 104:31.40 oracleTCEDEV2D (LOCAL=NO)
30659 oracle 20 0 9749m 103m 87m R 97.9 0.0 1335:29 oracleTCEDEV2D (LOCAL=NO)
30533 oracle 20 0 9749m 90m 75m R 97.3 0.0 1337:28 oracleTCEDEV2D (LOCAL=NO)
14978 oracle 20 0 9749m 51m 33m R 95.7 0.0 103:50.31 oracleTCEDEV2D (LOCAL=NO)
8578 oracle 20 0 9727m 140m 131m R 93.1 0.1 725:03.54 ora_p000_TCEDEV2D
8586 oracle 20 0 9727m 161m 153m R 92.8 0.1 722:42.63 ora_p002_TCEDEV2D
20453 oracle 20 0 9765m 95m 59m R 92.8 0.0 20:40.59 ora_j004_TCEDEV2D
27490 oracle 20 0 17.0g 280m 272m R 91.9 0.1 0:06.25 ora_m000_CRD3I
28858 oracle 20 0 9797m 776m 703m R 91.2 0.3 160:19.57 ora_j005_TCEINT1I
16543 oracle 20 0 17.0g 38m 35m R 90.6 0.0 99:03.71 oracleCRDIAI (LOCAL=NO)
6805 oracle 20 0 9725m 35m 27m R 89.0 0.0 15:55.92 ora_p002_TCEINT1I
8582 oracle 20 0 9725m 126m 118m R 88.8 0.0 724:32.50 ora_p001_TCEDEV2D
23751 oracle 20 0 9.9g 5.0g 4.5g R 88.7 2.0 819:49.27 ora_j002_TCEDEV2D
27464 root 20 0 79160 11m 4856 R 87.6 0.0 0:08.23 /bin/rpm -qa
42505 oracle 20 0 4143m 1.1g 467m R 87.1 0.4 75:10.93 oracleCRDNBC3I (LOCAL=NO)
27458 oracle 20 0 17.0g 338m 328m R 86.3 0.1 0:08.98 ora_m000_CRDIAI
29537 oracle 20 0 9829m 3.5g 3.4g R 85.6 1.4 154:46.04 ora_j001_TCEDEV2D
26335 oracle 20 0 9749m 68m 41m R 84.4 0.0 1:58.53 ora_j001_TCEINT1I
6793 oracle 20 0 9725m 34m 26m R 84.2 0.0 15:56.37 ora_p000_TCEINT1I
8590 oracle 20 0 9725m 184m 176m R 82.8 0.1 721:09.06 ora_p003_TCEDEV2D
29551 oracle 20 0 9813m 345m 259m R 82.4 0.1 162:01.24 ora_j005_TCEDEV2D
6809 oracle 20 0 9725m 35m 27m R 81.8 0.0 16:01.33 ora_p003_TCEINT1I
6797 oracle 20 0 9725m 35m 27m R 80.5 0.0 15:51.20 ora_p001_TCEINT1I
7429 oracle 20 0 9754m 125m 96m R 70.3 0.0 1387:35 oracleTCEINT1I (LOCAL=NO)
7427 oracle 20 0 9742m 106m 100m R 65.8 0.0 1391:00 oracleTCEINT1I (LOCAL=NO)
25307 oracle 20 0 1565m 170m 165m R 64.9 0.1 4:17.56 oracleCRDDDA2I (LOCAL=NO)
11 root RT 0 0 0 0 R 61.2 0.0 52:36.36 [migration/2]
7431 oracle 20 0 9750m 106m 83m R 56.4 0.0 1391:21 oracleTCEINT1I (LOCAL=NO)
149 root 20 0 0 0 0 S 49.7 0.0 5:25.56 [events/18]
40821 oracle 20 0 30808 4312 1724 R 47.3 0.0 352:04.11 top -Mc
24063 oracle 20 0 17.0g 1.1g 1.1g R 38.8 0.5 2:30.13 oracleCRDRI (LOCAL=NO)
24010 oracle 20 0 17.0g 1.2g 1.2g R 37.7 0.5 2:54.79 oracleCRDRI (LOCAL=NO)
24069 oracle 20 0 17.0g 1.1g 1.1g R 36.3 0.5 2:27.30 oracleCRDRI (LOCAL=NO)
453 root 20 0 0 0 0 S 20.8 0.0 37:40.35 [kswapd0]
23473 oracle 20 0 17.0g 72m 58m R 14.9 0.0 199:26.30 ora_dia0_CRDIAI
29588 oracle 20 0 17.0g 79m 65m S 12.9 0.0 193:41.76 ora_dia0_CRD3I
43470 oracle 20 0 17.0g 82m 68m S 10.4 0.0 197:25.18 ora_dia0_CRDRI
44871 oracle 20 0 10.4g 70m 68m S 8.1 0.0 31:10.68 ora_mmnl_MILSI
33977 oracle 20 0 17.0g 137m 116m S 6.6 0.1 106:02.39 ora_cp01_CRD3I
26192 oracle 20 0 9722m 275m 271m R 6.4 0.1 10:28.63 oracleTCEDEV2D (LOCAL=NO)
3075 oracle 20 0 9734m 196m 179m S 5.9 0.1 79:35.98 ora_mmon_TCEINT1I
13069 oracle 20 0 1564m 40m 33m S 5.3 0.0 73:17.56 ora_dia0_CRDDDA2I
18093 oracle 20 0 9722m 36m 32m S 5.3 0.0 0:36.34 oracleTCEINT1I (LOCAL=NO)
7591 oracle 20 0 9734m 228m 211m S 4.8 0.1 79:52.96 ora_mmon_TCEDEV2D
18344 oracle 20 0 3436m 40m 34m S 4.8 0.0 73:03.09 ora_dia0_CRDDDA3I
5928 root 20 0 1906m 34m 7568 S 4.6 0.0 75:32.59 python /usr/bin/goferd
29759 oracle 20 0 17.0g 208m 206m S 4.5 0.1 108:34.96 ora_mmnl_CRD3I
47455 oracle 20 0 10.4g 32m 27m S 3.7 0.0 41:03.94 ora_dia0_MILS2I
7906 oracle 20 0 3436m 42m 35m S 3.5 0.0 74:49.40 ora_dia0_CRDDDAI
36723 oracle 20 0 3770m 32m 27m S 3.5 0.0 40:06.08 ora_dia0_CRDNBCI
14607 oracle 20 0 17.0g 65m 61m S 3.4 0.0 0:13.62 ora_j002_CRDIAI
8132 oracle 20 0 3457m 165m 148m S 2.7 0.1 21:52.07 ora_mmon_CRDDDAI
47523 oracle 20 0 10.4g 178m 161m S 2.7 0.1 21:11.35 ora_mmon_MILS2I
49109 oracle 20 0 3290m 33m 28m R 2.7 0.0 39:10.95 ora_dia0_MILSDW2I
10377 oracle 20 0 9723m 229m 225m S 2.6 0.1 11:59.33 oracleTCEDEV2D (LOCAL=NO)
18532 oracle 20 0 3430m 75m 73m S 2.6 0.0 46:23.11 ora_mmnl_CRDDDA3I
------------------------------------------------------------------------------
kwalxorcld102[]> vmstat -w 1 10
procs -------------------memory------------------ ---swap-- -----io---- --system-- -----cpu-------
r b swpd free buff cache si so bi bo in cs us sy id wa st
20 0 0 997476 416352 244328416 0 0 327 176 9 5 49 16 33 2 0
24 1 0 987952 416352 244338880 0 0 9120 1625 22802 2937 58 7 34 0 0
23 0 0 978288 416352 244351744 0 0 13216 644 22530 2654 57 7 36 0 0
23 0 0 957168 416352 244361744 0 0 9216 1181 24648 3177 59 11 30 0 0
25 0 0 961912 416364 244371376 0 0 9000 736 26245 3100 58 14 28 0 0
24 0 0 953168 416364 244380928 0 0 9088 272 26458 2916 61 13 26 0 0
19 0 0 949000 416364 244389728 0 0 8704 352 23296 2966 57 9 34 0 0
21 0 0 944224 416364 244400704 0 0 9352 1004 23446 3018 56 10 34 0 0
20 0 0 924856 416372 244411168 0 0 9168 1412 23591 2829 58 9 32 0 0
25 0 0 907564 416380 244420080 0 0 8960 652 26652 2871 56 13 31 0 0