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

    IIOP nameservice deadlock

    maf Newbie

      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)