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.
Jean-Louis
On 10/18/2012 05:54 PM, Jean-Francois Malouin wrote:
No takers on this one?
jf
* Jean-Francois Malouin <jean-francois.malo...@bic.mni.mcgill.ca> [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
