Home -> Mailing Lists -> Oracle-L -> Slow RMAN Channel - KSV master wait/ ASM file metadata operation/ kfk: async disk IO

Slow RMAN Channel - KSV master wait/ ASM file metadata operation/ kfk: async disk IO

From: Chris Taylor <christopherdtaylor1994_at_gmail.com>
Date: Tue, 30 Oct 2018 10:44:22 -0500
Message-ID: <CAP79kiS3dhHrPycDh+EpVi3tKCfhgW_L2QEho-tnXwDOnaFHQA_at_mail.gmail.com> 





Oracle 12.1.0.2 Linux x86-64



Background:


We're running a Level0 and a Level1 Merge of a 75+ TB database to an ASM
diskroup.



    
  
  •   Looking for comments/ideas/suggestions on whether this is 'normal' or if
its really slow?  Seems like a problem to me but I'm not sure as I've never
done a Level1 Merge so maybe reading the SYSTEM datafile is supposed to be
slow for this step? **






The Level0 ran fine, the Level1 merge started and ran fine for hours.



Now all but one of my RMAN channels (6 total) are finished but one channel
is writing very slowly.



Tracing the problematic session shows below:






File# 1 is the system datafile which is size 32.99 GB.



Looking at the session from v$session shows:
MODULE CLIENT_INFO ACTION OSUSER EVENT WAIT_TIME_SECS WAIT_CLASS

backup incr datafile rman channel=d0 0000080 STARTED16 oracle Disk file
operations I/O 0.000005 User I/O


Strace shows:


io_submit(139813557071872, 1, {{data:0x7f28dcb09c48, pread, filedes:325,
buf:0x7f28dc36d000, nbytes:524288, offset:1734379831296}}) = 1

times(NULL)                             = 509955577
times(NULL)                             = 509955577


io_getevents(139813557071872, 4, 128, {{0x7f28dcb09ee8, 0x7f28dcb09ee8,
524288, 0}, {0x7f28dcb0a188, 0x7f28dcb0a188, 524288, 0}}, {0, 0}) = 2

times(NULL)                             = 509955577


getrusage(0x1 /* RUSAGE_??? */, {ru_utime={88371, 365510}, ru_stime={1383,
903614}, ...}) = 0

times(NULL)                             = 509955584


io_submit(139813557071872, 1, {{data:0x7f28dcb09ee8, pread, filedes:325,
buf:0x7f28dc2ec000, nbytes:524288, offset:1734380355584}}) = 1

times(NULL)                             = 509955584
times(NULL)                             = 509955584
times(NULL)                             = 509955584
times(NULL)                             = 509955584


io_submit(139813557071872, 1, {{data:0x7f28dcb0a188, pread, filedes:325,
buf:0x7f28dc04d000, nbytes:524288, offset:1734380879872}}) = 1

times(NULL)                             = 509955584
times(NULL)                             = 509955584


io_getevents(139813557071872, 4, 128, {{0x7f28dcb0a428, 0x7f28dcb0a428,
524288, 0}, {0x7f28dcb09c48, 0x7f28dcb09c48, 524288, 0}}, {0, 0}) = 2

times(NULL)                             = 509955584





So strace shows it streaming operations quickly but I can't figure out why
its taking so long.



The last operation to the rman log file was at 21:55 (9:55pm) last night.



Here's a sample of the RMAN output before it quit writing to the log -  you
can see the write times were pretty snappy then it looks like they started
slowing down.



channel d3: starting piece 1 at 201810292132
channel d3: finished piece 1 at 201810292135
piece handle=+ACTSENTRY/sentry/datafile/u6tgtjra tag=SENTRY_ comment=NONE

channel d3: backup set complete, elapsed time: 00:02:45
channel d3: starting compressed incremental level 1 datafile backup set
channel d3: specifying datafile(s) in backup set


including current control file in backup set
channel d3: starting piece 1 at 201810292135
channel d3: finished piece 1 at 201810292136
piece handle=+ACTSENTRY/sentry/datafile/u7tgtk0h tag=SENTRY_ comment=NONE

channel d3: backup set complete, elapsed time: 00:00:25
channel d3: starting compressed incremental level 1 datafile backup set
channel d3: specifying datafile(s) in backup set


including current SPFILE in backup set


channel d3: starting piece 1 at 201810292136
channel d3: finished piece 1 at 201810292136
piece handle=+ACTSENTRY/sentry/datafile/u8tgtk23 tag=SENTRY_ comment=NONE
channel d3: backup set complete, elapsed time: 00:00:03
channel d2: finished piece 1 at 201810292137
piece handle=+ACTSENTRY/sentry/datafile/u2tgtj8t tag=SENTRY_ comment=NONE
channel d2: backup set complete, elapsed time: 00:15:00
channel d5: finished piece 1 at 201810292141
piece handle=+ACTSENTRY/sentry/datafile/u4tgtjcp tag=SENTRY_ comment=NONE
channel d5: backup set complete, elapsed time: 00:17:06
channel d4: finished piece 1 at 201810292145
piece handle=+ACTSENTRY/sentry/datafile/u3tgtjb0 tag=SENTRY_ comment=NONE
channel d4: backup set complete, elapsed time: 00:22:02
channel d1: finished piece 1 at 201810292155
piece handle=+ACTSENTRY/sentry/datafile/u5tgtjp6 tag=SENTRY_ comment=NONE
channel d1: backup set complete, elapsed time: 00:24:38


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


Received on Tue Oct 30 2018 - 16:44:22 CET












Original text of this message