On Thu, Aug 19, 2010 at 6:09 PM, Dustin J. Mitchell <[email protected]> wrote: > There is a bit of taper/driver communication that should go on during > that pause (REQUEST-NEW-TAPE/NEW-TAPE). That should be recorded in > the amdump log. Can you attach that?
I got this in private mail (the mailing list rejected it). Here are the three key lines: driver: send-cmd time 9089.582 to taper: FILE-WRITE 03-00005 /holddisk/down/20100818201101/gertrude._opt_amanda.0 gertrude /opt/amanda 0 20100818201101 0 495980 driver: result time 9089.585 from taper: REQUEST-NEW-TAPE 03-00005 driver: send-cmd time 57627.988 to taper: NEW-TAPE So: (1) driver asks taper to write from holding, (2) taper asks for permisson to use the new tape, and (3) driver says "sure!" -- 48538.403 seconds later. You mentioned earlier that you are using flushing parameters. I was thrown off the trail by your mention of timestamps. 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. This is going to have to wait until Jean-Louis returns - he is the only person on earth who understands the mental gymnastics that go into those flush parameters. The driver is a maze of twisty little passages, all alike, and I don't dare touch it (you should find this shocking, given that I've been working full-time on Amanda for 4 years!). I suppose we could fix the underlying reporting issue by simply subtracting the time spent in the REQUEST-NEW-TAPE negotiation, but I have the feeling there's a deeper bug here. Dustin -- Open Source Storage Engineer http://www.zmanda.com
