Veritas-bu

[Veritas-bu] RMAN performance doth sucketh on media server.

2005-05-24 08:46:47
Subject: [Veritas-bu] RMAN performance doth sucketh on media server.
From: ckstehman AT pepco DOT com (ckstehman AT pepco DOT com)
Date: Tue, 24 May 2005 08:46:47 -0400
This is a multipart message in MIME format.
--=_alternative 004633B88525700B_=
Content-Type: text/plain; charset="US-ASCII"
Content-Disposition: inline

Putting a media server on a machine with Oracle is not a good idea in my 
view
We have dedicated systems for media servers.  Veritas uses alot of CPU 
when
copying data to the media.  I suggest you move the media server to a 
dedicated
system
=============================
Carl Stehman
PHI Services Company
202-331-6619
Pager 301-765-2703
ckstehman AT pepco DOT com



Mark.Donaldson AT cexp DOT com 
Sent by: veritas-bu-admin AT mailman.eng.auburn DOT edu
05/23/2005 08:41 PM

To
veritas-bu AT mailman.eng.auburn DOT edu
cc

Subject
[Veritas-bu] RMAN performance doth sucketh on media server.






I've got a media server with several large Oracle databases on it.  Simply
put, the performance sucks. 

It's an RMAN backup with 4 channels, MPX'd to 4/drive (so we're using one
tape drive).  I'm also making an in-line tape copy to a second tape at the
same time for off-site purposes.  Both tape drives are LTO2 shared in an 
SSO
environment.

Monitoring iostat, I see a burst of ~2MB/sec or so, usually after the
write_data "start writing data when first buffer is available" is logged,
then a fallback to 100/200/300 KB/sec for the remainder of the job.  The
"waiting on full/empty" buffer notes are few but when they are there, it's
"waiting on full buffer".

Here's the brief report from my summarizer on the policy:

---------------------------------------
## Gathering data.....Done.
## Write to buffer waiting on available buffer:
No Data Found.

## Write to tape waiting on full buffer:
Min: 38363  Avg: 58225  Max: 134966 with 13 samples
---------------------------------------

The bptm logs are showing the job spending a lot of time doing this:

   0.0  0.0  0.0    0.0    0.0   0   0 rmt/13
    0.0    0.0    0.0 


18:16:19.866 [28104] <2> io_write_back_header: drive index 14,
ue-13_1116892156, file num = 88, mpx_headers = 3, copy 1
18:16:19.869 [28104] <2> io_write_back_header: drive index 14,
ue-13_1116892192, file num = 88, mpx_headers = 2, copy 1
18:16:19.870 [28104] <2> io_write_back_header: drive index 14,
ue-13_1116892207, file num = 88, mpx_headers = 1, copy 1
18:16:19.871 [28104] <2> write_data: completed writing backup header, 
start
writing data when first buffer is available, copy 1
18:16:19.878 [28104] <2> write_data: absolute block position prior to
writing backup header(s) is 878978, copy 2
18:16:19.878 [28104] <2> write_data: block position check: actual 878978,
expected 878978
18:16:19.878 [28104] <2> io_write_back_header: drive index 13,
ue-13_1116892156, file num = 96, mpx_headers = 3, copy 2
18:16:19.881 [28104] <2> io_write_back_header: drive index 13,
ue-13_1116892192, file num = 96, mpx_headers = 2, copy 2
18:16:19.882 [28104] <2> io_write_back_header: drive index 13,
ue-13_1116892207, file num = 96, mpx_headers = 1, copy 2
18:16:19.883 [28104] <2> write_data: completed writing backup header, 
start
writing data when first buffer is available, copy 2
18:16:19.883 [28104] <2> write_data: first write, twin_index: 0 cindex: 2
dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
18:16:19.883 [28104] <2> write_data: received first buffer (262144 bytes),
begin writing data
18:16:23.608 [26567] <2> bptm: INITIATING (VERBOSE = 0): -U
18:16:23.610 [26567] <2> db_byid: search for media id 005111
18:16:23.610 [26567] <2> db_byid: 005111 found at offset 2
18:16:23.622 [26567] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:16:23.622 [26567] <2> db_byid: search for media id 005121
18:16:23.622 [26567] <2> db_byid: 005121 found at offset 4
18:16:23.642 [26567] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:16:23.642 [26567] <2> bptm: EXITING with status 0 <----------
18:16:41.852 [28104] <2> write_backup: write_data() returned, exit_status 
=
0, CINDEX = 2, TWIN_INDEX = 0, backup_status = -7
18:16:41.852 [28104] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.17789)
on drive index 14
18:16:43.199 [28104] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.17789)
on drive index 13

<snip>

18:25:25.096 [29843] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:25.098 [29843] <2> db_byid: search for media id 005111
18:25:25.098 [29843] <2> db_byid: 005111 found at offset 2
18:25:25.110 [29843] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:25.110 [29843] <2> db_byid: search for media id 005121
18:25:25.111 [29843] <2> db_byid: 005121 found at offset 4
18:25:25.130 [29843] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:25.130 [29843] <2> bptm: EXITING with status 0 <----------
18:25:30.625 [29901] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:30.627 [29901] <2> db_byid: search for media id 005111
18:25:30.627 [29901] <2> db_byid: 005111 found at offset 2
18:25:30.639 [29901] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:30.639 [29901] <2> db_byid: search for media id 005121
18:25:30.639 [29901] <2> db_byid: 005121 found at offset 4
18:25:30.659 [29901] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:30.659 [29901] <2> bptm: EXITING with status 0 <----------
18:25:35.991 [29978] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:35.993 [29978] <2> db_byid: search for media id 005111
18:25:35.993 [29978] <2> db_byid: 005111 found at offset 2
18:25:36.008 [29978] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:36.008 [29978] <2> db_byid: search for media id 005121
18:25:36.008 [29978] <2> db_byid: 005121 found at offset 4
18:25:36.028 [29978] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:36.028 [29978] <2> bptm: EXITING with status 0 <----------
18:25:39.407 [29983] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:39.409 [29983] <2> db_byid: search for media id 005111
18:25:39.409 [29983] <2> db_byid: 005111 found at offset 2
18:25:39.428 [29983] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:39.428 [29983] <2> db_byid: search for media id 005121
18:25:39.428 [29983] <2> db_byid: 005121 found at offset 4
18:25:39.448 [29983] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:39.449 [29983] <2> bptm: EXITING with status 0 <----------
18:25:42.651 [29998] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:42.653 [29998] <2> db_byid: search for media id 005111
18:25:42.653 [29998] <2> db_byid: 005111 found at offset 2
18:25:42.667 [29998] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:42.667 [29998] <2> db_byid: search for media id 005121
18:25:42.667 [29998] <2> db_byid: 005121 found at offset 4
18:25:42.687 [29998] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:42.687 [29998] <2> bptm: EXITING with status 0 <----------
18:25:53.231 [57] <2> bptm: INITIATING (VERBOSE = 0): -U
18:25:53.233 [57] <2> db_byid: search for media id 005111
18:25:53.233 [57] <2> db_byid: 005111 found at offset 2
18:25:53.246 [57] <2> db_lock_media: unable to lock media at offset 2
(005111)
18:25:53.246 [57] <2> db_byid: search for media id 005121
18:25:53.246 [57] <2> db_byid: 005121 found at offset 4
18:25:53.266 [57] <2> db_lock_media: unable to lock media at offset 4
(005121)
18:25:53.267 [57] <2> bptm: EXITING with status 0 <----------
_______________________________________________
Veritas-bu maillist  -  Veritas-bu AT mailman.eng.auburn DOT edu
http://mailman.eng.auburn.edu/mailman/listinfo/veritas-bu


This Email message and any attachment may contain information that is
proprietary, legally privileged, confidential and/or subject to copyright
belonging to Pepco Holdings, Inc. or its affiliates ("PHI").  This Email is
intended solely for the use of the person(s) to which it is addressed.  If
you are not an intended recipient, or the employee or agent responsible for
delivery of this Email to the intended recipient(s), you are hereby notified
that any dissemination, distribution or copying of this Email is strictly
prohibited.  If you have received this message in error, please immediately
notify the sender and permanently delete this Email and any copies.  PHI
policies expressly prohibit employees from making defamatory or offensive
statements and infringing any copyright or any other legal right by Email
communication.  PHI will not accept any liability in respect of such
communications.

--=_alternative 004633B88525700B_=
Content-Type: text/html; charset="US-ASCII"
Content-Disposition: inline


<br><font size=2 face="sans-serif">Putting a media server on a machine
with Oracle is not a good idea in my view</font>
<br><font size=2 face="sans-serif">We have dedicated systems for media
servers. &nbsp;Veritas uses alot of CPU &nbsp;when</font>
<br><font size=2 face="sans-serif">copying data to the media. &nbsp;I suggest
you move the media server to a dedicated</font>
<br><font size=2 face="sans-serif">system</font>
<br><font size=2 face="sans-serif">=============================<br>
Carl Stehman<br>
PHI Services Company<br>
202-331-6619<br>
Pager 301-765-2703<br>
ckstehman AT pepco DOT com</font>
<br>
<br>
<br>
<table width=100%>
<tr valign=top>
<td width=40%><font size=1 face="sans-serif"><b>Mark.Donaldson AT cexp DOT 
com</b>
</font>
<br><font size=1 face="sans-serif">Sent by: veritas-bu-admin AT 
mailman.eng.auburn DOT edu</font>
<p><font size=1 face="sans-serif">05/23/2005 08:41 PM</font>
<td width=59%>
<table width=100%>
<tr valign=top>
<td>
<div align=right><font size=1 face="sans-serif">To</font></div>
<td><font size=1 face="sans-serif">veritas-bu AT mailman.eng.auburn DOT 
edu</font>
<tr valign=top>
<td>
<div align=right><font size=1 face="sans-serif">cc</font></div>
<td>
<tr valign=top>
<td>
<div align=right><font size=1 face="sans-serif">Subject</font></div>
<td><font size=1 face="sans-serif">[Veritas-bu] RMAN performance doth sucketh
on media server.</font></table>
<br>
<table>
<tr valign=top>
<td>
<td></table>
<br></table>
<br>
<br>
<br><font size=2><tt>I've got a media server with several large Oracle
databases on it. &nbsp;Simply<br>
put, the performance sucks. <br>
<br>
It's an RMAN backup with 4 channels, MPX'd to 4/drive (so we're using one<br>
tape drive). &nbsp;I'm also making an in-line tape copy to a second tape
at the<br>
same time for off-site purposes. &nbsp;Both tape drives are LTO2 shared
in an SSO<br>
environment.<br>
<br>
Monitoring iostat, I see a burst of ~2MB/sec or so, usually after the<br>
write_data &quot;start writing data when first buffer is available&quot;
is logged,<br>
then a fallback to 100/200/300 KB/sec for the remainder of the job. 
&nbsp;The<br>
&quot;waiting on full/empty&quot; buffer notes are few but when they are
there, it's<br>
&quot;waiting on full buffer&quot;.<br>
<br>
Here's the brief report from my summarizer on the policy:<br>
<br>
---------------------------------------<br>
## Gathering data.....Done.<br>
## Write to buffer waiting on available buffer:<br>
No Data Found.<br>
<br>
## Write to tape waiting on full buffer:<br>
Min: 38363 &nbsp;Avg: 58225 &nbsp;Max: 134966 with 13 samples<br>
---------------------------------------<br>
<br>
The bptm logs are showing the job spending a lot of time doing this:<br>
<br>
 &nbsp; 0.0 &nbsp;0.0 &nbsp;0.0 &nbsp; &nbsp;0.0 &nbsp; &nbsp;0.0 &nbsp;
0 &nbsp; 0 rmt/13<br>
 &nbsp; &nbsp;0.0 &nbsp; &nbsp;0.0 &nbsp; &nbsp;0.0 &nbsp;<br>
<br>
<br>
18:16:19.866 [28104] &lt;2&gt; io_write_back_header: drive index 14,<br>
ue-13_1116892156, file num = 88, mpx_headers = 3, copy 1<br>
18:16:19.869 [28104] &lt;2&gt; io_write_back_header: drive index 14,<br>
ue-13_1116892192, file num = 88, mpx_headers = 2, copy 1<br>
18:16:19.870 [28104] &lt;2&gt; io_write_back_header: drive index 14,<br>
ue-13_1116892207, file num = 88, mpx_headers = 1, copy 1<br>
18:16:19.871 [28104] &lt;2&gt; write_data: completed writing backup header,
start<br>
writing data when first buffer is available, copy 1<br>
18:16:19.878 [28104] &lt;2&gt; write_data: absolute block position prior
to<br>
writing backup header(s) is 878978, copy 2<br>
18:16:19.878 [28104] &lt;2&gt; write_data: block position check: actual
878978,<br>
expected 878978<br>
18:16:19.878 [28104] &lt;2&gt; io_write_back_header: drive index 13,<br>
ue-13_1116892156, file num = 96, mpx_headers = 3, copy 2<br>
18:16:19.881 [28104] &lt;2&gt; io_write_back_header: drive index 13,<br>
ue-13_1116892192, file num = 96, mpx_headers = 2, copy 2<br>
18:16:19.882 [28104] &lt;2&gt; io_write_back_header: drive index 13,<br>
ue-13_1116892207, file num = 96, mpx_headers = 1, copy 2<br>
18:16:19.883 [28104] &lt;2&gt; write_data: completed writing backup header,
start<br>
writing data when first buffer is available, copy 2<br>
18:16:19.883 [28104] &lt;2&gt; write_data: first write, twin_index: 0 cindex:
2<br>
dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0<br>
18:16:19.883 [28104] &lt;2&gt; write_data: received first buffer (262144
bytes),<br>
begin writing data<br>
18:16:23.608 [26567] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:16:23.610 [26567] &lt;2&gt; db_byid: search for media id 005111<br>
18:16:23.610 [26567] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:16:23.622 [26567] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:16:23.622 [26567] &lt;2&gt; db_byid: search for media id 005121<br>
18:16:23.622 [26567] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:16:23.642 [26567] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:16:23.642 [26567] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:16:41.852 [28104] &lt;2&gt; write_backup: write_data() returned, exit_status
=<br>
0, CINDEX = 2, TWIN_INDEX = 0, backup_status = -7<br>
18:16:41.852 [28104] &lt;2&gt; io_ioctl: command (0)MTWEOF 1 from 
(bptm.c.17789)<br>
on drive index 14<br>
18:16:43.199 [28104] &lt;2&gt; io_ioctl: command (0)MTWEOF 1 from 
(bptm.c.17789)<br>
on drive index 13<br>
<br>
&lt;snip&gt;<br>
<br>
18:25:25.096 [29843] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:25.098 [29843] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:25.098 [29843] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:25.110 [29843] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:25.110 [29843] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:25.111 [29843] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:25.130 [29843] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:25.130 [29843] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:25:30.625 [29901] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:30.627 [29901] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:30.627 [29901] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:30.639 [29901] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:30.639 [29901] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:30.639 [29901] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:30.659 [29901] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:30.659 [29901] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:25:35.991 [29978] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:35.993 [29978] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:35.993 [29978] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:36.008 [29978] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:36.008 [29978] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:36.008 [29978] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:36.028 [29978] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:36.028 [29978] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:25:39.407 [29983] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:39.409 [29983] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:39.409 [29983] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:39.428 [29983] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:39.428 [29983] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:39.428 [29983] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:39.448 [29983] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:39.449 [29983] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:25:42.651 [29998] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:42.653 [29998] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:42.653 [29998] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:42.667 [29998] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:42.667 [29998] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:42.667 [29998] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:42.687 [29998] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:42.687 [29998] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
18:25:53.231 [57] &lt;2&gt; bptm: INITIATING (VERBOSE = 0): -U<br>
18:25:53.233 [57] &lt;2&gt; db_byid: search for media id 005111<br>
18:25:53.233 [57] &lt;2&gt; db_byid: 005111 found at offset 2<br>
18:25:53.246 [57] &lt;2&gt; db_lock_media: unable to lock media at offset
2<br>
(005111)<br>
18:25:53.246 [57] &lt;2&gt; db_byid: search for media id 005121<br>
18:25:53.246 [57] &lt;2&gt; db_byid: 005121 found at offset 4<br>
18:25:53.266 [57] &lt;2&gt; db_lock_media: unable to lock media at offset
4<br>
(005121)<br>
18:25:53.267 [57] &lt;2&gt; bptm: EXITING with status 0 &lt;----------<br>
_______________________________________________<br>
Veritas-bu maillist &nbsp;- &nbsp;Veritas-bu AT mailman.eng.auburn DOT edu<br>
http://mailman.eng.auburn.edu/mailman/listinfo/veritas-bu<br>
</tt></font>
<br>
<br><br>This Email message and any attachment may contain information that is 
proprietary, legally privileged, confidential and/or subject to copyright 
belonging to Pepco Holdings, Inc. or its affiliates ("PHI").  This Email is 
intended solely for the use of the person(s) to which it is addressed.  If you 
are not an intended recipient, or the employee or agent responsible for 
delivery of this Email to the intended recipient(s), you are hereby notified 
that any dissemination, distribution or copying of this Email is strictly 
prohibited.  If you have received this message in error, please immediately 
notify the sender and permanently delete this Email and any copies.  PHI 
policies expressly prohibit employees from making defamatory or offensive 
statements and infringing any copyright or any other legal right by Email 
communication.  PHI will not accept any liability in respect of such 
communications.

--=_alternative 004633B88525700B_=--