IcePatch2 on IceGrid is very very slow.

leojay

Hi all,

I'm using ICE 3.3.1
I modified the IceGrid demo come up with Ice in "C:\Ice-3.3.1-VC90\demopy\IceGrid\simple", the xml file is in the attachment.
I try to use IceGrid and IcePatch2 together, and want to deploy the IcePatch2 server on my workstation(named "lj"), and deploy application to another computer named "Node86".
But the "application add" is very very slow. It seems that patching on "Node86" used on than 3 minutes. It's abnormal, isn't it?

registry log:
[ 08/11/09 02:04:14.565 bin/icegridnode: Adapter: added adapter `ReplicatedHelloAdapter' ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Adapter: added adapter `Simple.IcePatch2.IcePatch2' ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Server: added server `Simple.IcePatch2' (`232B3AAD-1849-4F2E-854D-28F500341107', `1') ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Adapter: added adapter `SimpleServer-4.Hello' ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Server: added server `SimpleServer-4' (`232B3AAD-1849-4F2E-854D-28F500341107', `1') ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Adapter: added adapter `SimpleServer-5.Hello' ]
[ 08/11/09 02:04:14.565 bin/icegridnode: Server: added server `SimpleServer-5' (`232B3AAD-1849-4F2E-854D-28F500341107', `1') ]
[ 08/11/09 02:04:14.566 bin/icegridnode: Server: loading `Simple.IcePatch2' on node `lj' ]
[ 08/11/09 02:04:14.569 bin/icegridnode: Server: loaded `Simple.IcePatch2' on node `lj' ]
[ 08/11/09 02:04:14.569 bin/icegridnode: Server: loading `SimpleServer-4' on node `Node86' ]
[ 08/11/09 02:04:14.571 bin/icegridnode: Server: loaded `SimpleServer-4' on node `Node86' ]
[ 08/11/09 02:04:14.571 bin/icegridnode: Server: loading `SimpleServer-5' on node `Node86' ]
[ 08/11/09 02:04:14.572 bin/icegridnode: Server: loaded `SimpleServer-5' on node `Node86' ]
[ 08/11/09 02:04:14.573 bin/icegridnode: Patch: started patching of application `Simple' on node `Node86' ]
[ 08/11/09 02:04:14.574 bin/icegridnode: Patch: started patching of application `Simple' on node `lj' ]
[ 08/11/09 02:04:14.574 bin/icegridnode: Patch: finished patching of application `Simple' on node `lj' ]
[ 08/11/09 02:07:23.572 bin/icegridnode: Patch: finished patching of application `Simple' on node `Node86' ]

matthew

The most likely issue is that your icegridnode is publishing endpoints which are unreachable. Run your nodes with --Ice.Trace.Network=1 and pay close attention to which endpoints your server is listening on. You can specify specific endpoints with the -h of your object adapter configuration (ie: tcp -h 192.168.2.1).

leojay

Thanks for your reply.

I changed the xml file, specified endpoints for each server, and nothing get changed. It's still very very slow.

The attachment is the new xml file for your information.

I add "--Ice.Trace.Network=1" to icegridnode on Node86, and I find a line of log showing:
[ 08/11/09 16:31:20.946 bin/icegridnode: Network: closing tcp connection
local address = 192.168.1.86:57164
remote address = <not connected> ]
What's the meaning of this?

benoit

Hi,

It means that the node tried to establish a network connection which most likely failed. The trace shows the closing of this connection. Try to run the node with --Ice.Trace.Network=2 instead to see the connection establishment attempt.

You most likely also need to specify the -h <host> option in endpoints of the IceGrid node and registry configuration files (not only in the XML descriptor).

Cheers,
Benoit.

leojay

I think the problem is solved after I turned the windows firewall off.


"--Ice.Trace.Network=2" makes icegridnode show more information:
[ 08/11/09 17:22:43.076 bin/icegridnode: Network: failed to establish tcp connection
local address = 192.168.1.86:43124
remote address = <not connected>
Network.cpp:1226: Ice::ConnectFailedException:
connect failed: Connection timed out ]

After I turned the windows firewall off, no more "Connection timed out" was thrown, "Connection refused" instead. And "application add" returned very quickly.

I don't know why windows firewall will cause the "time out" problem, but, anyway, (at least It seems that) It's OK now.

Thanks.

benoit

Hi,

The Windows firewall simply ignores connection requests and unless you're using timeouts it can take a very long time for the client (the IceGrid registry here) to get an error from the connection establishment.

Note that unless another address was reachable for this node, it's likely that the patch failed. I recommend figuring out why you're getting this connection refused exception.

Cheers,
Benoit

leojay

It seems that the socket port in IcePatch2 server(192.168.1.12 in this case) will change in each connection, when Node86 connect to the previous port, the connection will be refused and Node86 will try to connect to another port and this time connection will be established.

[ 08/11/09 17:25:10.549 bin/icegridnode: Network: trying to establish tcp connection to 192.168.1.12:4856 ]
[ 08/11/09 17:25:10.550 bin/icegridnode: Network: failed to establish tcp connection
  local address = 192.168.1.86:36501
  remote address = <not connected>
  Network.cpp:1220: Ice::ConnectionRefusedException:
  connection refused: Connection refused ]
[ 08/11/09 17:25:10.550 bin/icegridnode: Network: closing tcp connection
  local address = 192.168.1.86:36501
  remote address = <not connected> ]
[ 08/11/09 17:25:10.586 bin/icegridnode: Network: trying to establish tcp connection to 192.168.1.12:4899 ]
[ 08/11/09 17:25:10.587 bin/icegridnode: Network: tcp connection established
  local address = 192.168.1.86:43474
  remote address = 192.168.1.12:4899 ]
[ 08/11/09 17:25:33.873 bin/icegridnode: Network: closing tcp connection
  local address = 192.168.1.86:43474
  remote address = 192.168.1.12:4899 ]
[ 08/11/09 17:25:37.810 bin/icegridnode: Network: trying to establish tcp connection to 192.168.1.12:4899 ]
[ 08/11/09 17:25:37.810 bin/icegridnode: Network: failed to establish tcp connection
  local address = 192.168.1.86:43475
  remote address = <not connected>
  Network.cpp:1220: Ice::ConnectionRefusedException:
  connection refused: Connection refused ]
[ 08/11/09 17:25:37.811 bin/icegridnode: Network: closing tcp connection
  local address = 192.168.1.86:43475
  remote address = <not connected> ]
[ 08/11/09 17:25:37.842 bin/icegridnode: Network: trying to establish tcp connection to 192.168.1.12:4931 ]
[ 08/11/09 17:25:37.842 bin/icegridnode: Network: tcp connection established
  local address = 192.168.1.86:50494
  remote address = 192.168.1.12:4931 ]

Do you think there is something wrong with it?

benoit

Hi,

Ok, that's fine. Since the port changes each time the IcePatch2 server is restarted these connection refused exceptions are expected. Upon getting this exception, the IceGrid node retrieves the new endpoints for the IcePatch2 server from the IceGrid registry and it tres again with the correct endpoints.

Cheers,
Benoit.