Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re:Binding takes for ages on Jonas-server. No additional info to troubleshoot

On 08/24/2011 02:53 PM, Stefaan Somers wrote:
> Hi Florent,
>
> we did the change (trum rufs.......) And yes indeed it performs a lot
> faster now (still less than 5% of the time before). Many, many thanks
yes, the deployment is faster now.

> Now we still have the following questions :
> 1) isn't it better that by default this option is disabled for the
> JONAS-server. Will avoid a lot of confusion for future users of the
> Jonas-server
Maybe.
In fact I need to investigate because we don't have this issue with many 
of EJB-JARs

> 2) How did you see that this was causing the problem? Something in the
> log-file???
I perform some dump of the threads in order to see where we are

> 3) now we have put this in comment, can this change something on the
> behaviour of the application, or is it only used for administering
> beans
This is only used in order to collect statistics, this is not a core 
component, so you won't see any change in your application

Regards,

Florent

>
> Greetings
>
> On 24 August 2011 14:09, Florent BENOIT<[email protected]>  wrote:
>>     Hi,
>>
>> I was able to deploy your EAR
>> You should comment the<statistics>  component located in
>> JONAS_BASE/conf/easybeans-jonas.xml file
>>
>> Regards,
>>
>> Florent
>>
>> On 08/24/2011 10:01 AM, Stefaan Somers wrote:
>>> Hi Florent,
>>>
>>> we tried both options but without any success :
>>> 1) no change
>>> 2) takes only 1 minute less (12 minutes ->    11 minutes)
>>>
>>> Did you already had a chance to deploying the ear-file??
>>>
>>> Greetings
>>>
>>> On 23 August 2011 15:13, Florent BENOIT<[email protected]>    wrote:
>>>>     Hi,
>>>>
>>>> Could you try to make a new run with :
>>>>
>>>> 1/ Launching JOnAS with the following system property :
>>>> -Deasybeans.useSimplePool=true
>>>>
>>>> 2/ Try with another persistence provider
>>>> JONAS_BASE/conf/jonas.properties (change from hibernate to eclipselink
>>>> for
>>>> example)
>>>>
>>>> Also, I'm interested in having the ear in order to reproduce your problem
>>>>
>>>> Regards,
>>>>
>>>> Florent
>>>>
>>>>
>>>>
>>>> On 08/23/2011 02:44 PM, Paul Adriaenssens wrote:
>>>>> Here the correct URL to access the DEBUG level logfile:
>>>>> ftp://applicaties:[email protected]
>>>>>
>>>>> Paul
>>>>>
>>>>>> Actually the question is if it's normal that it takes approximately 8
>>>>>> seconds for each SLSB between the logging of the line with
>>>>>> 'createSubcontext env' and the logging of the line with
>>>>>> 'createSubcontext
>>>>>> comp'?
>>>>>>
>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> ....
>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>>
>>>>>> Currently for one of our applications containing 290 generated SLSB's
>>>>>> the
>>>>>> JOnAS startup takes about 1 hour!
>>>>>>
>>>>>> You can find the full DEBUG level logfile of one of our generated
>>>>>> applications containing 83 SLSB's on
>>>>>> ftp://ftps.provant.be/jonas-start.log
>>>>>>
>>>>>> Also this process seems to slow down, in the beginning it takes about
>>>>>> 1,5
>>>>>> sec per SLSB, at the end about 8 sec.
>>>>>>
>>>>>> Presumably we use somewhere a wrong configuration; or the source code
>>>>>> (Bean class, Data class, persistence.xml) is not generated in an
>>>>>> optimal
>>>>>> way ...
>>>>>>
>>>>>> Or is it normal behaviour when a large number of SLSB's is used?
>>>>>>
>>>>>> Kind Regards,
>>>>>>
>>>>>> Paul
>>>>>>
>>>>>>> Hi Florent,
>>>>>>> many thanks for answering already. I've set the logging as asked, but
>>>>>>> it
>>>>>> doesn't give me much more information.
>>>>>>> Is it normal that these entry-lines appear for every bean defined. Is
>>>>>> there any possibility to make that the bean is not
>>>>>>> container-managed. If so what are the consequences??
>>>>>>> Greetings
>>>>>>> On 19 August 2011 09:06, Florent BENOIT<[email protected]>
>>>>>>>   wrote:
>>>>>>>> This is normal behaviour but you should see some "elapsed time" for
>>>>>> bytecode
>>>>>>>> injection, bytecode processing, etc.
>>>>>>>> Try to set debug to only org.ow2.easybeans.container.JContainer3 or
>>>>>> org.ow2.easybeans.container
>>>>>>>> logger.org.ow2.easybeans.container.JContainer3.level DEBUG
>>>>>>>> logger.org.ow2.easybeans.container.level DEBUG
>>>>>>>> Regards,
>>>>>>>> Florent
>>>>>>>> On 08/18/2011 09:34 PM, Stefaan Somers wrote:
>>>>>>>>> I've succeeded to set the logging right now. What I can see in the
>>>>>> log-files are many of the following entries :
>>>>>>>>> 2011-08-19 00:30:36,953 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:30:43,359 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:30:51,250 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:30:51,250 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:51,250 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:30:51,250 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:30:51,266 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:30:58,907 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:31:06,814 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:31:15,127 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.bind : bind EJBContext
>>>>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.bind : bind TimerService
>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> env
>>>>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.createSubcontext :
>>>>>>>>> createSubcontext
>>>>>>>>> comp
>>>>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.rebind : rebind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.rebind : rebind ORB
>>>>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.lookup : lookup comp
>>>>>>>>> 2011-08-19 00:31:23,096 : JavaCompExtensionListener.handle : Bean is
>>>>>> container managed so remove availability of java:comp/UserTransaction
>>>>>> object
>>>>>>>>> 2011-08-19 00:31:23,112 : ContextImpl.unbind : unbind
>>>>>>>>> UserTransaction
>>>>>> 2011-08-19 00:31:23,112 : ContextImpl.bind : bind EJBContext
>>>>>>>>> Any idea what is going wrong, or is this normal behaviour??
>>>>>>>>> Already many thnks for your help.
>>>>>>>>> Greetings
>>>>>>>>> On 18 August 2011 17:13, Guillaume Sauthier (OW2)
>>>>>>>>> <[email protected]>        wrote:
>>>>>>>>>> Please set back the monolog configuration to javaLog:
>>>>>>>>>> log.config.classname
>>>>>>>>>> org.objectweb.util.monolog.wrapper.javaLog.LoggerFactory
>>>>>>>>>> Easybeans is printing its debug information on a logger backed by
>>>>>> Java
>>>>>>>>>> util
>>>>>>>>>> Log.
>>>>>>>>>> --G
>>>>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>>>>> No luck either.
>>>>>>>>>>> I hereby include the content of the trace.properties :
>>>>>>>>>>> #
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> -----------------------------------------------------------------------
>>>>>> # This is a default configuration file for monolog.
>>>>>>>>>>> #
>>>>>>>>>>> # 2 handlers have been defined : tty (System.out) and logf (file)
>>>>>>>>>>> #
>>>>>>>>>>> # Patterns for each handler may include these possible values : #
>>>>>>>>>>> %h
>>>>>>     the thread name
>>>>>>>>>>> # %O{1} the Class name (basename only)
>>>>>>>>>>> # %M    the method name
>>>>>>>>>>> # %L    the line number
>>>>>>>>>>> # %d    the date
>>>>>>>>>>> # %l    the level
>>>>>>>>>>> # %m    the message itself
>>>>>>>>>>> # %n    a new line
>>>>>>>>>>> #
>>>>>>>>>>> # A list of predefined loggers is given at the end of the file. #
>>>>>> Each logger inherits from its parent for properties not defined. #
>>>>>> The root logger is "root". It must always be defined.
>>>>>>>>>>> #
>>>>>>>>>>> # Each logger is associated with a level that can be one of : #
>>>>>> ERROR | WARN | INFO | DEBUG | FATAL | INHERIT
>>>>>>>>>>> #
>>>>>>>>>>> # ->        More info on http://www.objectweb.org/monolog/doc.html #
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> -----------------------------------------------------------------------
>>>>>> #
>>>>>>>>>>>
>>>>>>>>>>> -----------------------------------------------------------------------
>>>>>> # Define which wrapper to use (= javaLog)
>>>>>>>>>>> #
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> -----------------------------------------------------------------------
>>>>>> # For Log4j you need to add log4j.jar
>>>>>>>>>>> log.config.classname
>>>>>>>>>>> org.objectweb.util.monolog.wrapper.log4j.MonologLoggerFactory #
>>>>>> log.config.classname
>>>>>>>>>>> org.objectweb.util.monolog.wrapper.javaLog.LoggerFactory
>>>>>>>>>>> #----------
>>>>>>>>>>> # PrivateCompany
>>>>>>>>>>> #----------
>>>>>>>>>>> logger.net.democritus.level INFO
>>>>>>>>>>> logger.com.privatecompany.level INFO
>>>>>>>>>>> logger.net.palver.level INFO
>>>>>>>>>>> logger.org.ow2.easybeans.level DEBUG
>>>>>>>>>>> On 18 August 2011 15:57, Guillaume Sauthier (OW2)
>>>>>>>>>>> <[email protected]>        wrote:
>>>>>>>>>>>> the format is:
>>>>>>>>>>>> logger.<name>.level<level>
>>>>>>>>>>>> you missed the .level
>>>>>>>>>>>> --G
>>>>>>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>> I included the following line in trace.properties, but I see no
>>>>>> additional logging :
>>>>>>>>>>>>> logger.org.ow2.easybeans DEBUG
>>>>>>>>>>>>> Greetings
>>>>>>>>>>>>> On 18 August 2011 13:26, Guillaume Sauthier (OW2)
>>>>>>>>>>>>> <[email protected]>        wrote:
>>>>>>>>>>>>>> Maybe you can add traces for the org.ow2.easybeans logger ? So
>>>>>> that we can see where time is consumed.
>>>>>>>>>>>>>> --G
>>>>>>>>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>>>> we have an application with many EJB's. Is it normal that the
>>>>>> startup
>>>>>>>>>>>>>>> takes more than 10 minutes. Are there any steps I can do, to
>>>>>> troubleshoot this performance-problem.
>>>>>>>>>>>>>>> 18/08/11 13:02:26 (I) JCLLoggerAdapter.info : Not binding
>>>>>> factory
>>>>>>>>>>>>>>> to
>>>>>>>>>>>>>>> JNDI, no JNDI name configured
>>>>>>>>>>>>>>> 18/08/11 13:16:39 (I) JContainer3.start : Container
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> 'D:\jonas-full-5.1.4\BASE\work\apps\jonas\pocAppEAR_2011.08.18-12.56.31.ear\pocAppEJB.jar'
>>>>>> [104 SLSB, 0 SFSB, 0 MDB] started in 891.270 ms
>>>>>>>>>>>>>>> Greetings,
>>>>>>>>>>>>>>> Stefaan Somers
>>>>>>
>>>>>>
>>