Amanda-Users

Estimate timeout

2005-08-30 11:08:56
Subject: Estimate timeout
From: "LaValley, Brian E" <BLaValley AT ALLEGROMICRO DOT com>
To: "Amanda (E-mail)" <amanda-users AT amanda DOT org>
Date: Tue, 30 Aug 2005 11:01:52 -0400
Can someone please help me get to the bottom of this issue?  I have Amanda
2.4.4p2 on a Fedora Core 3 machine which is the tape server.  It has no
trouble backing up itself and other Linux machines.  The trouble comes with
a Sun Solaris 8 client which never completes its estimate. I tried to keep
increasing the etimeout value, but I am at 29600 and am wondering how far I
should go?  Is there some other part I should be looking at? Thank you.

The Sun's sendsize log is as follows:

sendsize: debug 1 pid 12359 ruid 548 euid 548: start at Mon Aug 29 18:00:02
2005
sendsize: version 2.4.4p2
sendsize[12359]: time 0.034: waiting for any estimate child: 1 running
sendsize[12361]: time 0.035: calculating for amname
'/dev/vx/dsk/homedg/homevol', dirname '/home', spindle -1
sendsize[12361]: time 0.035: getting size via gnutar for
/dev/vx/dsk/homedg/homevol level 0
sendsize[12361]: time 0.092: spawning /home/backup/amanda_sun/libexec/runtar
in pipeline
sendsize[12361]: argument list: /opt/sfw/bin/gtar --create --file /dev/null
--directory /home --one-file-system --listed-incremental
/home/backup/amanda_sun/var/amanda/gnutar-lists/coneng_dev_vx_dsk_homedg_hom
evol_0.new --sparse --ignore-failed-read --totals --exclude-from
/tmp/amanda/sendsize._dev_vx_dsk_homedg_homevol.20050829180002.exclude .

The server's amdump file is:

amdump: start at Mon Aug 29 18:00:01 EDT 2005
amdump: datestamp 20050829
planner: pid 7543 executable /opt/amanda/libexec/planner version 2.4.4p2
planner: build: VERSION="Amanda-2.4.4p2"
planner:        BUILT_DATE="Thu Aug 11 12:35:19 EDT 2005"
planner:        BUILT_MACH="Linux napier 2.6.9-1.667 #1 Tue Nov 2 14:41:25
EST 2004 i686 i686 i386 GNU/Linux"
planner:        CC="gcc"
planner:        CONFIGURE_COMMAND="'./configure' '--prefix=/opt/amanda'"
planner: paths: bindir="/opt/amanda/bin" sbindir="/opt/amanda/sbin"
planner:        libexecdir="/opt/amanda/libexec" mandir="/opt/amanda/man"
planner:        AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
planner:        CONFIG_DIR="/opt/amanda/etc" DEV_PREFIX="/dev/"
planner:        RDEV_PREFIX="/dev/" DUMP="/sbin/dump"
planner:        RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
planner:        XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF VXRESTORE=UNDEF
planner:        SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/gtar"
planner:        COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
planner:        LPRCMD="/usr/bin/lpr" MAILER="/usr/bin/Mail"
planner:        listed_incr_dir="/opt/amanda/var/amanda/gnutar-lists"
planner: defs:  DEFAULT_SERVER="napier" DEFAULT_CONFIG="daily"
planner:        DEFAULT_TAPE_SERVER="napier"
planner:        DEFAULT_TAPE_DEVICE="/dev/nst0" HAVE_MMAP HAVE_SYSVSHM
planner:        LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
planner:        AMANDA_DEBUG_DAYS=4 BSD_SECURITY USE_AMANDAHOSTS
planner:        CLIENT_LOGIN="backup" FORCE_USERID HAVE_GZIP
planner:        COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
planner:        COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
planner: time 0.000: dgram_bind: socket bound to 0.0.0.0.728
READING CONF FILES...
driver: pid 7544 executable /opt/amanda/libexec/driver version 2.4.4p2
driver: tape size 52433920
driver: send-cmd time 0.003 to taper: START-TAPER 20050829
taper: pid 7545 executable taper version 2.4.4p2
planner: time 0.056: startup took 0.056 secs

SETTING UP FOR ESTIMATES...
planner: time 0.056: setting up estimates for
coneng:/dev/vx/dsk/homedg/homevol
taper: page size is 4096
taper: buffer size is 32768
taper: buffer[00] at 0xf6efd000
taper: buffer[01] at 0xf6f05000
taper: buffer[02] at 0xf6f0d000
taper: buffer[03] at 0xf6f15000
taper: buffer[04] at 0xf6f1d000
taper: buffer[05] at 0xf6f25000
taper: buffer[06] at 0xf6f2d000
taper: buffer[07] at 0xf6f35000
taper: buffer[08] at 0xf6f3d000
taper: buffer[09] at 0xf6f45000
taper: buffer[10] at 0xf6f4d000
taper: buffer[11] at 0xf6f55000
taper: buffer[12] at 0xf6f5d000
taper: buffer[13] at 0xf6f65000
taper: buffer[14] at 0xf6f6d000
taper: buffer[15] at 0xf6f75000
taper: buffer[16] at 0xf6f7d000
taper: buffer[17] at 0xf6f85000
taper: buffer[18] at 0xf6f8d000
taper: buffer[19] at 0xf6f95000
taper: buffer structures at 0xf6f9d000 for 240 bytes
changer: opening pipe to: /opt/amanda/libexec/chg-scsi -info
coneng:/dev/vx/dsk/homedg/homevol overdue 13025 days for level 0
setup_estimate: coneng:/dev/vx/dsk/homedg/homevol: command 0, options:
    last_level -1 next_level0 -13025 level_days 0
    getting estimates 0 (0) -1 (-1) -1 (-1)
planner: time 0.107: setting up estimates for napier:/
napier:/ overdue 11 days for level 0
setup_estimate: napier:/: command 0, options:
    last_level 3 next_level0 -11 level_days 1
    getting estimates 0 (2999630) 3 (38650) -1 (-1)
planner: time 0.146: setting up estimates for napier:/home
setup_estimate: napier:/home: command 0, options:
    last_level 0 next_level0 3 level_days 0
    getting estimates 0 (80282840) 1 (0) -1 (-1)
planner: time 0.209: setting up estimates for napier:/common
napier:/common overdue 13025 days for level 0
setup_estimate: napier:/common: command 0, options:
    last_level -1 next_level0 -13025 level_days 0
    getting estimates 0 (0) -1 (-1) -1 (-1)
planner: time 0.209: setting up estimates took 0.153 secs

GETTING ESTIMATES...
driver: started dumper0 pid 7556
driver: started dumper1 pid 7557
driver: started dumper2 pid 7558
driver: started dumper3 pid 7559
dumper: dgram_bind: socket bound to 0.0.0.0.742
dumper: pid 7557 executable dumper1 version 2.4.4p2, using port 742
dumper: dgram_bind: socket bound to 0.0.0.0.741
dumper: pid 7556 executable dumper0 version 2.4.4p2, using port 741
dumper: dgram_bind: socket bound to 0.0.0.0.743
dumper: pid 7558 executable dumper2 version 2.4.4p2, using port 743
dumper: dgram_bind: socket bound to 0.0.0.0.744
dumper: pid 7559 executable dumper3 version 2.4.4p2, using port 744
changer: got exit: 0 str: 6 15 1 1
changer: opening pipe to: /opt/amanda/libexec/chg-scsi -slot current
changer: got exit: 0 str: 6 /dev/nst0
taper: slot 6: date X        label DailySet1-A06 (new tape)
taper: read label `DailySet1-A06' date `X'
taper: wrote label `DailySet1-A06' date `20050829'
planner: time 10735.451: got result for host napier disk /common: 0 ->
294080K, -1 -> -1K, -1 -> -1K
planner: time 10735.481: got result for host napier disk /home: 0 ->
81027540K, 1 -> 3635110K, -1 -> -1K
planner: time 10735.481: got result for host napier disk /: 0 -> 3193020K, 3
-> 281800K, -1 -> -1K
planner: time 29598.524: error result for host coneng disk
/dev/vx/dsk/homedg/homevol: Estimate timeout from coneng
planner: time 29598.552: getting estimates took 29598.342 secs
FAILED QUEUE:
  0: coneng     /dev/vx/dsk/homedg/homevol
DONE QUEUE:
  0: napier     /common
  1: napier     /home
  2: napier     /

GENERATING SCHEDULE:
--------
ENDFLUSH
DUMP napier fffffeff9ffe0f /common 20050829 13027 0 1970:1:1:0:0:0 147040
4901
DUMP napier fffffeff9ffe0f / 20050829 13 0 1970:1:1:0:0:0 952854 11210 3
2005:8:16:5:23:44 94810 162
DUMP napier fffffeff9ffe0f /home 20050829 2 1 2005:8:26:1:10:29 1817555
60585
--------
driver: adding holding disk 0 dir /backup/amanda/rdumps/dump3 size 83886080
driver: adding holding disk 1 dir /backup/amanda/rdumps/dump2 size 83886080
driver: adding holding disk 2 dir /backup/amanda/ldump size 14698880
reserving 182471040 out of 182471040 for degraded-mode dumps
driver: flush size 0
driver: start time 29598.652 inparallel 4 bandwidth 2200 diskspace 182471040
dir OBSOLETE datestamp 20050829 driver: drain-ends tapeq FIRST big-dumpers
ttt
driver: result time 29598.652 from taper: TAPER-OK
driver: send-cmd time 29598.668 to dumper0: FILE-DUMP 00-00001
/backup/amanda/rdumps/dump3/20050829/napier._common.0 napier fffffeff9ffe0f
/common NODEVICE 0 1970:1:1:0:0:0 256000 GNUTAR 147104
|;bsd-auth;srvcomp-best;index;exclude-list=/opt/amanda/etc/exclude.gtar;
driver: state time 29598.669 free kps: 2170 space: 182323936 taper: idle
idle-dumpers: 3 qlen tapeq: 0 runq: 2 roomq: 0 wakeup: 15 driver-idle:
start-wait
driver: interface-state time 29598.669 if : free 570 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 29598.669 hdisk 0: free 83738976 dumpers 1 hdisk 1:
free 83886080 dumpers 0 hdisk 2: free 14698880 dumpers 0
dumper: stream_client: connected to 198.151.154.11.33238
dumper: stream_client: our side is 0.0.0.0.33241
dumper: stream_client: connected to 198.151.154.11.33239
dumper: stream_client: our side is 0.0.0.0.33242
dumper: stream_client: connected to 198.151.154.11.33240
dumper: stream_client: our side is 0.0.0.0.33243
driver: state time 29613.666 free kps: 2170 space: 182323936 taper: idle
idle-dumpers: 3 qlen tapeq: 0 runq: 2 roomq: 0 wakeup: 86400 driver-idle:
client-constrained
driver: interface-state time 29613.666 if : free 570 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 29613.666 hdisk 0: free 83738976 dumpers 1 hdisk 1:
free 83886080 dumpers 0 hdisk 2: free 14698880 dumpers 0
driver: result time 29782.170 from dumper0: DONE 00-00001 294080 80960 183
[sec 182.929 kb 80960 kps 442.6 orig-kb 294080]
driver: finished-cmd time 30379.942 dumper0 dumped napier:/common
driver: send-cmd time 30379.942 to taper: FILE-WRITE 00-00002
/backup/amanda/rdumps/dump3/20050829/napier._common.0 napier fffffeff9ffe0f
/common 0 20050829
driver: startaflush: FIRST napier /common 80993 52433920
driver: send-cmd time 30379.942 to dumper0: FILE-DUMP 01-00003
/backup/amanda/rdumps/dump2/20050829/napier._.0 napier fffffeff9ffe0f /
NODEVICE 0 1970:1:1:0:0:0 256000 GNUTAR 953024
|;bsd-auth;srvcomp-best;index;exclude-list=/opt/amanda/etc/exclude.gtar;
driver: state time 30379.942 free kps: 2115 space: 181437023 taper: writing
idle-dumpers: 3 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 15 driver-idle:
start-wait
driver: interface-state time 30379.942 if : free 515 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 30379.942 hdisk 0: free 83805087 dumpers 0 hdisk 1:
free 82933056 dumpers 1 hdisk 2: free 14698880 dumpers 0
dumper: stream_client: connected to 198.151.154.11.33248
dumper: stream_client: our side is 0.0.0.0.33251
dumper: stream_client: connected to 198.151.154.11.33249
dumper: stream_client: our side is 0.0.0.0.33252
dumper: stream_client: connected to 198.151.154.11.33250
dumper: stream_client: our side is 0.0.0.0.33253
driver: state time 30394.939 free kps: 2115 space: 181437023 taper: writing
idle-dumpers: 3 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 86400 driver-idle:
client-constrained
driver: interface-state time 30394.939 if : free 515 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 30394.939 hdisk 0: free 83805087 dumpers 0 hdisk 1:
free 82933056 dumpers 1 hdisk 2: free 14698880 dumpers 0
taper: reader-side: got label DailySet1-A06 filenum 1
driver: result time 30398.426 from taper: DONE 00-00002 DailySet1-A06 1 [sec
18.482 kb 80961 kps 4380.4 {wr: writers 2532 rdwait 0.000 wrwait 6.681
filemark 11.386}]
driver: finished-cmd time 30398.488 taper wrote napier:/common
driver: state time 30398.489 free kps: 2115 space: 181518016 taper: idle
idle-dumpers: 3 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 86400 driver-idle:
client-constrained
driver: interface-state time 30398.489 if : free 515 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 30398.489 hdisk 0: free 83886080 dumpers 0 hdisk 1:
free 82933056 dumpers 1 hdisk 2: free 14698880 dumpers 0
driver: result time 38099.589 from dumper0: RQ-MORE-DISK 01-00003
driver: send-cmd time 38099.609 to dumper0: CONTINUE
/backup/amanda/rdumps/dump2/20050829/napier._.0 256000 47680
driver: state time 38099.610 free kps: 2115 space: 181470336 taper: idle
idle-dumpers: 3 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 86400 driver-idle:
client-constrained
driver: interface-state time 38099.610 if : free 515 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 38099.610 hdisk 0: free 83886080 dumpers 0 hdisk 1:
free 82885376 dumpers 1 hdisk 2: free 14698880 dumpers 0
driver: result time 38128.887 from dumper0: DONE 01-00003 3171490 970731
7749 [sec 7748.732 kb 970731 kps 125.3 orig-kb 3171490]
driver: finished-cmd time 39972.833 dumper0 dumped napier:/
driver: send-cmd time 39972.833 to taper: FILE-WRITE 00-00004
/backup/amanda/rdumps/dump2/20050829/napier._.0 napier fffffeff9ffe0f / 0
20050829
driver: startaflush: FIRST napier / 970860 52352927
driver: send-cmd time 39972.833 to dumper0: FILE-DUMP 01-00005
/backup/amanda/rdumps/dump3/20050829/napier._home.1 napier fffffeff9ffe0f
/home NODEVICE
1 2005:8:26:1:10:29 256000 GNUTAR 1817856
|;bsd-auth;srvcomp-best;index;exclude-list=/opt/amanda/etc/exclude.gtar;
driver: state time 39972.834 free kps: 2170 space: 179682324 taper: writing
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle:
not-idle
driver: interface-state time 39972.834 if : free 570 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 39972.834 hdisk 0: free 82068224 dumpers 1 hdisk 1:
free 82915220 dumpers 0 hdisk 2: free 14698880 dumpers 0
dumper: stream_client: connected to 198.151.154.11.33262
dumper: stream_client: our side is 0.0.0.0.33265
dumper: stream_client: connected to 198.151.154.11.33263
dumper: stream_client: our side is 0.0.0.0.33266
dumper: stream_client: connected to 198.151.154.11.33264
dumper: stream_client: our side is 0.0.0.0.33267
taper: reader-side: got label DailySet1-A06 filenum 2
driver: result time 40427.763 from taper: DONE 00-00004 DailySet1-A06 2 [sec
454.927 kb 970732 kps 2133.8 {wr: writers 30337 rdwait 323.781 wrwait
125.391 filemark 5.193}]
driver: finished-cmd time 40428.312 taper wrote napier:/
driver: state time 40428.313 free kps: 2170 space: 180653184 taper: idle
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle:
not-idle
driver: interface-state time 40428.313 if : free 570 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 40428.313 hdisk 0: free 82068224 dumpers 1 hdisk 1:
free 83886080 dumpers 0 hdisk 2: free 14698880 dumpers 0
driver: result time 57938.307 from dumper0: DONE 01-00005 3635660 1553613
17965 [sec 17965.056 kb 1553613 kps 86.5 orig-kb 3635660]
driver: finished-cmd time 58086.354 dumper0 dumped napier:/home
driver: send-cmd time 58086.354 to taper: FILE-WRITE 00-00006
/backup/amanda/rdumps/dump3/20050829/napier._home.1 napier fffffeff9ffe0f
/home 1 20050829driver: startaflush: FIRST napier /home 1553838 51382067
driver: state time 58086.355 free kps: 2200 space: 180917202 taper: writing
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle:
not-idle
driver: interface-state time 58086.355 if : free 600 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 58086.355 hdisk 0: free 82332242 dumpers 0 hdisk 1:
free 83886080 dumpers 0 hdisk 2: free 14698880 dumpers 0
taper: reader-side: got label DailySet1-A06 filenum 3
driver: result time 58374.520 from taper: DONE 00-00006 DailySet1-A06 3 [sec
288.165 kb 1553614 kps 5391.4 {wr: writers 48552 rdwait 182.654 wrwait
93.531 filemark 11.095}]
driver: finished-cmd time 58375.093 taper wrote napier:/home
driver: state time 58375.093 free kps: 2200 space: 182471040 taper: idle
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle:
not-idle
driver: interface-state time 58375.093 if : free 600 if ETH0: free 600 if
LOCAL: free 1000
driver: hdisk-state time 58375.093 hdisk 0: free 83886080 dumpers 0 hdisk 1:
free 83886080 dumpers 0 hdisk 2: free 14698880 dumpers 0
driver: QUITTING time 58375.093 telling children to quit
driver: send-cmd time 58375.093 to dumper0: QUIT
driver: send-cmd time 58375.094 to dumper1: QUIT
driver: send-cmd time 58375.094 to dumper2: QUIT
driver: send-cmd time 58375.095 to dumper3: QUIT
driver: send-cmd time 58375.095 to taper: QUIT
taper: DONE [idle wait: 57586.600 secs]
taper: writing end marker. [DailySet1-A06 OK kb 2605472 fm 3]
driver: FINISHED time 58378.168
amdump: end at Tue Aug 30 10:12:59 EDT 2005

<Prev in Thread] Current Thread [Next in Thread>