[omniORB] omniORB4: LONG Pause during orb->shutdown(0), orb->destroy()

Ken Feuerman kfeuerma@adobe.com
Fri, 30 Nov 2001 10:18:21 -0800


Duncan,

Good news (well, from my point of view anyway):  I can indeed reproduce 
this problem using the call_back example.  Here's what the console output 
looks like on the cb_client side.  I've added two annotations to indicate 
where the long pauses occur:

 >cb_client -ORBtraceLevel 15 -ORBtraceThreadId 1 
IOR:010000001200000049444c3a636
22f5365727665723a312e30000000010000000000000068000000010102000f0000003135332e333
22e3135392e3230300000b10d00000e000000fec1ca073c000006780000000000000002000000000
00000080000000100000000545441010000001c00000001000000010001000100000001000105090
101000100000009010100
omniORB: (0) Distribution date: Wed Nov 14 19:10:23 GMT 2001 dpg1
omniORB: (0) Native char code sets: UTF-8 ISO-8859-1.
omniORB: (0) Transmission char code sets: UTF-8(1.2) ISO-8859-1(1.2) 
ISO-8859-1(
1.1) ISO-8859-1(1.0).
omniORB: (0) Native wide char code sets: UTF-16.
omniORB: (0) Transmission wide char code sets: UTF-16(1.2).
omniORB: (0) Information: the omniDynamic library is not linked.
omniORB: (0) Creating ref to remote: root<0>
  target id      : IDL:omg.org/CORBA/Object:1.0
  most derived id: IDL:cb/Server:1.0
omniORB: (0) Initialising incoming endpoints.
omniORB: (0) Starting serving incoming endpoints.
omniAsyncInvoker: thread id=1 has started. Total threads = 1
omniORB: (0) Adding root<0> (activating) to object table.
omniORB: (0) State root<0> (activating) -> active
omniORB: (0) Creating ref to local: root<0>
  target id      : IDL:cb/CallBack:1.0
  most derived id: IDL:cb/CallBack:1.0
cb_client: server->one_time(call_back, "Hello!")
omniORB: (0) LocateRequest to remote: root<0>
omniAsyncInvoker: thread id=2 has started. Total threads = 2
omniAsyncInvoker: thread id=3 has started. Total threads = 3
omniORB: (3) Accepted connection from giop:tcp:153.32.159.200:3508 because 
of th
is rule: "* unix,ssl,tcp"
omniORB: (3) Handling a GIOP LOCATE_REQUEST.
cb_client: call_back("Hello!")
cb_client: Returned.
omniORB: (0) ObjRef(IDL:cb/CallBack:1.0) -- deleted.
omniORB: (0) omniRemoteIdentity deleted.
omniORB: (0) ObjRef(IDL:cb/Server:1.0) -- deleted.
omniORB: (0) Preparing to shutdown ORB.
omniORB: (0) Destroying POA(RootPOA).
omniORB: (0) Deactivating all POA(RootPOA)'s objects.
omniORB: (0) State root<0> (active) -> deactivating
omniORB: (0) Waiting for requests to complete on POA(RootPOA).
omniORB: (3) POA(RootPOA) etherealising object.
  id: IDL:cb/CallBack:1.0
omniORB: (3) State root<0> (deactivating) -> etherealising
omniORB: (0) Requests on POA(RootPOA) completed.
omniORB: (0) Etherealising POA(RootPOA)'s objects.
omniORB: (3) Removing root<0> (etherealising) from object table
omniORB: (3) Object table entry root<0> (dead) deleted.
omniORB: (3) RefCountServantBase has zero ref count -- deleted.
omniORB: (0) Stopping serving incoming endpoints.
[================== PAUSE for a few seconds =====================]
omniAsyncInvoker: thread id=1 has exited. Total threads = 2
[================== PAUSE for approx. 2 minutes =================]
omniORB: (3) throw giopStream::CommFailure from 
giopStream.cc:798(0,NO,COMM_FAIL
URE_UnMarshalArguments)
omniORB: (0) Destruction of POA(RootPOA) complete.
omniORB: (0) Shutting-down all incoming endpoints.
omniORB: (0) 0 object references present at ORB shutdown.
omniORB: (0) ORB shutdown is complete.
omniORB: (0) 1 remaining rope deleted.
omniAsyncInvoker: thread id=2 has exited. Total threads = 1
omniAsyncInvoker: thread id=3 has exited. Total threads = 0
omniAsyncInvoker: deleted.
omniORB: (0) No more references to the ORB -- deleted.
omniORB: (0) Final clean-up
omniORB: (0) Deleted 2 nil object references and 0 other tracked objects.
omniORB: (0) Final clean-up completed.
 >


Of interest is the following message printed out on the cb_server side, 
right when the client side finally wakes up after the 2 minute pause and 
displays its giopStream::CommFailure:

omniORB: (3) throw giopStream::CommFailure from 
giopImpl12.cc:1208(0,NO,COMM_FAI
LURE_UnMarshalArguments)


Again, I'm on Win2000, MSVC 6.0.  Does this help get to the bottom of 
it?  Thanks again!

--Ken Feuerman.
Adobe Systems, Inc.


At 10:41 AM 11/30/2001 +0000, Duncan Grisby wrote:
>On Thursday 29 November, Ken Feuerman wrote:
>
> > Within Process B, the implementation of Destroy() is to set an event.  The
> > main thread waits on this event, deactivates the "DataStream" servant, 
> then
> > calls orb->shutdown(0) and orb->destroy().  The problem is that there's a
> > very long pause in the thread launched by orb->shutdown(0) while it waits
> > to stop serving the incoming endpoints.
>
>You could just call orb->shutdown(0) from within the Destroy()
>implementation. Then a thread blocking in orb->run() would wake up,
>and could call orb->destroy(). This doesn't have anything to do with
>your hang, though.
>
> > I've appended the output from a run of Process B with the trace level set
> > at 15, and (through some debugger hackery) traced locks and unlocks
> > <orb_lock>.  I'm running on Win2000, MSVC 6.0, omniORB snapshot as
> > indicated in the log below.  Any ideas why the hang?
>
>No ideas, I'm afraid. Have you tried the call_back example from the
>omniORB distribution?  It'll be useful to know if that hangs or not --
>it doesn't for me. If the call_back example doesn't hang, are you able
>to construct a minimal example that does exhibit the hang?
>
>Another thing to try is to run with argument -ORBtraceThreadId 1, as
>well as -ORBtraceLevel 15. That will add the thread id to all trace
>messages, which might make it easier to see what's going on.
>
>Cheers,
>
>Duncan.
>
>--
>  -- Duncan Grisby  \  Research Engineer  --
>   -- AT&T Laboratories Cambridge          --
>    -- http://www.uk.research.att.com/~dpg1 --