IO wait during backup

Env is 2 node RAC (12.2 GI + RDBMS) on Linux.

We are seeing significant amount of IO wait during level 0 backups (weekly once) and level 1 backups (daily). RMAN backup is running on Node A and Golden Gate is running on Node B. The below are some artifacts

*iostat------*

*Node A*

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util

sda 0.00 0.00 0.00 69.00 0.00 600.50 17.41

    0.00 0.03 0.00 0.03 0.03 0.20

sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00

    0.00 0.00 0.00 0.00 0.00 0.00

sdc 0.00 0.00 7.00 0.00 3584.00 0.00 1024.00

    1.29 165.57 165.57 0.00 71.86 50.30

sdd 0.00 0.00 6.00 0.00 3088.00 0.00 1029.33

    1.00 213.67 213.67 0.00 39.00 23.40

sde 0.00 0.00 14.00 0.00 1541.50 0.00 220.21

    0.91 49.71 49.71 0.00 33.93 47.50

sdf 0.00 0.00 4.00 0.00 3072.00 0.00 1536.00

    0.84 176.25 176.25 0.00 144.75 57.90

sdg 0.00 0.00 5.00 0.00 2560.00 0.00 1024.00

    0.25 70.40 70.40 0.00 40.80 20.40

sdh 0.00 0.00 6.00 0.00 3072.00 0.00 1024.00

    1.15 166.83 166.83 0.00 73.33 44.00

sdi 0.00 0.00 7.00 0.00 3584.00 0.00 1024.00

    1.08 129.43 129.43 0.00 62.57 43.80

sdj 0.00 0.00 8.00 0.00 4096.00 0.00 1024.00

    0.46 120.50 120.50 0.00 29.75 23.80

sdk 0.00 0.00 10.00 0.00 5120.00 0.00 1024.00

    0.97 86.20 86.20 0.00 58.40 58.40

sdl 0.00 0.00 11.00 0.00 5120.00 0.00 930.91

    1.25 83.91 83.91 0.00 48.09 52.90

sdm 0.00 0.00 7.00 0.00 3080.00 0.00 880.00

    0.89 198.00 198.00 0.00 65.00 45.50

sdn 0.00 0.00 10.00 0.00 4096.50 0.00 819.30

    0.65 76.20 76.20 0.00 41.30 41.30

sdo 0.00 0.00 16.00 0.00 7168.00 0.00 896.00

    1.21 69.94 69.94 0.00 35.00 56.00

………….

………….

emcpowerc 0.00 0.00 50.00 1.00 24608.00 16.00 965.65

    3.28 64.35 64.90 37.00 10.39 53.00

emcpowerf 0.00 0.00 52.00 0.00 24632.00 0.00 947.38

    2.86 55.02 55.02 0.00 9.60 49.90

emcpowerd 0.00 0.00 140.00 0.00 28714.00 0.00 410.20

    6.93 49.21 49.21 0.00 7.10 99.40

emcpowerb 0.00 0.00 64.00 0.00 32768.00 0.00 1024.00

    3.56 55.62 55.62 0.00 5.81 37.20

emcpowere 0.00 0.00 51.00 0.00 24624.00 0.00 965.65

    2.66 52.14 52.14 0.00 7.73 39.40

emcpowerg 0.00 0.00 64.00 0.00 32768.00 0.00 1024.00

    3.42 56.77 56.77 0.00 5.77 36.90

emcpowerbw 0.00 0.00 59.00 0.00 28696.00 0.00 972.75

    3.83 56.97 56.97 0.00 9.34 55.10

emcpowerh 0.00 0.00 57.00 0.00 28688.00 0.00 1006.60

    3.15 52.25 52.25 0.00 6.16 35.10

emcpowerbv 0.00 0.00 56.00 0.00 28672.00 0.00 1024.00

    3.49 56.66 56.66 0.00 8.18 45.80

emcpowerj 0.00 0.00 65.00 0.00 32776.00 0.00 1008.49

    3.64 56.15 56.15 0.00 6.46 42.00

emcpowerbu 0.00 0.00 64.00 0.00 32768.00 0.00 1024.00

    3.38 56.25 56.25 0.00 5.58 35.70

emcpoweri 0.00 0.00 64.00 0.00 32768.00 0.00 1024.00

    3.81 56.34 56.34 0.00 7.50 48.00

emcpowerbt 0.00 0.00 57.00 0.00 28680.00 0.00 1006.32

    3.10 54.84 54.84 0.00 7.21 41.10

emcpowerl 0.00 0.00 56.00 0.00 28672.00 0.00 1024.00

    2.91 51.95 51.95 0.00 7.25 40.60

emcpowerbs 0.00 0.00 67.00 0.00 34304.00 0.00 1024.00

    3.76 57.18 57.18 0.00 5.25 35.20

*Node B------*

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util

sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00

    0.00 0.00 0.00 0.00 0.00 0.00

sdez 0.00 0.00 0.00 0.00 0.00 0.00 0.00

    0.00 0.00 0.00 0.00 0.00 0.00

sdfa 0.00 0.00 18.00 0.00 128.00 24.00 16.89

    1.24 82.00 82.00 0.00 39.00 70.20

sdfb 0.00 0.00 17.00 1.00 120.00 16.00 15.11

    1.41 73.50 73.00 82.00 45.33 81.60

sdfc 0.00 0.00 8.00 1.00 40.00 16.00 12.44

    0.90 76.22 75.75 80.00 56.22 50.60

sdfd 0.00 0.00 10.00 1.00 80.00 16.00 17.45

    0.69 71.36 70.80 77.00 31.36 34.50

sdfe 0.00 0.00 12.00 3.00 96.00 24.00 16.00

    0.53 70.00 70.08 69.67 22.93 34.40

sdff 0.00 0.00 12.00 0.00 88.00 4.00 15.33

    0.84 93.50 93.50 0.00 42.25 50.70

sdfg 0.00 0.00 8.00 2.00 64.00 136.00 40.00

    0.61 66.40 66.12 67.50 30.80 30.80

sdfh 0.00 0.00 20.00 1.00 120.00 8.00 12.19

    1.62 73.19 74.05 56.00 39.29 82.50

sdfi 0.00 0.00 9.00 0.00 64.00 0.00 14.22

    0.54 92.67 92.67 0.00 42.89 38.60

…………

………..

emcpoweraw 0.00 0.00 14.00 1.00 112.00 16.00 17.07

    3.69 291.93 292.36 286.00 61.40 92.10

emcpowerav 0.00 0.00 9.00 0.00 72.00 0.00 16.00

    2.58 291.78 291.78 0.00 94.44 85.00

emcpowerax 0.00 0.00 5.00 2.00 40.00 16.00 16.00

    2.66 288.71 291.60 281.50 131.57 92.10

emcpowerbi 0.00 0.00 5.00 1.00 40.00 8.00 16.00

    1.96 297.17 298.80 289.00 139.67 83.80

emcpowerbh 0.00 0.00 8.00 0.00 64.00 0.00 16.00

    2.43 293.88 293.88 0.00 115.25 92.20

emcpowerbg 0.00 0.00 5.00 0.00 40.00 0.00 16.00

    1.60 289.40 289.40 0.00 179.60 89.80

emcpowerbf 0.00 0.00 5.00 0.00 40.00 0.00 16.00

    2.07 293.40 293.40 0.00 184.00 92.00

emcpowerbe 0.00 0.00 11.00 0.00 88.00 0.00 16.00

    3.12 294.18 294.18 0.00 89.27 98.20

emcpowerbd 0.00 0.00 4.00 1.00 32.00 8.00 16.00

    0.85 283.40 279.75 298.00 132.80 66.40

emcpowerbc 0.00 0.00 6.00 1.00 48.00 8.00 16.00

    2.29 288.71 289.67 283.00 128.43 89.90

emcpowerbb 0.00 0.00 10.00 0.00 80.00 0.00 16.00

    3.02 291.80 291.80 0.00 100.00 100.00

emcpowerba 0.00 0.00 10.00 0.00 80.00 0.00 16.00

    2.83 292.80 292.80 0.00 84.20 84.20

emcpoweraz 0.00 0.00 8.00 1.00 64.00 8.00 16.00

    2.26 291.89 291.75 293.00 111.11 100.00

emcpoweray 0.00 0.00 5.00 1.00 40.00 8.00 16.00

    1.25 288.67 286.80 298.00 94.50 56.70

*vmstat------*

*Node A*

SNAP_INTERVAL 30 CPU_CORES 18 VCPUS 72 OSWBB_ARCHIVE_DEST /ora45/dbworkspace/OSWATCHER/oswbb/archive

zzz ***Sat May 9 01:00:15 EDT 2020

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----

r b swpd free buff cache si so bi bo in cs us sy id wa st

6 123 0 32364372 303780 40037240 0 0 561 153 0 0 3 1 94 3 0

1 125 0 32371232 303780 40037456 0 0 41317 30810 35987 45850 4  1 27 67 0

5 123 0 32371060 303780 40037644 0 0 30972 23008 43202 56629 3  1 27 69 0

zzz ***Sat May 9 01:00:45 EDT 2020

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----

r b swpd free buff cache si so bi bo in cs us sy id wa st

4 119 0 32338792 303780 40038420 0 0 561 153 0 0 3 1 94 3 0

2 124 0 32329172 303780 40038840 0 0 12392 9241 18276 20114 3  1 30 66 0

3 118 0 32334116 303780 40038836 0 0 16690 11341 17579 19183 3  2 32 64 0

*Node B*

SNAP_INTERVAL 30 CPU_CORES 18 VCPUS 72 OSWBB_ARCHIVE_DEST /ora45/dbworkspace/OSWATCHER/oswbb/archive

zzz ***Sat May 9 01:00:15 EDT 2020

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----

r b swpd free buff cache si so bi bo in cs us sy id wa st

6 123 0 32364372 303780 40037240 0 0 561 153 0 0 3 1 94 3 0

1 125 0 32371232 303780 40037456 0 0 41317 30810 35987 45850 4  1 27 67 0

5 123 0 32371060 303780 40037644 0 0 30972 23008 43202 56629 3  1 27 69 0

zzz ***Sat May 9 01:00:45 EDT 2020

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----

r b swpd free buff cache si so bi bo in cs us sy id wa st

4 119 0 32338792 303780 40038420 0 0 561 153 0 0 3 1 94 3 0

2 124 0 32329172 303780 40038840 0 0 12392 9241 18276 20114 3  1 30 66 0

3 118 0 32334116 303780 40038836 0 0 16690 11341 17579 19183 3  2 32 64 0

*From AWR during Level 0 backup*

*Top 10 Foreground Events by Total Wait Time*

*Event*

*Waits*

*Total Wait Time (sec)*

*Avg Wait*

*% DB time*

*Wait Class*

db file sequential read

124,916

8451.4

67.66ms

83.9

User I/O

control file sequential read

25,283

142.3

5.63ms

1.4

System I/O

DB CPU 87.3

.9

log file sync

158

41

259.41ms

.4

Commit

gc current block 2-way

131,697

13.7

104.37us

.1

Cluster

name-service call wait

82

12.4

150.77ms

.1

Other

gc cr grant 2-way

62,345

7.3

117.49us

.1

Cluster

cursor: pin S wait on X

617

5.8

9.40ms

.1

Concurrency

Sync ASM rebalance

9

4.9

545.95ms

.0

Other

library cache lock

446

3.8

8.54ms

.0

Concurrency

I tried to collect MML wait during Level 1 backup window as I could not collect the same during Level 0 backup.

*Before starting Level 0*

Backup: MML write backup piece 301955.357264

Backup: MML initialization 0.001998

Backup: MML delete backup piece 79.890461

Backup: MML extended initialization 218.460778

Backup: MML commit backup piece 452.491904

Backup: MML shutdown                   642.291437

Backup: MML create a backup piece      52.15988

Backup: MML query backup piece         159.223808



Total                                  303559.87753

*After*

Backup: MML write backup piece 304953.207321

Backup: MML initialization 0.002076

Backup: MML delete backup piece 79.890461

Backup: MML extended initialization 227.604029

Backup: MML commit backup piece 480.266509

Backup: MML shutdown                   657.297723

Backup: MML create a backup piece      83.378908

Backup: MML query backup piece         159.562624



Total                                  306650.213124





3090.34             MML           (306650.213124 - 303559.87753)

4392                Elapsed       (2540 + 1852)

1301.66             RMAN         (Elapsed - MML)

70.36               Percent spent on MML            70% time spent on MML

Archive log backup also started during ID backup, so elapsed time calculated as sum of ID and Archive.

5/10/2020 11:01:55 PM     5/10/2020 11:44:15 PM     3374.81       313.02 DB
INCR      2540

5/10/2020 11:13:04 PM     5/10/2020 11:43:56 PM     105.58        105.59
     ARCHIVELOG   1852

We only see this high load on the server when the backups are running.

I am trying to isolate where is the IO bottleneck before i talk to system admin, is it on Server side or storage side ? . Also is there any utilities i can use to monitor IO waits as a non-root user. Please suggest.

Thanks,
Mani

--
http://www.freelists.org/webpage/oracle-l