* Jean-Louis Martineau <[email protected]> [20121019 12:39]: > Jean-Francois, > > I already committed many fixes that should improve it a lot. > There are still some case where it will report too much time > (waiting for the driver or operating the changers), they are on my > list of things to fix, but as they are only cosmetic, they do not > get a high priority.
I understand Jean-Louis. Are those fixes in the main branch? thanks for the amazing work! jf > > Jean-Louis > > On 10/18/2012 05:54 PM, Jean-Francois Malouin wrote: > >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</nam! e>! > > \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 >
