Slow connection establishment C# <-> Java

JuergenJuergen Juergen BogerOrganization: OFFIS e.V.Project: Autonomous Navigating Transportion SystemMember
We have a problem concerning ICE in C# and Java. We use Ice 3.4.2

We have 2 applications, that are communicating via ICE. One is written in Java and
the other in C#. All applications are running on the same machine.

The problem:
First RPC-Call from Java-App to C#-App needs long time (app. 1 minute). All other calls, after
the first one, are very fast... This also happens, if there were no RPCs for over 1 minute, then the
first is slow again.

The problemprogress:
  1. C#-App creates a proxy {A} to itself (server proxy)
  2. C#-App gets the proxy {B} to the Java-App (client proxy)
  3. C#-App sends the proxy {A} via ICE-RPC to the Java-App {B} => {B}.registerObserver({A}* proxy) (This call is fast)
  4. The Java-App sends an ICE-RPC to this observerproxy {A}.onUpdate(...) (This call hangs up in Java for app. 1 minute)
  5. All next ICE-RPCs from Java are fast, until the connection is disconnected again (no use for more than 1 minute)

If both applications are in Java, the ICE-RPCs are fast and there are no problems.
The problem is exactly the same, as mentioned in "Why is my .NET application so slow to start? - ZeroC Documentation - ZeroC" .
We already tried this (added this, to the app.config of the C#-application), without success. Is it, cause one application is in Java? How to fix it?

Comments

  • mesmes CaliforniaMark SpruiellOrganization: ZeroC, Inc.Project: Ice DeveloperAdministrators, ZeroC Staff ZeroC Staff
    Hello Juergen,

    Welcome to the forum.

    Also, thank you for checking the FAQ before posting! :)

    We need more information about what the Java app is doing during this delay. The most likely reasons are network issues or configuration problems, such as attempting to connect to an IP address that is inaccessible.

    Please run both programs with Ice.Trace.Network=3 and Ice.Trace.Protocol=1, and post both log files.

    Best regards,
    Mark
  • JuergenJuergen Juergen BogerOrganization: OFFIS e.V.Project: Autonomous Navigating Transportion SystemMember
    Her is the log from the Java App:
    I should say, that we have got 3 apps and one of that is not running, it uses port 10200, that why these connection fail to establish.
    -- 29.10.11 13:20:53:289 Network: attempting to bind to tcp socket 0.0.0.0:10100
    -- 29.10.11 13:20:53:957 Network: accepting tcp connections at 0:0:0:0:0:0:0:0:10100
       local interfaces: 192.168.178.29, 127.0.0.1
    -- 29.10.11 13:20:54:216 Network: published endpoints for object adapter `SimpleATFAdapter':
       tcp -h 192.168.178.29 -p 10100
    -- 29.10.11 13:20:54:283 Network: trying to establish tcp connection to 127.0.0.1:10200
    -- 29.10.11 13:20:55:287 Network: failed to establish tcp connection
       local address = <not available>:45048
       remote address = 127.0.0.1:10200
    -- 29.10.11 13:20:55:289 Network: trying to establish tcp connection to 127.0.0.1:10200
    -- 29.10.11 13:20:56:289 Network: failed to establish tcp connection
       local address = <not available>:45049
       remote address = 127.0.0.1:10200
    -- 29.10.11 13:20:56:297 Network: trying to establish tcp connection to 127.0.0.1:10300
    -- 29.10.11 13:20:56:298 Network: tcp connection established
       local address = 127.0.0.1:45050
       remote address = 127.0.0.1:10300
    -- 29.10.11 13:20:56:314 Network: received 14 of 14 bytes via tcp
       local address = 127.0.0.1:45050
       remote address = 127.0.0.1:10300
    -- 29.10.11 13:20:56:316 Protocol: received validate connection 
       message type = 3 (validate connection)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 14
    -- 29.10.11 13:20:56:320 Protocol: sending request 
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 105
       request id = 1
       identity = Mission
       facet = 
       operation = onAntsSoftwareStarted
       mode = 0 (normal)
       context = 
    -- 29.10.11 13:20:56:320 Network: sent 105 of 105 bytes via tcp
       local address = 127.0.0.1:45050
       remote address = 127.0.0.1:10300
    -- 29.10.11 13:20:56:368 Network: accepted tcp connection
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:368 Protocol: sending validate connection 
       message type = 3 (validate connection)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 14
    -- 29.10.11 13:20:56:368 Network: sent 14 of 14 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:422 Network: received 14 of 14 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:422 Network: received 32 of 32 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:423 Protocol: received request 
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 46
       request id = 1
       identity = SimpleATF
       facet = 
       operation = getType
       mode = 2 (idempotent)
       context = 
    -- 29.10.11 13:20:56:429 Protocol: sending reply 
       message type = 2 (reply)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 26
       request id = 1
       reply status = 0 (ok)
    -- 29.10.11 13:20:56:429 Network: sent 26 of 26 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:524 Network: received 14 of 14 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:524 Network: received 155 of 155 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:525 Protocol: received request 
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 169
       request id = 2
       identity = SimpleATF
       facet = 
       operation = registerPositionObserver
       mode = 0 (normal)
       context = 
    -- 29.10.11 13:20:56:529 Protocol: sending reply 
       message type = 2 (reply)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 25
       request id = 2
       reply status = 0 (ok)
    -- 29.10.11 13:20:56:529 Network: sent 25 of 25 bytes via tcp
       local address = 192.168.178.29:10100
       remote address = 192.168.178.29:45051
    -- 29.10.11 13:20:56:561 Network: received 14 of 14 bytes via tcp
       local address = 127.0.0.1:45050
       remote address = 127.0.0.1:10300
    -- 29.10.11 13:20:56:561 Network: received 11 of 11 bytes via tcp
       local address = 127.0.0.1:45050
       remote address = 127.0.0.1:10300
    -- 29.10.11 13:20:56:561 Protocol: received reply 
       message type = 2 (reply)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 25
       request id = 1
       reply status = 0 (ok)
    -- 29.10.11 13:20:56:562 Network: trying to establish tcp connection to 169.254.197.14:10300
    -- 29.10.11 13:21:17:592 Network: failed to establish tcp connection
       local address = <not available>:45052
       remote address = 169.254.197.14:10300
    -- 29.10.11 13:21:17:593 Network: trying to establish tcp connection to 192.168.178.29:10300
    -- 29.10.11 13:21:17:595 Network: tcp connection established
       local address = 192.168.178.29:45053
       remote address = 192.168.178.29:10300
    -- 29.10.11 13:21:17:600 Network: received 14 of 14 bytes via tcp
       local address = 192.168.178.29:45053
       remote address = 192.168.178.29:10300
    -- 29.10.11 13:21:17:600 Protocol: received validate connection 
       message type = 3 (validate connection)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 14
    -- 29.10.11 13:21:17:601 Protocol: sending request 
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 113
       request id = 1
       identity = Mission
       facet = 
       operation = onPositionChange
       mode = 0 (normal)
       context = 
    

    After that, this log repeats:
    -- 29.10.11 13:21:17:601 Network: sent 113 of 113 bytes via tcp
       local address = 192.168.178.29:45053
       remote address = 192.168.178.29:10300
    -- 29.10.11 13:21:19:150 Network: received 14 of 14 bytes via tcp
       local address = 192.168.178.29:45053
       remote address = 192.168.178.29:10300
    -- 29.10.11 13:21:19:150 Network: received 11 of 11 bytes via tcp
       local address = 192.168.178.29:45053
       remote address = 192.168.178.29:10300
    -- 29.10.11 13:21:19:151 Protocol: received reply 
       message type = 2 (reply)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 25
       request id = 1
       reply status = 0 (ok)
    -- 29.10.11 13:21:19:251 Protocol: sending request 
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 113
       request id = 2
       identity = Mission
       facet = 
       operation = onPositionChange
       mode = 0 (normal)
       context = 
    

    Because, we update the position and say to the observer, that it changed. I think the fault is in this lines
    "-- 29.10.11 13:20:56:562 Network: trying to establish tcp connection to 169.254.197.14:10300
    -- 29.10.11 13:21:17:592 Network: failed to establish tcp connection
    local address = <not available>:45052
    remote address = 169.254.197.14:10300"
    Here it tries, to connect ip 169.254.197.14:10300 and this takes approx. 20 seconds. But how to prevent this?
  • bernardbernard Jupiter, FLBernard NormierOrganization: ZeroC, Inc.Project: IceAdministrators, ZeroC Staff ZeroC Staff
    Hi Juergen,

    It looks like you have a second network interface on this computer that fails to get an address through DHCP and gets the IP address 169.254.197.14 ... and you don't want to use that interface.

    The solution is to specify '-h <address>' in your object adapter endpoint configuration, instead of -h * or no -h at all, which means listen on all interfaces.

    I don't know why you don't have this issue for all your object adapters:
    -- 29.10.11 13:20:53:289 Network: attempting to bind to tcp socket 0.0.0.0:10100
    -- 29.10.11 13:20:53:957 Network: accepting tcp connections at 0:0:0:0:0:0:0:0:10100
    local interfaces: 192.168.178.29, 127.0.0.1

    here you listen on all interfaces but don't get this 169.254.197.14.

    In any case, use:
    XXX.Endpoints=tcp -h 192.168.178.29 -p 10300
    
    or
    XXX.Endpoints=tcp -h 127.0.0.1 -p 10300
    

    to fix this issue.

    Best regards,
    Bernard
  • JuergenJuergen Juergen BogerOrganization: OFFIS e.V.Project: Autonomous Navigating Transportion SystemMember
    It looks like it is woring fine now... Big thanks for the help!
Sign In or Register to comment.