0 Replies Latest reply on Apr 29, 2005 5:54 AM by maf
IIOP nameservice deadlock

maf Apr 29, 2005 5:54 AM
Hi all,

I am using JBoss 3.2.5 and access session beans from C++ CORBA clients.
In certain situations many clients at a time try to lookup new references for a certain bean in the name service. Sometimes in this case a deadlock occurs.
All RequestProcessor threads become blocked while waiting for replies and after that all requests are queued until the queue is full.

The problem is also reproduceable with JBoss 3.2.7 and jacorb.jar V 2.2.1 (JBoss patch 2) containing the lastest JacORB fixes.

When I increase the thread count (jacorb.poa.thread_pool_max in jacorb.properties), the problem does not occur and no thread becomes deadlocked. I don't think that this is the correct way to handle this, because imho the queueing mechanism should be used in this case to handle a temporary overload situation.

Am I wrong or can anybody help?

Frank
11:38:55,218 DEBUG [Thread-186|queue] rid: 4 opname: resolve is queued (queue size: 1)
11:38:55,218 DEBUG [RequestController-5|controller] rid: 4 opname: resolve trying to get a RequestProcessor
11:38:55,233 DEBUG [RequestController-5|controller] waiting for queue
11:38:55,233 DEBUG [RequestProcessor-260|controller] rid: 4 opname: resolve starts with request processing
11:38:55,233 DEBUG [RequestProcessor-260|controller] rid: 4 opname: resolve invokeOperation on servant (stream based)
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-260|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [Thread-226|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,233 DEBUG [Thread-226|queue] rid: 4 opname: resolve is queued (queue size: 1)
11:38:55,233 DEBUG [RequestController-5|controller] rid: 4 opname: resolve trying to get a RequestProcessor
11:38:55,233 DEBUG [RequestController-5|controller] waiting for queue
11:38:55,233 DEBUG [RequestProcessor-261|controller] rid: 4 opname: resolve starts with request processing
11:38:55,233 DEBUG [RequestProcessor-261|controller] rid: 4 opname: resolve invokeOperation on servant (stream based)
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [RequestProcessor-261|policies] get_policy_overrides returns 0 policies
11:38:55,233 DEBUG [Thread-227|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,233 DEBUG [Thread-227|queue] rid: 4 opname: resolve is queued (queue size: 1)
11:38:55,233 DEBUG [RequestController-5|controller] rid: 4 opname: resolve trying to get a RequestProcessor
since here all request are queued
11:38:55,233 WARN [RequestController-5|controller] Thread pool exhausted, consider increasing jacorb.poa.thread_pool_max (currently: 8)
11:38:55,233 DEBUG [Thread-210|poa] POA EJBHome&%psibms&%BMSAppBean rid: 12 opname: create _invoke: queuing request
11:38:55,233 DEBUG [Thread-210|queue] rid: 12 opname: create is queued (queue size: 1)
11:38:55,233 DEBUG [RequestController-6|controller] rid: 12 opname: create trying to get a RequestProcessor
11:38:55,233 DEBUG [RequestController-6|controller] waiting for queue
11:38:55,233 DEBUG [RequestProcessor-262|controller] rid: 12 opname: create starts with request processing
11:38:55,233 DEBUG [RequestProcessor-262|controller] rid: 12 opname: create invokeOperation on servant (stream based)
11:38:55,233 DEBUG [Thread-194|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,233 DEBUG [Thread-194|queue] rid: 4 opname: resolve is queued (queue size: 2)
11:38:55,233 DEBUG [Thread-195|poa] POA EJBHome&%psibms&%BMSAppBean rid: 12 opname: create _invoke: queuing request
11:38:55,296 DEBUG [Thread-195|queue] rid: 12 opname: create is queued (queue size: 1)
11:38:55,296 DEBUG [RequestController-6|controller] rid: 12 opname: create trying to get a RequestProcessor
11:38:55,296 DEBUG [RequestController-6|controller] waiting for queue
11:38:55,296 DEBUG [RequestProcessor-263|controller] rid: 12 opname: create starts with request processing
11:38:55,296 DEBUG [RequestProcessor-263|controller] rid: 12 opname: create invokeOperation on servant (stream based)
11:38:55,296 DEBUG [Thread-16|poa] POA Naming rid: 3140 opname: resolve _invoke: queuing request
11:38:55,296 DEBUG [Thread-16|queue] rid: 3140 opname: resolve is queued (queue size: 3)
11:38:55,296 DEBUG [Thread-184|poa] POA EJBHome&%psibms&%BMSAppBean rid: 8 opname: create _invoke: queuing request
11:38:55,296 DEBUG [Thread-184|queue] rid: 8 opname: create is queued (queue size: 1)
11:38:55,296 DEBUG [RequestController-6|controller] rid: 8 opname: create trying to get a RequestProcessor
11:38:55,296 DEBUG [Thread-204|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,296 DEBUG [Thread-204|queue] rid: 4 opname: resolve is queued (queue size: 4)
11:38:55,296 DEBUG [Thread-189|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,296 DEBUG [Thread-189|queue] rid: 4 opname: resolve is queued (queue size: 5)
11:38:55,296 DEBUG [Thread-206|poa] POA Naming rid: 4 opname: resolve _invoke: queuing request
11:38:55,296 DEBUG [Thread-206|queue] rid: 4 opname: resolve is queued (queue size: 6)
11:38:55,296 DEBUG [Thread-195|poa] POA EJBHome&%psibms&%BMSAppBean rid: 16 opname: create _invoke: queuing request
11:38:55,296 DEBUG [Thread-195|queue] rid: 16 opname: create is queued (queue size: 2)
11:38:55,296 DEBUG [Thread-16|poa] POA Naming rid: 3142 opname: resolve _invoke: queuing request
11:38:55,296 DEBUG [Thread-16|queue] rid: 3142 opname: resolve is queued (queue size: 7)
11:38:55,296 DEBUG [RequestProcessor-262|delegate] Delegate.getReference with POA <EJBObject&%psibms&%BMSAppBean>
11:38:55,296 DEBUG [RequestProcessor-263|delegate] Delegate.getReference with POA <EJBObject&%psibms&%BMSAppBean>
11:38:55,296 DEBUG [RequestProcessor-250|delegate] Delegate.getReference with POA <EJBObject&%psibms&%BMSAppBean>
11:38:55,296 DEBUG [RequestProcessor-229|delegate] Delegate.getReference with POA <EJBObject&%psibms&%BMSAppBean>
11:38:55,296 DEBUG [RequestProcessor-263|controller] rid: 12 opname: create ends with request processing
11:38:55,296 DEBUG [RequestProcessor-250|controller] rid: 12 opname: create ends with request processing
11:38:55,296 DEBUG [RequestProcessor-229|controller] rid: 8 opname: create ends with request processing
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Finalizer|delegate] Delegate gc'ed!
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3144 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3144 opname: resolve is queued (queue size: 8)
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3146 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3146 opname: resolve is queued (queue size: 9)
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3148 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3148 opname: resolve is queued (queue size: 10)
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3150 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3150 opname: resolve is queued (queue size: 11)
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3152 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3152 opname: resolve is queued (queue size: 12)
11:38:55,311 DEBUG [Thread-16|poa] POA Naming rid: 3154 opname: resolve _invoke: queuing request
11:38:55,311 DEBUG [Thread-16|queue] rid: 3154 opname: resolve is queued (queue size: 13)