Hi,
Just upgraded to 3.3.2 from 3.3.0 and I noticed the same problem that
I reported back in summer 2010 when I upgraded to 3.1.1: amreport
taper stats are not indicative of the real tape performance when
flushing parameters are in effect.
3.3.0 didn't have this problem btw.
I'm using the flushing parameters
flush-threshold-dumped 100
flush-threshold-scheduled 100
taperflush 100
autoflush yes
Dustin comment at the time was (freely reformated)
> Now I see that the flush parameters *are* relevant, as the driver is holding
> off on granting permission to use the new volume until the parameters are met.
> The time spent waiting for permission from the driver is counted along with
> the
> time spent operating the changer in the final, reported time. Arguably the
> bug
> is that the driver requests that the taper begin a dump when the flush
> thresholds are not met - in fact, I thought this was how the flush thresholds
> were implemented. The actual implementation seems a very odd workaround.
amreport, amdump log and driver debug file (trimmed) are appended.
Look at the DLE gertrude:/opt/amanda. Reports says it took 480m to write 700MB
to tape but when I look at the driver debug file I see that it took 10s...
amreport:
STATISTICS:
Total Full Incr. Level:#
-------- -------- -------- --------
Estimate Time (hrs:min) 0:02
Run Time (hrs:min) 13:31
Dump Time (hrs:min) 9:00 8:02 0:58
Output Size (meg) 1865499.4 1692378.8 173120.6
Original Size (meg) 1865499.4 1692378.8 173120.6
Avg Compressed Size (%) 100.0 100.0 100.0
DLEs Dumped 13 5 8 1:8
Avg Dump Rate (k/s) 58953.1 59868.1 51289.9
Tape Time (hrs:min) 13:27 13:06 0:21
Tape Size (meg) 1865499.4 1692378.8 173120.6
Tape Used (%) 251.0 226.0 25.1
DLEs Taped 13 5 8 1:8
Parts Taped 58 46 12 1:12
Avg Tp Write Rate (k/s) 39447.2 36752.6 139258
USAGE BY TAPE:
Label Time Size % DLEs Parts
av48-2_up_Q00190 3:36 1165007M 150.9 2 30
av48-2_up_Q00191 1:48 700492M 90.7 11 28
NOTES:
taper: Slot 7 with label av48-2_up_Q00190 is usable
taper: tape av48-2_up_Q00190 kb 1192967192 fm 30 [OK]
taper: Slot 24 with label av48-2_up_Q00191 is usable
taper: tape av48-2_up_Q00191 kb 717304228 fm 28 [OK]
DUMP SUMMARY:
DUMPER STATS TAPER
STATS
HOSTNAME DISK L ORIG-MB OUT-MB COMP% MMM:SS KB/s MMM:SS
KB/s
-----------------------------
------------------------------------------------------
edgar /opt/amanda 0 1003 1003 -- 0:46 22277.9 0:17
60388.2
gaspar /opt/amanda 0 2042 2042 -- 1:07 31186.7 0:21
99573.3
gertrude /opt/amanda 0 719 719 -- 0:28 26354.9 479:16
25.6
tullus /raid/hrrt1 1 10 10 -- 0:02 6560.8 0:05
2108.0
tullus /raid/hrrt2 1 4 4 -- 0:01 6314.1 0:05
824.0
tullus /raid/hrrt3 1 14 14 -- 0:04 4020.1 0:05
2906.0
tullus /raid/hrrt4 1 173056 173056 -- 57:19 51534.0 20:39
143026.2
tullus /raid/hrrt5 1 3 3 -- 0:00 6685.8 0:04
737.5
tullus /raid/hrrt6 1 32 32 -- 0:11 3022.5 0:05
6536.0
tullus /raid/hrrt7 1 1 1 -- 0:00 2666.2 0:05
250.0
tullus /raid/hrrt8 0 1687909 1687909 -- 479:29 60079.9 305:46
94212.3
tullus /raid/proj1 1 0 0 -- 0:00 667.6 0:05 8.0
wart /opt/amanda 0 706 706 -- 0:37 19452.8 0:13
55637.7
(brought to you by Amanda version 3.3.2)
-----------
amdump log:
driver: send-cmd time 147.563 to dumper4: PORT-DUMP 04-00005 26059 gertrude
ffffffff9efefbffffffffff01 /opt/aman da NODEVICE 0 1970:1:1:0:0:0 amgtar "" ""
"" "" BSDTCP AMANDA 127.0.0.1:26060 20 |" <auth>BSDTCP</auth>\n <rec
ord>NO</record>\n <datapath>AMANDA</datapath>\n <backup-program>\n
<plugin>amgtar</plugin>\n <property>\ n <name>ignore</name>\n
<value encoding=\"raw\" raw=\"OiBEaXJlY3RvcnkgaXMgbmV3JA==\">:_Directory_is_ne
w$</value> <value encoding=\"raw\"
raw=\"OiBEaXJlY3RvcnkgaGFzIGJlZW4gcmVuYW1lZA==\">:_Directory_has_been_re
named</value> <value encoding=\"raw\"
raw=\"OiBmaWxlIGNoYW5nZWQgYXMgd2UgcmVhZCBpdCQ=\">:_file_changed_as_we
_read_it$</value> <value encoding=\"raw\"
raw=\"OiBzb2NrZXQgaWdub3JlZCQ=\">:_socket_ignored$</value> < value
encoding=\"raw\"
raw=\"OiBDYW5ub3Qgc3RhdDogTm8gc3VjaCBmaWxlIG9yIGRpcmVjdG9yeSQ=\">:_Cannot_stat:_No_such_f
ile_or_directory$</value>\n </property>\n <property>\n
<name>check-device</name>\n!
<value>NO</va lue>\n </property>\n </backup-program>\n"
driver: result time 175.534 from dumper4: DONE 04-00005 736280 736280 28 "[sec
27.937 kb 736280 kps 26354.9 orig -kb 736280]"
driver: finished-cmd time 175.534 dumper4 dumped gertrude:/opt/amanda
driver: send-cmd time 175.534 to chunker4: DONE 04-00005
driver: result time 175.534 from chunker4: DONE 04-00005 736280 "[sec 27.968 kb
736280 kps 26326.1]"
driver: finished-cmd time 175.534 chunker4 chunked gertrude:/opt/amanda7.968 kb
736280 kps 26326.1]"
driver: send-cmd time 175.535 to taper: FILE-WRITE worker0 04-00007
/holddisk/up/20121004201101/gertrude._opt_am anda.0 gertrude /opt/amanda 0
20121004201101 "" "" "" "" 42949672960 memory "" 8589934592
736280gertrude._opt_amdriver: startaflush: LARGESTFIT gertrude /opt/amanda
736312 09672960 memory "" 8589934592 736280
taper: status file gertrude /opt/amanda:/var/tmp/amanda/taper_status_file_m1R1WM
driver: result time 175.539 from taper: REQUEST-NEW-TAPE 04-00007
driver: send-cmd time 175.539 to taper: START-SCAN worker0 04-00007
driver: started chunker4 pid 26552aper: START-SCAN worker0 04-00007
driver: result time 28932.218 from taper: DONE 04-00007 INPUT-GOOD TAPE-GOOD
"[sec 28756.000000 bytes 753950720 kps 25.604396 orig-kb 736280]" "" ""
driver: finished-cmd time 28932.218 taper wrote gertrude:/opt/amanda
-----------
taper.debug
Thu Oct 4 20:12:12 2012: thd-0x2141a40: taper: av48: updating state
Thu Oct 4 20:13:57 2012: thd-0x2141a40: taper: Amanda::Taper::Scribe preparing
to write, part size 42949672960, using LEOM (falling back to holding disk as
cache) (splitter) (LEOM supported)
Thu Oct 4 20:13:57 2012: thd-0x2141a40: taper: Starting <Xfer@0x2cf7dd0
(<XferSourceHolding@0x2d33830> -> <XferDestTaperSplitter@0x2d100a0>)>
Thu Oct 4 20:13:57 2012: thd-0x2141a40: taper: Final linkage:
<XferSourceHolding@0x2d33830> -(PULL_BUFFER)-> <XferElementGlue@0x2d358c0>
-(PUSH_BUFFER)-> <XferDestTaperSplitter@0x2d100a0>
Fri Oct 5 04:12:57 2012: thd-0x2141a40: taper: Building type TAPESTART header
of 2097152-2097152 bytes with name='av48-2_up_Q00190' disk='' dumplevel=0 and
blocksize=2097152
Fri Oct 5 04:13:01 2012: thd-0x2141a40: taper: invoking /usr/sbin/mtx -f
/dev/changer status
Fri Oct 5 04:13:03 2012: thd-0x2141a40: taper: av48: updating state
Fri Oct 5 04:13:03 2012: thd-0x2c4d3a0: taper: Building type SPLIT_FILE header
of 2097152-2097152 bytes with name='gertrude' disk='/opt/amanda' dumplevel=0
and blocksize=2097152
Fri Oct 5 04:13:13 2012: thd-0x2141a40: taper: Amanda::Taper::Scribe preparing
to write, part size 42949672960, using LEOM (falling back to holding disk as
cache) (splitter) (LEOM supported)
Fri Oct 5 04:13:13 2012: thd-0x2141a40: taper: Starting <Xfer@0x2d0c210
(<XferSourceHolding@0x2d338c0> -> <XferDestTaperSplitter@0x2d101e0>)>
Fri Oct 5 04:13:13 2012: thd-0x2141a40: taper: Final linkage:
<XferSourceHolding@0x2d338c0> -(PULL_BUFFER)-> <XferElementGlue@0x2d359a0>
-(PUSH_BUFFER)-> <XferDestTaperSplitter@0x2d101e0>
thanks!
jf
