No takers on this one? jf
* Jean-Francois Malouin <[email protected]> [20121005 15:11]: > 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
