Subject: Very slow pipe/TCP connection in 1.6_BETA4
To: None <current-users@netbsd.org>
From: Andreas Wrede <andreas@planix.com>
List: current-users
Date: 07/08/2002 11:02:41
I am running a Amanda amrecover for a single file on a i386/1.6_BETA4
system and the througput through /dev/nrst0 >> amrestore >pipe> gzip
-d >TCP> /sbin/restore manages less than 10Kbytes/sec.
A tcpdump shows that the ACK is sent 0.2 seconds after the packet it
acknowledges:
10:08:06.805509 localhost.amidxtape > localhost.748: P 81920:98304(16384) ack 1 win 16384 <nop,nop,timestamp 99618 1>
10:08:07.005142 localhost.748 > localhost.amidxtape: . ack 98304 win 65535 <nop,nop,timestamp 99619 99618>
10:08:12.005763 localhost.amidxtape > localhost.748: P 98304:114688(16384) ack 1 win 16384 <nop,nop,timestamp 99629 1>
10:08:12.205674 localhost.748 > localhost.amidxtape: . ack 114688 win 65535 <nop,nop,timestamp 99629 99629>
10:08:12.206045 localhost.amidxtape > localhost.748: P 114688:131072(16384) ack 1 win 16384 <nop,nop,timestamp 99629 1>
10:08:12.405709 localhost.748 > localhost.amidxtape: . ack 131072 win 65535 <nop,nop,timestamp 99630 99629>
netstat shows the Send-Q of the gzip end of the connection
always at 16384 byes, the Recv-Q of the restore side always
at 0 bytes.
ps shows amrestore in state pipdwt, gzip and restore in netio:
UID PID PPID CPU PRI NI VSZ RSS WCHAN STAT TT TIME COMMAND
0 6332 709 0 10 0 272 4 wait IW+ p3 0:00.00 amrecover -s localhost -t localhost
10 6368 322 0 10 0 84 4 wait IW ?? 0:00.00 amidxtaped
0 6369 6332 0 2 0 3044 2756 netio S+ p3 0:05.77 restore xbf 2 - /home/andreas/.kde/share/kde/apps/korganizer/cal-s.vcs
10 6370 6368 0 -6 0 72 672 pipdwt S ?? 0:01.63 amrestore -h -p /dev/nrst0 woffi ^sd1a$ 20020703
10 6380 6370 0 2 0 540 260 netio S ?? 0:31.55 /usr/bin/gzip -dc
running ktrace on the processes involved (amrestore, gzip and restore)
shows a 5 sec(!) delay after every call to write(1) by amrestore:
[...]
6370 amrestore 0.000083 CALL write(0x5,0x804bae0,0x8000)
6369 restore 5.178410 GIO fd 0 read 2048 bytes
6369 restore 0.000087 RET read 2048/0x800
6369 restore 0.000039 CALL read(0,0x80d6000,0x800)
6369 restore 0.000046 GIO fd 0 read 2048 bytes
6369 restore 0.000190 RET read 2048/0x800
6369 restore 0.000040 CALL read(0,0x80d6000,0x800)
6369 restore 0.000049 GIO fd 0 read 2048 bytes
6369 restore 0.000041 RET read 2048/0x800
6369 restore 0.000033 CALL read(0,0x80d6000,0x800)
6369 restore 0.000043 GIO fd 0 read 2048 bytes
6369 restore 0.000054 RET read 2048/0x800
6369 restore 0.000033 CALL read(0,0x80d6000,0x800)
6369 restore 0.000047 GIO fd 0 read 2048 bytes
6369 restore 0.000039 RET read 2048/0x800
6369 restore 0.000029 CALL read(0,0x80d6000,0x800)
6369 restore 0.000045 GIO fd 0 read 2048 bytes
6369 restore 0.000138 RET read 2048/0x800
6369 restore 0.000039 CALL read(0,0x80d6000,0x800)
6369 restore 0.000049 GIO fd 0 read 2048 bytes
6369 restore 0.000042 RET read 2048/0x800
6369 restore 0.000026 CALL read(0,0x80d6000,0x800)
6369 restore 0.000046 GIO fd 0 read 2048 bytes
6369 restore 0.000054 RET read 2048/0x800
6369 restore 0.000033 CALL read(0,0x80d6000,0x800)
6380 gzip 0.198951 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 4088 bytes
6380 gzip 0.000000 GIO fd 1 wrote 64 bytes
6380 gzip 0.001002 RET write 32768/0x8000
6369 restore 0.000073 GIO fd 0 read 2048 bytes
6369 restore 0.000044 RET read 2048/0x800
6369 restore 0.000035 CALL read(0,0x80d6000,0x800)
6369 restore 0.000155 GIO fd 0 read 2048 bytes
6369 restore 0.000047 RET read 2048/0x800
6369 restore 0.000034 CALL read(0,0x80d6000,0x800)
6369 restore 0.000046 GIO fd 0 read 2048 bytes
6369 restore 0.000055 RET read 2048/0x800
6369 restore 0.000035 CALL read(0,0x80d6000,0x800)
6369 restore 0.000049 GIO fd 0 read 2048 bytes
6369 restore 0.000044 RET read 2048/0x800
6369 restore 0.000031 CALL read(0,0x80d6000,0x800)
6369 restore 0.000048 GIO fd 0 read 2048 bytes
6369 restore 0.000149 RET read 2048/0x800
6369 restore 0.000041 CALL read(0,0x80d6000,0x800)
6369 restore 0.000052 GIO fd 0 read 2048 bytes
6369 restore 0.000076 RET read 2048/0x800
6369 restore 0.000029 CALL read(0,0x80d6000,0x800)
6369 restore 0.000045 GIO fd 0 read 2048 bytes
6369 restore 0.000054 RET read 2048/0x800
6369 restore 0.000032 CALL read(0,0x80d6000,0x800)
6369 restore 0.000045 GIO fd 0 read 2048 bytes
6369 restore 0.000041 RET read 2048/0x800
6369 restore 0.000028 CALL read(0,0x80d6000,0x800)
6380 gzip 0.001505 CALL read(0,0x8076c80,0x8000)
6380 gzip 0.000210 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 4088 bytes
6380 gzip 0.000000 GIO fd 0 read 64 bytes
6380 gzip 0.000877 RET read 32768/0x8000
6370 amrestore 0.000049 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 4088 bytes
6370 amrestore 0.000000 GIO fd 5 wrote 64 bytes
6370 amrestore 0.000871 RET write 32768/0x8000
6370 amrestore 0.000026 CALL read(0x3,0x804bae0,0x8000)
6380 gzip 0.001635 CALL write(0x1,0x80b3de0,0x8000)
6370 amrestore 0.013789 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 4088 bytes
6370 amrestore 0.000000 GIO fd 3 read 64 bytes
6370 amrestore 0.000960 RET read 32768/0x8000
6370 amrestore 0.000025 CALL write(0x5,0x804bae0,0x8000)
6369 restore 5.178135 GIO fd 0 read 2048 bytes
6369 restore 0.000088 RET read 2048/0x800
.. the pattern repeats.
Handles, etc:
USER CMD PID FD MOUNT INUM MODE SZ|DV R/W
amanda amrestore 6370 wd /tmp 12 drwx------ 1536 r
amanda amrestore 6370 0* internet stream tcp c0ef18b4 127.0.0.1:10083 <-> 127.0.0.1:748
amanda amrestore 6370 2 /tmp 44 -rw------- 1082 w
amanda amrestore 6370 3 / 187 crw-rw---- nrst0 r
amanda amrestore 6370 5* pipe 0xc0c1d100 -> 0xc0c1d280 w
amanda gzip 6380 wd /tmp 12 drwx------ 1536 r
amanda gzip 6380 0* pipe 0xc0c1d280 <- 0xc0c1d100 r
amanda gzip 6380 1* internet stream tcp c0ef18b4 127.0.0.1:10083 <-> 127.0.0.1:748
amanda gzip 6380 2 /tmp 44 -rw------- 1082 w
amanda gzip 6380 3 / 187 crw-rw---- nrst0 r
root restore 6369 wd /m2 2 drwxrwxr-x 512 r
root restore 6369 0* internet stream tcp c0ef1010 127.0.0.1:748 <-> 127.0.0.1:10083
root restore 6369 1 / 1119 crw--w---- ttyp3 rw
root restore 6369 2 / 1119 crw--w---- ttyp3 rw
root restore 6369 3* internet stream tcp c0d55da0 127.0.0.1:529 <-> 127.0.0.1:10082
root restore 6369 4* internet stream tcp c0ef1010 127.0.0.1:748 <-> 127.0.0.1:10083
root restore 6369 5 / 373 crw-rw-rw- tty r
root restore 6369 6 /tmp 13 -rw------- 3737404 r
root restore 6369 10 /tmp 42 -rw------- 3859 w
The machine has no other load. Changing the interface (real-ethernet
or loopback) makes no difference. The only other relevant info might
be that I have set net.inet.tcp.cwm=0.
Does anyone have an idea what is holding things up here?
At the current rate, the restore will finish some time in August but I
need the tape drive before that.
--
- aew