Issue1304

I have a simple python client/server system that works just fine in
CPython, but it is painfully slow under Jython. I have traced it down to
a send call on a TCP socket. The problem only seems to arise if the same
socket is used for sending and receiving, but not when sending only. The
problem is quite sporadic ... working fine sometimes. I see the problem
even if no data is actually being received, it is just calling recv.

The end result is that sending 192 bytes usually takes <= 0.001 seconds
... but occasionally takes upwards of 12 seconds!

To reproduce this I keep byteSink.py running in CPython and then run
problemReport.py under Jython several times (5-10 is usually enough to
see the worst behaviour).

This is all done on Ubuntu 8.04 using OpenJDK 1.6.

Doh, this is on Jython 2.5b3

Played with this some more, if I remove the settimeout call things work
better. And, in hindsight I could have achieved the same effect (and
perhaps in a cleaner way) by using select. So this is not as big of an
issue for me now. But it looks like using both send and recv on sockets
with a timeout set is a bit funky.

There is an error in your code, namely

  def run(self):
    while True:
      try:
        data = self.revc(4)  # <-- should be self.recv
        print "got data"
        # ...
      except socket.error:
        break

When I correct the error, everything runs fine.

I'll look at the timings produced.

I can't keep your byteSink running on cpython, in Windows. It keeps
exiting with "socket.error: (10054, 'Connection reset by peer')" when
the client disconnects. I'll rewrite it to keep looping.

Just some notes as I go along.

The settimeout() call will change the way that bytes are sent on the socket.

If you do NOT use settimeout, then the bytes are sent through the
java.nio APIs. If you use settimeout, then data is sent using the
java.net APIs (because timeout's are not supported on java.nio).

We've had problems with threading and the java.net APIs before

http://bugs.jython.org/issue1744567

Particluarly, see this message

http://bugs.jython.org/msg1662

which says

"""
OK, I'm reasonably confident that this is a java bug, related to the
simultaneous use of input and output streams on a socket created by
java.nio. See these bug reports for further info

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4509080
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4774871

The problem is that the read and write methods of the InputStream and
OutputStream returned by the java.nio.channels.Channels class are
protected by a lock, which means that asocket cannot be read and written
to at the same time by different threads. 
"""

One more thing, I changed your code to send more data, and to loop a few
times sending it, so that the JVM gets a little time to warm up.

So I changed your code to this

p = Problem()
p.send('helo'*4800)
for x in range(10):
  p.send('A'*19200)

And the timings I get look far more favourable.

These are the timings with the settimeout call

send 19200 bytes in 0.015000 seconds
send 19200 bytes in 0.016000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.016000 seconds

And these are the timings without the settimeout call

send 19200 bytes in 0.141000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.016000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.000000 seconds
send 19200 bytes in 0.016000 seconds
send 19200 bytes in 0.000000 seconds

Do you see the same on your platform?

With the settimeout:
sent 192000 bytes in 8.828000 seconds
sent 192000 bytes in 0.248000 seconds
sent 192000 bytes in 0.251000 seconds
sent 192000 bytes in 0.252000 seconds
 ... the rest of them are about .25

So I ran it again and got:
sent 192000 bytes in 0.006000 seconds
sent 192000 bytes in 130.101000 seconds
sent 192000 bytes in 0.000000 seconds
sent 192000 bytes in 0.000000 seconds
and the rest are all basically 0.

I have run it a number of times and it seems to always fall into one of
those two categories: either the second one is incredibly slow (up to 30
seconds!) with the rest being very fast OR they are almost all around
.25 seconds.

Without the settimeout I get results in the low milliseconds (around
0.003000 or less) for times ... quite reasonable for what its doing.

Oh, that 130 should have been 13 ... still ridiculously slow, but not
quite as ridiculous.

Just to clarify a bit more, for my real code I have switched to using
select, which is a much better choice in this case. Perhaps the
'solution' for this problem is a FAQ entry saying "Try select (or poll)
its better"

Jython is awesome and I am really itching to see a final 2.5 release, so
it seems a shame to be wasting time tracking down a messy issue when
there is a pretty reasonable workaround.

[Kevin]
> Just to clarify a bit more, for my real code I have switched to using
> select, which is a much better choice in this case. Perhaps the
> 'solution' for this problem is a FAQ entry saying "Try select (or poll)
> its better"

Ah, if only it were that simple ....

http://bugs.jython.org/issue1291

This stuff seems to be highly platform dependent.

In light of issue #1291, I recommend using select.poll() instead of
select.select(), for anyone using Windows.

Ugh.. that makes things messy. I want my code to work under any
combination of windows/linux and cpython/jython. windows+cpython has no
poll (at least that is what I have heard).

So, what is the resolution for this issue?

For me personally the resolution is to use select. It gets me everything
that settimeout did (and more). Since the resolution of issue1291 select
seems like a good choice.

Closing by agreement with the OP.