7 Replies Latest reply on Sep 19, 2012 10:35 AM by garrydias

    Failed to acquire the pool semaphore in empty pool

    garrydias

      Hello .. I have a problem in jboss 5.1 using ejb 3.0

       

      My clustered app process thousands requests but I have problems in only one node.

       

      My bean is annotated with StrictMaxPool=100 without strictTimeout. Sometimes the max pool size is reached and the incoming requests (new bean instances creation in the pool) are blocked with Failed to acquire the pool semaphore, strictTimeout=-1. Until now it´s an application regular behavior.

       

      When beans creation requests  decreases my ejb blocks new instances creation =/ and Failed to acquire the pool semaphore, strictTimeout=-1 occurs all the time. It´s like the pool is still full but in JMX-CONSOLE (domain j2ee, service=EJB3) and accessing MyWorkerBean link, the AvailableCount attribute is always 0  (until in other clustered node this attribute increases and decreases normally) and worse: no bean is instantiated anymore. My pool is empty but the container can´t instatiate MyWorkerBeans anymore. Why???

       

      I´ll appreciate any help

       

      thanks

        • 1. Re: Failed to acquire the pool semaphore in empty pool
          garrydias

          Let me explain better...

           

          It´s my stateless bean:

           

          {code}

          @Clustered

          @Stateless(name = "MyWorkerBean")

          @Pool(value = PoolDefaults.POOL_IMPLEMENTATION_STRICTMAX, maxSize = 30)

          public class MyWorkerBean implements WorkerInterface {

               public void sleep(boolean flag) throws Exception

               {

                    Thread.sleep(60000);

               }

          }

          {code}

           

          To stress this bean, I´m using a JMeter test case with 100 concurrent threads. Each thread perform a ejb lookUp for MyWorkerBean.

          Each looked up instance performs a call to sleep() method. So, the first 30 lookups will perform succesfully and the remaining 70 will fail with "Fail to aquire pool semaphore, strictTimeout=-1" error.

          Now, I have 30 bean instances filling the pool during 60 seconds and if I check the MBean for MyWorkerBean in jmx-console it marks AvailableCount attribute is 30.

          After 60 seconds all 30 instances perform succesfully and I run 100 more jmeter threads again, but this time all lookups blows with "Fail to aquire pool semaphore, strictTimeout=-1" and the MBean for MyWorkerBean in jmx-console marks AvailableCount is 0 (0 is wrong, right? should not mark 30 again?).

           

          PS: the look up is performed by:

           

          {code}org.springframework.beans.factory.BeanFactory.getBean("MyWorkerBean"){code}

          thanks

          • 2. Re: Failed to acquire the pool semaphore in empty pool
            garrydias

            Please.. has somebody an explanation for this bizarre behavior?

            I don´t think that it´s a Spring´s issue because Spring perform a lookup behind the scenes  and the problem is in "lookup  time" =/

             

            thanks for any help

            • 3. Re: Failed to acquire the pool semaphore in empty pool
              jaikiran

              It looks like the bean instances are never released. How do you make use of the returned proxies from the lookup() method? What does the code look like?

              • 4. Re: Failed to acquire the pool semaphore in empty pool
                garrydias

                Hi Pai... thnx for your reply

                 

                everything starts in my webservice class MyWorkerWS:

                 

                {code:java}

                public interface MyWorkerInterface

                {

                    public WorkResponse execute(WorkRequest request);

                }{code:java}

                 

                 

                {code:java}

                @javax.jws.WebService(portName = "MyWorkerWSPort", name = "MyWorker", serviceName = "MyWorker")

                public class MyWorkerWS extends SpringSupport implements MyWorkerInterface {

                 

                    @javax.jws.WebMethod(operationName = "execute")

                    @javax.jws.soap.SOAPBinding(parameterStyle = ParameterStyle.BARE)

                    @javax.jws.WebResult(name = "workResponse", partName = "workResponse", targetNamespace = "http://ws.working.my.com/")

                    public WorkResponse execute(

                        @javax.jws.WebParam(mode = Mode.IN, name = "work", partName = "work")

                        WorkRequest request)

                    {

                 

                        final int startingDepth = NDC.getDepth();

                        WorkResponse response = null;

                        try {

                            //Here I´m looking up my bean via Spring

                            MyWorkerInterface worker = (MyWorkerInterface) super.getBeanFactory().getBean("myWorkerBean");

                 

                            //Sometimes it performs around 300ms and sometimes more than 20000ms

                            response = worker.execute(request);           

                        } catch (org.springframework.beans.BeansException beansException) {

                            LoggerHelper.error("Application error", beansException);

                        } catch (EJBException ejbException) {

                 

                            final String errorMessage =

                                org.apache.commons.lang.StringUtils.defaultString(ejbException.getMessage());

                 

                            if (errorMessage.startsWith("Failed to acquire the pool semaphore")) {

                                // MyWorkerInterface.execute(WorkRequest) method is delayed for more than 20000ms.

                                // When the execute method backs to its normal execution time this EJBException is still happening

                                // but the pool seems to be empty

                                LoggerHelper.error("Pool is full because MyWorkerInterface.execute(WorkRequest) is" +

                                        "taking more time than normal to perform.", ejbException);

                            }

                            else {

                                LoggerHelper.error("ejb error", ejbException);

                            }

                        }

                        return response;

                    }

                }{code:java}

                 

                Spring support class

                 

                {code:java}

                public class SpringSupport {

                 

                    protected final org.apache.log4j.Logger logger =

                        org.apache.log4j.Logger.getLogger(this.getClass());

                 

                    @javax.annotation.Resource

                    private javax.xml.ws.WebServiceContext webServiceContext;

                 

                    private org.springframework.context.ApplicationContext cachedApplicationContext;

                 

                    protected org.springframework.beans.factory.BeanFactory getBeanFactory() {

                        if (cachedApplicationContext != null) {

                            return cachedApplicationContext;

                        }

                        if (webServiceContext == null) {

                            return null;

                        }

                        javax.xml.ws.handler.MessageContext messageContext = webServiceContext.getMessageContext();

                        if (messageContext == null) {

                            return null;

                        }

                        javax.servlet.ServletContext servletContext =

                            (javax.servlet.ServletContext) messageContext.get(

                                    javax.xml.ws.handler.MessageContext.SERVLET_CONTEXT);

                 

                        if (servletContext == null) {

                            return null;

                        }

                        this.cachedApplicationContext =

                            (org.springframework.context.ApplicationContext) servletContext

                            .getAttribute(

                                    org.springframework.web.context.WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE);

                        return cachedApplicationContext;

                    }

                }{code:java}

                 

                Bean class

                 

                {code:java}

                @Clustered

                @Local(MyWorkerInterface.class)

                @Stateless(name = "MyWorkerBean")

                @Interceptors(value = { SpringBeanAutowiringInterceptor.class, LoggingInterceptor.class })

                @RolesAllowed(value = "client")

                @Pool(value = PoolDefaults.POOL_IMPLEMENTATION_STRICTMAX, maxSize = 30)

                public class MyWorkerBean implements MyWorkerInterface {

                 

                    @RolesAllowed("client")

                    @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED)

                    public WorkResponse execute(final WorkRequest workRequest) {

                 

                        long start = System.currentTimeMillis();

                 

                        WorkExchange exchange = new WorkExchange();

                        exchange.setWorkRequest(workRequest);

                 

                        // A JMSProducer is created to send exchange to a JMS queue

                        // A MDB class retrieve data from a third party webservice (expensive operation taking between 300 to 60000ms to finish) using WorkExchange.workRequest fields

                        // A JMSConsumer is created to retrieve exchange object when MDB ends

                 

                        LoggerUtil.info("Operation time: " + (System.currentTimeMillis() - start));

                 

                        // WorkExchange.workResponse have been set by MDB

                        WorkResponse response = exhange.getWorkResponse();

                 

                        return response;

                    }

                }{code:java}

                 

                Look up settings in Spring xml

                 

                {code:xml}

                     <jee:local-slsb lookup-home-on-startup="false" id="myWorkerBean" business-interface="MyWorkerInterface"

                        jndi-name="MyWorkerBean/local" />

                {code:xml}

                 

                • 5. Re: Failed to acquire the pool semaphore in empty pool
                  garrydias

                  I made a mistake.

                   

                  The error "Failed to acquire pool semaphore" occurs at method invocation. The lookup occurs normally. The exception is thrown in this line

                   

                  response = worker.execute(request);

                   

                   

                  (still searching a solution...)

                  • 6. Re: Failed to acquire the pool semaphore in empty pool
                    musmanhassan

                    Hi Garry,

                     

                    Did you found the solution???

                    • 7. Re: Failed to acquire the pool semaphore in empty pool
                      garrydias

                      Yes. I´m still writing a post with a sequence diagram to explain better.

                       

                      To be short:

                       

                      At the line where I wrote // A JMSConsumer is created to retrieve exchange object when MDB end there´s lot of statements and one of that is a call to javax.jms.MessageConsumer.receive() method. However, when the producer sent the message it set a Time To Live in my jms message. This TTL was 20 seconds. As my MDB connect to a third party webService that hangs more than 30 seconds sometimes, my jms message died before MDB acks the comsumption. Meanwhile, the javax.jms.MessageConsumer.receive() method is waiting for a message that should never come because the jms message relies in DLQ now. So, javax.jms.MessageConsumer.receive() method will wait forever and an available MyWorkerBean instance in my pool (annotated as @Pool(value = PoolDefaults.POOL_IMPLEMENTATION_STRICTMAX, maxSize = 30)) will be decreased. You can see this decreasing in jmx-console, menu j2ee.

                       

                      The solution was set a TTL for MessageConsumer.receive() method. So today my code looks like this:

                       

                      @Clustered
                      @Local(MyWorkerInterface.class)
                      @Stateless(name = "MyWorkerBean")
                      @Interceptors(value = { SpringBeanAutowiringInterceptor.class, LoggingInterceptor.class })
                      @RolesAllowed(value = "client")
                      @Pool(value = PoolDefaults.POOL_IMPLEMENTATION_STRICTMAX, maxSize = 30)
                      public class MyWorkerBean implements MyWorkerInterface {

                          @RolesAllowed("client")
                          @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED)
                          public WorkResponse execute(final WorkRequest workRequest) {

                              long start = System.currentTimeMillis();

                              WorkExchange exchange = new WorkExchange();
                              exchange.setWorkRequest(workRequest);

                              // A JMSProducer is created to send exchange to a JMS queue
                              // A MDB class retrieve data from a third party webservice (expensive operation taking between 300 to 60000ms to finish) using WorkExchange.workRequest fields
                              ...

                                       ObjectMessage responseMessage = (ObjectMessage) messageConsumer.receive(20000);

                              ...


                              LoggerUtil.info("Operation time: " + (System.currentTimeMillis() - start));

                              // WorkExchange.workResponse have been set by MDB
                              WorkResponse response = exhange.getWorkResponse();

                              return response;
                          }
                      }

                       

                      []s