[Vortex] Slow throughput over bandwidth-limited socket

[Jens Alfke]

My app is streaming time-sensitive data across a TLS-ified BEEP  
connection; it needs a throughput of at least about 20kbytes/sec  
(160kbits/sec). This should be no problem with typical broadband  
connections, whichever direction the data is going, since uplink  
speeds are usually at least 256kbps. (I've got a fairly pokey DSL  
connection and it manages 480kbps upstream.)

But with the latest Vortex library I'm finding that my app is unable  
to transfer data fast enough in limited-bandwidth situations, where it  
used to work fine a few weeks ago. In fact, it's able to use less than  
half the available bandwidth. Did something change in Vortex's low- 
level frame handling that could cause this? I need to resolve this  
somehow or it's going to make my app unusable in many situations.

One of the tests I do is to use DummyNet to throttle one host's  
network interface down to 256kbps, then run my app between it and  
another host on the same LAN. When I did this initially about two  
weeks ago, Vortex performed fine. But running it again today, my  
logging shows that the data rate it's able to manage is only about  
100kbps -- or in other words, it's receiving 4kbyte frames at a rate  
of about 3 per second.

The way I'm streaming the data is that the receiver, when it's ready  
for another buffer, sends a MSG containing the byte-range it wants,  
and the sender sends a RPY containing the data. Currently the data  
size is always 32kbytes.

I've attached a segment of the logs, showing what happens between the  
time I request a 32kbyte chunk of data, and when it arrives at my  
handler. (It's in RTF so I could boldface the most important lines.)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Vortex slow throughput.rtf
Type: text/rtf
Size: 18922 bytes
Desc: not available
Url : http://lists.aspl.es/pipermail/vortex/attachments/20080418/9d5d9b3b/attachment-0002.bin 
-------------- next part --------------



Here's what the interval from one 4k chunk to the next looks like.  
Note that the elapsed time is 0.297 sec to read 4kbytes, which works  
out to 110kbits/sec.

11:17:47.278| Vortex: vortex-frame-factory: line read from underlying  
transport: 'RPY 6 3 * 93178 4096
'
11:17:47.279| Vortex: vortex-frame-factory: from='get-next' allocating  
a new frame id=42
11:17:47.279| Vortex: vortex-frame-factory: Frame received on channel  
6, content type=, transfer encoding=, payload size=4096, mime content  
size=0
11:17:47.279| Vortex: vortex-reader: passed initial accept stage
11:17:47.279| Vortex: vortex-reader: passed connection existence stage
11:17:47.279| Vortex: vortex-reader: passed message number checking  
stage
11:17:47.280| Vortex: vortex-channel: setting pending reply  
processed=0 for channel=6
11:17:47.280| Vortex: vortex-channel: updating channel receiving  
status to: msgno=-1, rpyno=3, seqno=97274, ansno=0..
11:17:47.280| Vortex: vortex-reader: passed channel update status due  
to frame received stage
11:17:47.280| Vortex: vortex-channel: SEQ FRAME: updating allowed max  
seq no to be received from 97273 to 101369 (delta: 4096)
11:17:47.280| Vortex: vortex-reader: notifying remote side that  
current buffer status is SEQ 6 97274 4096

11:17:47.280| Vortex: vortex-sequencer: Sending message, size (18)  
over connection id=3
11:17:47.281| Vortex: vortex-frame-factory: bytes written: 18
11:17:47.281| Vortex: vortex-frame-factory: write on socket request=18  
written=18
11:17:47.281| Vortex: vortex-channel: channel=0 unref called, ref  
count status after calling=1
11:17:47.281| Vortex: vortex-reader: more flag and completed flag  
detected, skipping to the next frame
11:17:47.484| Vortex: vortex-reader: something to read
11:17:47.485| Vortex: vortex-tls: SSL_read returned that isn't ready  
to read: retrying
11:17:47.532| Vortex: vortex-reader: something to read
11:17:47.536| Vortex: vortex-tls: SSL_read returned that isn't ready  
to read: retrying
11:17:47.574| Vortex: vortex-reader: something to read
11:17:47.575| Vortex: vortex-frame-factory: line read from underlying  
transport: 'RPY 6 3 . 97274 4096
'

?Jens
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1875 bytes
Desc: not available
Url : http://lists.aspl.es/pipermail/vortex/attachments/20080418/9d5d9b3b/attachment-0003.bin