Description of problem: rsync a file between machines. Speed is reported many times true transfer speed Version-Release number of selected component (if applicable): rsync-3.0.7-3.fc12.i686 How reproducible: Every time Steps to Reproduce: 1. rsync -av --progress local-file remote-f12-machine:~/directory/ 2. 3. Actual results: Typical result is 1891895 100% 110.81MB/s 0:00:00 (xfer#1, to-check=0/1) when actual speed is around 45kB/s Expected results: Reported speed should match the correct rate of transfer Additional info: This appears to have been the case for versions of Fedora before f12 (tested f11), and may also be present for current versions?
This message is a reminder that Fedora 12 is nearing its end of life. Approximately 30 (thirty) days from now Fedora will stop maintaining and issuing updates for Fedora 12. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '12'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 12's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 12 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora please change the 'version' of this bug to the applicable version. If you are unable to change the version, please add a comment here and someone will do it for you. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
I can't reproduce this behaviour. Can you please re-run the rsync with -vvvv option and attach the output?
$ rsync -avvvv --progress path-to-file fpath-to-remote/ cmd=<NULL> machine=fiz user=<NULL> path=~/mnt/www/mike/albums/2010/fall2010/ cmd[0]=ssh cmd[1]=fiz cmd[2]=rsync cmd[3]=--server cmd[4]=-vvvvlogDtpre.iLs cmd[5]=. cmd[6]=~/mnt/www/mike/albums/2010/fall2010/ opening connection using: ssh fiz rsync --server -vvvvlogDtpre.iLs . "~/mnt/www/mike/albums/2010/fall2010/" note: iconv_open("UTF-8", "UTF-8") succeeded. (Client) Protocol versions: remote=30, negotiated=30 sending incremental file list [sender] make_file(IMG_20101101_085101.jpg,*,0) [sender] flist start=1, used=1, low=0, high=0 [sender] i=1 /home/mike/Pictures/university/fall2010 IMG_20101101_085101.jpg mode=0100664 len=1253272 uid=500 gid=500 flags=5 send_file_list done file list sent send_files starting server_recv(2) starting pid=3822 (Server) Protocol versions: remote=30, negotiated=30 received 1 names [Receiver] flist start=1, used=1, low=0, high=0 [Receiver] i=1 1 IMG_20101101_085101.jpg mode=0100664 len=1253272 gid=513 flags=0 recv_file_list done get_local_name count=1 /home/mike/mnt/www/mike/albums/2010/fall2010/ generator starting pid=3822 delta-transmission enabled recv_generator(IMG_20101101_085101.jpg,1) send_files(1, /home/mike/Pictures/university/fall2010/IMG_20101101_085101.jpg) count=0 n=0 rem=0 send_files mapped /home/mike/Pictures/university/fall2010/IMG_20101101_085101.jpg of size 1253272 calling match_sums /home/mike/Pictures/university/fall2010/IMG_20101101_085101.jpg IMG_20101101_085101.jpg 32768 2% 0.00kB/s 0:00:00 sending file_sum false_alarms=0 hash_hits=0 matches=0 1253272 100% 58.20MB/s 0:00:00 (xfer#1, to-check=0/1) sender finished /home/mike/Pictures/university/fall2010/IMG_20101101_085101.jpg recv_files(1) starting generate_files phase=1 recv_files(IMG_20101101_085101.jpg) data recv 32768 at 0 data recv 32768 at 32768 data recv 32768 at 65536 data recv 32768 at 98304 data recv 32768 at 131072 data recv 32768 at 163840 data recv 32768 at 196608 data recv 32768 at 229376 data recv 32768 at 262144 data recv 32768 at 294912 data recv 32768 at 327680 data recv 32768 at 360448 data recv 32768 at 393216 data recv 32768 at 425984 data recv 32768 at 458752 data recv 32768 at 491520 data recv 32768 at 524288 data recv 32768 at 557056 data recv 32768 at 589824 data recv 32768 at 622592 data recv 32768 at 655360 data recv 32768 at 688128 data recv 32768 at 720896 data recv 32768 at 753664 data recv 32768 at 786432 data recv 32768 at 819200 data recv 32768 at 851968 data recv 32768 at 884736 data recv 32768 at 917504 data recv 32768 at 950272 data recv 32768 at 983040 data recv 32768 at 1015808 data recv 32768 at 1048576 data recv 32768 at 1081344 data recv 32768 at 1114112 data recv 32768 at 1146880 data recv 32768 at 1179648 data recv 32768 at 1212416 data recv 8088 at 1245184 got file_sum set modtime of .IMG_20101101_085101.jpg.sP9mq9 to (1288623180) Mon Nov 1 10:53:00 2010 renaming .IMG_20101101_085101.jpg.sP9mq9 to IMG_20101101_085101.jpg send_files phase=1 recv_files phase=1 generate_files phase=2 send_files phase=2 send files finished total: matches=0 hash_hits=0 false_alarms=0 data=1253272 recv_files phase=2 generate_files phase=3 recv_files finished generate_files finished client_run waiting on 13991 sent 1253528 bytes received 31 bytes 32559.97 bytes/sec total size is 1253272 speedup is 1.00 _exit_cleanup(code=0, file=main.c, line=1039): entered _exit_cleanup(code=0, file=main.c, line=1039): about to call exit(0) Note that 4 lines up from here we see 32559.97 bytes/sec which I can believe, but further up we see: 1253272 100% 58.20MB/s 0:00:00 (xfer#1, to-check=0/1) which is wrong for the speed.
By the way I tried a transfer initiated from the same machine as used in the previous comment - but to a local machine on the same local network, and this worked fine. It was only when I sent from this machine which is within a university network in the UK to the remote machine which is across the internet in the USA, that this problem appears to manifest itself - the local network is very fast and runs at gigabit speeds, though the NIC on the sending machine only runs at 100Mbps. The remote machine has the capability of receiving at around 30Mbps but the network in the big wide world presumably cannot run at as fast as the machines at either end! I wonder if this is a factor?
This is really strange, unless there is really super-power future UK-USA network connection :) Can you send me output of $ uname -a command, please? As I still can't reproduce this behaviour, the last chance is to make a debugging program for you and see it's output.
[mike@home1 ~]$ uname -a Linux home1.mymachine.com 2.6.32.23-170.fc12.i686.PAE #1 SMP Mon Sep 27 17:40:41 UTC 2010 i686 i686 i386 GNU/Linux I have removed the machine name for security.... I will try to do the analogous test with an f13 machine this weekend....
OK here is another test output - this is from f12 to a remote f13 machine (UK to UK) - upload maximum speed outbound from my home connection is 387kbps: [mike@home1 ~]$ time rsync -avvvv --progress -e ssh Pictures/university-physics/autumn07-2340933091_7d7a03a5c2_b.jpg momnf:~/Downloads/ cmd=ssh machine=momnf user=<NULL> path=~/Downloads/ cmd[0]=ssh cmd[1]=momnf cmd[2]=rsync cmd[3]=--server cmd[4]=-vvvvlogDtpre.iLsf cmd[5]=. cmd[6]=~/Downloads/ opening connection using: ssh momnf rsync --server -vvvvlogDtpre.iLsf . "~/Downloads/" note: iconv_open("UTF-8", "UTF-8") succeeded. (Client) Protocol versions: remote=30, negotiated=30 (Server) Protocol versions: remote=30, negotiated=30 sending incremental file list [sender] make_file(autumn07-2340933091_7d7a03a5c2_b.jpg,*,0) [sender] flist start=1, used=1, low=0, high=0 [sender] i=1 Pictures/university-physics autumn07-2340933091_7d7a03a5c2_b.jpg mode=0100664 len=749204 uid=500 gid=500 flags=5 send_file_list done file list sent send_files starting server_recv(2) starting pid=16212 received 1 names [Receiver] flist start=1, used=1, low=0, high=0 [Receiver] i=1 1 autumn07-2340933091_7d7a03a5c2_b.jpg mode=0100664 len=749204 gid=500 flags=0 recv_file_list done get_local_name count=1 /home/mike/Downloads/ generator starting pid=16212 delta-transmission enabled recv_generator(autumn07-2340933091_7d7a03a5c2_b.jpg,1) send_files(1, Pictures/university-physics/autumn07-2340933091_7d7a03a5c2_b.jpg) count=0 n=0 rem=0 send_files mapped Pictures/university-physics/autumn07-2340933091_7d7a03a5c2_b.jpg of size 749204 calling match_sums Pictures/university-physics/autumn07-2340933091_7d7a03a5c2_b.jpg autumn07-2340933091_7d7a03a5c2_b.jpg 32768 4% 0.00kB/s 0:00:00 sending file_sum false_alarms=0 hash_hits=0 matches=0 749204 100% 97.61MB/s 0:00:00 (xfer#1, to-check=0/1) sender finished Pictures/university-physics/autumn07-2340933091_7d7a03a5c2_b.jpg recv_files(1) starting generate_files phase=1 recv_files(autumn07-2340933091_7d7a03a5c2_b.jpg) data recv 32768 at 0 data recv 32768 at 32768 data recv 32768 at 65536 data recv 32768 at 98304 data recv 32768 at 131072 data recv 32768 at 163840 data recv 32768 at 196608 data recv 32768 at 229376 data recv 32768 at 262144 data recv 32768 at 294912 data recv 32768 at 327680 data recv 32768 at 360448 data recv 32768 at 393216 data recv 32768 at 425984 data recv 32768 at 458752 data recv 32768 at 491520 data recv 32768 at 524288 data recv 32768 at 557056 data recv 32768 at 589824 data recv 32768 at 622592 data recv 32768 at 655360 data recv 32768 at 688128 data recv 28308 at 720896 got file_sum set modtime of .autumn07-2340933091_7d7a03a5c2_b.jpg.1jzFMh to (1288642562) Mon Nov 1 20:16:02 2010 renaming .autumn07-2340933091_7d7a03a5c2_b.jpg.1jzFMh to autumn07-2340933091_7d7a03a5c2_b.jpg send_files phase=1 recv_files phase=1 generate_files phase=2 send_files phase=2 send files finished total: matches=0 hash_hits=0 false_alarms=0 data=749204 recv_files phase=2 generate_files phase=3 recv_files finished generate_files finished client_run waiting on 10771 sent 749409 bytes received 31 bytes 40510.27 bytes/sec total size is 749204 speedup is 1.00 [sender] _exit_cleanup(code=0, file=main.c, line=1042): entered [sender] _exit_cleanup(code=0, file=main.c, line=1042): about to call exit(0) real 0m17.627s user 0m0.030s sys 0m0.014s Notice the line saying: 749204 100% 97.61MB/s 0:00:00 (xfer#1, to-check=0/1) This is from one machine in the UK to another about 35 miles away (though the network route is probably via the ISP's servers a much larger distance away). Both machines are connected to the same ISP.
Here is a test sending the file in the reverse direction from the f13 machine to the f12 machine - again this is on a standard broadband connection with both machines connected to the same ISP and around 35 miles apart. I have curtailed the output and hidden the machine names: [mike@crc Downloads]$ time rsync -avv --progress -e "ssh -p xxx" autumn07-2340933091_7d7a03a5c2_b.jpg home.co.uk:~/Downloads/ opening connection using: ssh -p xxx home.co.uk rsync --server -vvlogDtpre.iLsf . "~/Downloads/" sending incremental file list delta-transmission enabled autumn07-2340933091_7d7a03a5c2_b.jpg 749204 100% 113.87MB/s 0:00:00 (xfer#1, to-check=0/1) total: matches=0 hash_hits=0 false_alarms=0 data=749204 sent 749409 bytes received 31 bytes 51685.52 bytes/sec total size is 749204 speedup is 1.00 real 0m13.759s user 0m0.025s sys 0m0.022s Again the speed is reported incorrectly.
Since this also appears in f13 I have changed the version to f13.
The f13 machine on which the last test was done has uname -a output as: Linux machine.com 2.6.34.7-61.fc13.i686.PAE #1 SMP Tue Oct 19 04:24:06 UTC 2010 i686 i686 i386 GNU/Linux
Thanks, Mike! I'll try look at this more deeply. I think there could be kind of problem in initial step ("guessing" the first time difference) while sending/receiving small files in less than one second. Can you confirm this by sending 2MB+ file? I would appreciate output too.
Looks like you are right - I sent a 13 MB file and the output looks sensible. If you want full output then I can do that later also but the brief output is: [mike@gestalt firefox_stuff]$ rsync -avv firefox-4.0b8pre.en-US.linux-i686.tar.bz2 fiz:~/Downloads/ --progress opening connection using: ssh fiz rsync --server -vvlogDtpre.iLs . "~/Downloads/" sending incremental file list created directory /home/mike/Downloads delta-transmission enabled firefox-4.0b8pre.en-US.linux-i686.tar.bz2 13578773 100% 87.74kB/s 0:02:30 (xfer#1, to-check=0/1) total: matches=0 hash_hits=0 false_alarms=0 data=13578773 sent 13580552 bytes received 31 bytes 84090.30 bytes/sec total size is 13578773 speedup is 1.00 So this reports 88 kB/s which is believable - I can do a similar test for this with -avvvv if you like - let me know.
This message is a reminder that Fedora 13 is nearing its end of life. Approximately 30 (thirty) days from now Fedora will stop maintaining and issuing updates for Fedora 13. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '13'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 13's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 13 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora please change the 'version' of this bug to the applicable version. If you are unable to change the version, please add a comment here and someone will do it for you. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
I have run a few tests of small files between two f14 machines and I don't see the problem any more - so I am happy that this is closed.