FASP transfer stops
Eventually the file transfer completes and we get some additional log information:
LOG FASP Transfer Stop uuid=a9063e44-f785-4bca-8e71-3eaa20a64b32 op=recv status=success file="/tmp/1GB" size=1048576000 start_byte=0 rate=96.36Mbps elapsed=87.05s loss=0.00 rexreqs=0 overhead=0 mtime="2014-04-10 19:49"
LOG Receiver bl t/o/r/d/ts=722162/722160/0/2/722160 rex_rtt l/h/s/o=0/0/174/8 ooo_rtt l/h/s/o=0/0/174/8 rate_rtt b/l/h/s/r/f=174/175/178/175/0/1 ctl bm/bs=0/0 rex n/s/q/v/a/r=0/0/0/0/0/0 bl l/d/o/r/a/x/dl/df/dm/ds=0/0/0/0/0/2/0/0/0/0 disk l/h/b=0/1/0 vlink lq/lo/rq/ro=0/0/0/0 rate t/m/c/n/vl/vr/r=100000000/0/100000000/100000000/100000000/100000000/100000000 prog t/f/e=1048576000/1048576000/87494969 rcvD=1
LOG Receiver DS Qs ds/n/rq/ao/ap/rd/ru/no/po/pc/do=0/0/0/0/0/0/0/0/0/0/0 Rs i/o=1/1 mgmt backlog i/s/n =
Completed: 1024000K bytes transferred in 87 seconds
(95875K bits/sec), in 1 file.
LOG FASP Session Stop uuid=a9063e44-f785-4bca-8e71-3eaa20a64b32 op=recv status=success source=aspera-test-dir-large/1GB (1) dest=/tmp source_prefix=- local=130.237.209.248:42132 peer=198.23.89.123:33001 tcp_port=22 os="Linux 3.7.10-1.45-desktop #1 SMP PREEMPT" ver=3.5.4.103990 lic=6:1:1 peeros="Linux 2.6.32-504.3.3.el6.x86_64 #1 SMP W" peerver=3.5.4.100392 peerlic=10:1:22001 proto_sess=20002 proto_udp=20000 proto_bwmeas=20000 proto_data=20008
LOG FASP Session Params uuid=a9063e44-f785-4bca-8e71-3eaa20a64b32 userid=0 user="aspera" targetrate=100000000 minrate=0 rate_policy=fair cipher=none resume=0 create=0 ovr=1 times=0 precalc=yes mf=0 mf_path=- mf_suffix=.aspera-inprogress partial_file_suffix= files_encrypt=no files_decrypt=no file_csum=none dgram_sz=0 prepostcmd=- tcp_mode=no rtt_auto=yes cookie="-" vl_proto_ver=1 peer_vl_proto_ver=1 vl_local=0 vlink_remote=0 vl_sess_id=3840 srcbase=- rd_sz=0 wr_sz=0 cluster_num_nodes=1 cluster_node_id=0 range=0-0 keepalive=no test_login=no proxy_ip=- net_rc_alg=alg_delay exclude_older/newer_than=0/0
LOG FASP Session Statistics [Receiver] id=a9063e44-f785-4bca-8e71-3eaa20a64b32 delay=176ms rex_delay=8ms ooo_delay=8ms solicited_rex=0.00% rcvd_rex=0.00% rcvd_dups=0.00% ave_xmit_rate 98.63Mbps effective=100.00% effective_rate=98.63Mbps (detail: good_blks 722160 bl_total 722162 bl_orig 722160 bl_rex 0 dup_blks 0 dup_last_blks 0 drop_blks_xnf 2) (sndr ctl: sent 112 rcvd 112 lost 0 lost 0.00%) (rcvr ctl: sent 879 rcvd 877 lost 2 lost 0.23%) (rex ctl: sent 0 rcvd 0 lost 0 lost 0.00%) (progress: tx_bytes 1048576000 file_bytes 1048576000 tx_time 87494969) rex_xmit_blks 0 xmit_total 722162 rex_xmit_pct 0.00%
Completed: 1024000K bytes transferred in 87 seconds (95875K bits/sec), in 1 file
delay=176ms rex_delay=8ms
ave_xmit_rate 98.63Mbps
(sndr ctl: sent 112 rcvd 112 lost 0 lost 0.00%)
(rcvr ctl: sent 879 rcvd 877 lost 2 lost 0.23%)
Transcript
Eventually, the file transfer stops, and we got a bunch of data out of that, and we can see it transferred this file which was a 1024 times a thousand kilobytes - so one gigabyte. It was transferred in 87 seconds. For a total of 95875 kilobits per second. The actual measured delay was 176 ms. And the average transmission rate was 98.63 megabits per second - so just slightly under the 100 megabits per second that I specified. And if you look at the sender control information being sent from their server to my client, we see that it sent 112 control messages of which all of them were received whereas the receiver sent traffic in the reverse direction and it sent 879 control messages, but two of those were lost, so we have a 0.23% loss ratio for those control messages and the [continued on next page]